[[combinable]] on same core timing

[aclassifier]

Could anybody describe what's happening here?

Code: Select all

#include <platform.h> // core
#include <stdio.h>
#include <timer.h> // delay_milliseconds(200), XS1_TIMER_HZ etc

#define DEBUG_PRINT_TEST 1
#define debug_print(fmt, ...) do { if(DEBUG_PRINT_TEST) printf(fmt, __VA_ARGS__); } while (0)

typedef signed int time32_t;

#define ONE_SECOND_TICKS (1000 * XS1_TIMER_KHZ)

#define TEST_TIMER_VALUES_SKEW_PLACED 2

#if (TEST_TIMER_VALUES_SKEW_PLACED==0)
    #define INFO "UNPLACED"
    #define COMBINABLE
    #define PLACED_0
    #define PLACED_1
#elif (TEST_TIMER_VALUES_SKEW_PLACED==1)
    #define INFO "PLACED"
    #define COMBINABLE [[combinable]]
    #define PLACED_0 on tile[0].core[0]:
    #define PLACED_1 on tile[0].core[1]:
#elif (TEST_TIMER_VALUES_SKEW_PLACED==2)
    #define INFO "PLACED_SAMECORE"
    #define COMBINABLE [[combinable]]
    #define PLACED_0 on tile[0].core[0]:
    #define PLACED_1 on tile[0].core[0]:
#else
    #error
#endif

COMBINABLE // or not!
void test_task (const unsigned task_id, const unsigned initial_delay_ticks) {

    timer     tmr;
    time32_t  time;
    debug_print ("%s from #%u\n", INFO, task_id);

    tmr :> time; // Showing something else than delay_milliseconds(ms) etc:
    select {case tmr when timerafter (time + initial_delay_ticks) :> void: break;}
    
    // ONLY IN BOTTOM LOG: tmr :> time; // Reset time is CRUCIAL!

    while (1) {
        select {
            case tmr when timerafter (time) :> time32_t now: {
                debug_print ("After %08X :> now %08X, #%u lost %d ticks\n", time, now, task_id, now-time);
                time += ONE_SECOND_TICKS; // FUTURE TIMEOUT, same value as "time" above
            } break;
        }
    }
}

int main() {
    par {
        PLACED_0 /* or not! */ test_task (0, 0); // No initial delay
        PLACED_1 /* or not! */ test_task (1, ONE_SECOND_TICKS/2);
    }
    return 0;
}

Thw first two logs I guess show that the low level code of them are (about?) equal. (500 ms is 50000000 is hex 02FAF080). Even if #1 is delayed with 500 ms it looks like the two run more or less in phase. In the third and fourth lines After is 083D07B0 and 083D0DC3 differ by only dec 1555 tics of 10 ns = 15.55 us.

Code: Select all

UNPLACED from #1
UNPLACED from #0
After 02491CC5 :> now 02491CD9, #0 lost 20 ticks
After 02491687 :> now 05440715, #1 lost 50000014 ticks
After 083EF787 :> now 083EF789, #1 lost 2 ticks
After 083EFDC5 :> now 083EFDC7, #0 lost 2 ticks
After 0E34D887 :> now 0E34D889, #1 lost 2 ticks
After 0E34DEC5 :> now 0E34DEC7, #0 lost 2 ticks

PLACED from #1
PLACED from #0
After 02472CC3 :> now 02472CD6, #0 lost 19 ticks
After 024726B0 :> now 0542173E, #1 lost 50000014 ticks
After 083D07B0 :> now 083D07B2, #1 lost 2 ticks
After 083D0DC3 :> now 083D0DC5, #0 lost 2 ticks
After 0E32E8B0 :> now 0E32E8B2, #1 lost 2 ticks
After 0E32EEC3 :> now 0E32EEC5, #0 lost 2 ticks
After 1428C9B0 :> now 1428C9B2, #1 lost 2 ticks

But this log shows something that I can't describe. First there is the 500ms initial delay crops up on both. Then that #1 lags behind so much. They should be exactly out of phase by 500ms but since they are almost in phase. Also notice the swinging in value from 2089 to 1972

Code: Select all

PLACED_SAMECORE from #0
PLACED_SAMECORE from #1
After 02405B6B :> now 053B539D, #0 lost 50001970 ticks
After 024062CA :> now 053B666A, #1 lost 50004896 ticks
After 08363C6B :> now 08363C75, #0 lost 10 ticks
After 083643CA :> now 08364BF3, #1 lost 2089 ticks
After 0E2C1D6B :> now 0E2C1D75, #0 lost 10 ticks
After 0E2C24CA :> now 0E2C2CF3, #1 lost 2089 ticks
After 1421FE6B :> now 1421FE75, #0 lost 10 ticks
After 142205CA :> now 14220D7E, #1 lost 1972 ticks
After 1A17DF6B :> now 1A17DF75, #0 lost 10 ticks
After 1A17E6CA :> now 1A17EE7E, #1 lost 1972 ticks
After 200DC06B :> now 200DC075, #0 lost 10 ticks
After 200DC7CA :> now 200DCF7E, #1 lost 1972 ticks

After 42 seconds and wraparound I get this pattern again (swinging in from 2089 to 1972 again for #1):

Code: Select all

After FC97456B :> now FC974575, #0 lost 10 ticks
After FC974CCA :> now FC97547E, #1 lost 1972 ticks
After 028D266B :> now 028D2675, #0 lost 10 ticks
After 028D2DCA :> now 028D35F3, #1 lost 2089 ticks
After 0883076B :> now 08830775, #0 lost 10 ticks
After 08830ECA :> now 088316F3, #1 lost 2089 ticks
After 0E78E86B :> now 0E78E875, #0 lost 10 ticks
After 0E78EFCA :> now 0E78F7F3, #1 lost 2089 ticks
After 146EC96B :> now 146EC975, #0 lost 10 ticks
After 146ED0CA :> now 146ED87E, #1 lost 1972 ticks

In the code example here I have looked at “Programming XC on XMOS Devices” by Douglas Watt (page 18).

If I add this before the while loop:

Code: Select all

tmr :> time; // Reset time is CRUCIAL!

then everything is more explainable, even no swing in:

Code: Select all

PLACED_SAMECORE from #0
PLACED_SAMECORE from #1
After 02AE25CB :> now 05A91DF6, #0 lost 50001963 ticks
After 05A91DA5 :> now 05A930C3, #1 lost 4894 ticks
After 08A406CB :> now 08A406D5, #0 lost 10 ticks
After 0B9EFEA5 :> now 0B9EFEAF, #1 lost 10 ticks
After 0E99E7CB :> now 0E99E7D5, #0 lost 10 ticks
After 1194DFA5 :> now 1194DFAF, #1 lost 10 ticks
...
After FA0A26A5 :> now FA0A26AF, #1 lost 10 ticks
After FD050FCB :> now FD050FD5, #0 lost 10 ticks
After 000007A5 :> now 000007AF, #1 lost 10 ticks
After 02FAF0CB :> now 02FAF0D5, #0 lost 10 ticks
After 05F5E8A5 :> now 05F5E8AF, #1 lost 10 ticks
After 08F0D1CB :> now 08F0D1D5, #0 lost 10 ticks

It's not strange that [[combinable]] placed on the same core is special, since the two selects would be joined into one core select, but I still don't see many of the other points above.

Like why should reset of time cause such a clean pattern, while without that reset we have the swing in. Is there some cycle interference in the scheduling?

I will try to discuss this at [1] when I know more of what's going on here. I have asked more than one question here (and some I see I haven't asked, there are other matters like the 4894 ticks above) so I guess that a single paragraph as an answer may be difficult. But maybe there is one?

I use xTc 14.3.3

[1] [[combinable]] on same core timing (standard disclaimer: no money, gifts, ads etc..)

[CousinItt]

Hi,

your trigger point variable time is not updated after your first select statement:

Code: Select all

select {case tmr when timerafter (time + initial_delay_ticks) :> void: break;}

So won't the timerafter() in the select statement in the while loop be triggered immediately on entry and the timing be messed up from then on?

Or am I missing the point?

[aclassifier]

Hi,

your trigger point variable time is not updated after your first select statement:

Code: Select all

select {case tmr when timerafter (time + initial_delay_ticks) :> void: break;}

So won't the timerafter() in the select statement in the while loop be triggered immediately on entry and the timing be messed up from then on?

Or am I missing the point?

You are right. With initial_delay_ticks 0 then the select should be taken immediately. With initial_delay_ticks 0.5 secs it should be taken after 0.5 seconds.

But all logs above except the last (with tmr :> time in front of the while(1)) seem to run in phase. That's what puzzled me.

There is something here that I haven't understood.