PROCESSOR-SDK-AM64X: EtherCAT Slave Sync1 generated too late

Dominic Rath

Dear TI team,

we're seeing an issue with the EtherCAT slave firmware where the Sync1 pulse is being generated one Sync0 period too late.

In our use-case we're configuring the Sync1 cycle time to be a multiple of the Sync0 cycle time. We haven't looked at the behavior of the TIESC slave when Sync1 is simply shifted from Sync0.

For our test case we've configured the system for 1ms Sync0 cycle time and 5ms Sync1 cycle time.

We've instrumented execution of the Sync0/Sync1 ISRs and tasks to make sure we're not just being scheduled too late. We can see that the Sync1 task executes within a few microseconds (5-12) after the Sync1 ISR. If we look at the Sync0/Sync1 events beginning with the first Sync0 event, we see the following sequence.

	ts (us)		systime (us)	NextSync0 (us)	NextSync1 (us)
0	11.4	Sync 0 task	0.0	986.7
1	1002.9	Sync 0 task	992.1	986.7
2	2003.8	Sync 0 task	1992.9	1986.7
3	3001.8	Sync 0 task	2991.1	2986.7
4	4006.9	Sync 0 task	3996.0	3986.7
5	5015.6	Sync 1 task	5004.3		8986.7
6	5022.8	Sync 0 task	5012.1	5986.7
7	6002.8	Sync 0 task	5992.0	5986.7
8	7003.0	Sync 0 task	6992.2	6986.7
9	8001.9	Sync 0 task	7991.1	7986.7
10	9005.6	Sync 0 task	8994.8	8986.7
11	10011.9	Sync 0 task	10000.2	10986.7
12	10017.2	Sync 1 task	10006.3		13986.7
13	11002.2	Sync 0 task	10991.1	10986.7
14	12001.9	Sync 0 task	11990.9	11986.7

(ts in us is based on the R5f cycle counter, systime is read via bsp_get_local_sys_time, NextSync0/NextSync1 are read from ESC_ADDR_NEXT_SYNC0/1_PULSE)

(systime, NextSync0 and NextSync1 are relative to the first systime we've logged, so that the numbers are easier to read)

The first Sync1 Event is generated together with the 6th Sync0 Event, instead of with the 5th Sync0 Event. The period is ok.
The NextSync0 timestamps are sometimes not yet updated when we read them (marked in light blue). This is due to PINDSW-2360. We can work around that.
In line 5, the NextSync1 register reads ~9ms. At that moment the systime register shows ~5ms. If we take the "NextSync1" value of 9 ms, and subtract the period of 5ms, we see that this event SHOULD have fired at 4ms. This shows how the Sync1 event fires one Sync0 period too late.
In line 12, we see that the second Sync1 event fired at ~10ms. If we take "NextSync1" value of ~14ms and subtract the period of 5ms, we see that this event SHOULD have fired at 9ms, which is also what NextSync1 showed back in line 5.
We've also tested with other Sync0/Sync1 cycle times, and so far it's been always one Sync0 period that the Sync1 was being generated too late.

It seems that this is a bug within the TIESC firmware. We can work around this, but of course it would be nice to have this a) confirmed by TI and b) eventually fixed.

We've seen this bug in MCU+ SDKs 08.00 (slave firmware 5.4.242) , 08.02 (slave firmware 6.5.0) and 08.03RC1 (slave firmware 6.5.2).

Let me know if you need any further details regarding this issue.

Best Regards,

Dominic

over 3 years ago

0 Dhaval Khandla over 3 years ago

TI__Mastermind 28504 points

Hi
We are looking into this. We will provide further response by end of this week.

Regards

Dhaval Khandla

0 Dominic Rath over 3 years ago in reply to Dhaval Khandla

Mastermind 7720 points

Hi Dhaval,

any news here? Have you been able to verify our findings?

Regards, Dominic

0 Dhaval Khandla over 3 years ago in reply to Dominic Rath

TI__Mastermind 28504 points

Dominic
We have verified that the SYNC0 and SYNC1 pulses are being generated properly.

In our SDK, interrupt nesting is disabled by default and that might be causing these timings. It is disabled because of the MCUSDK-1016 bug mentioned in Release Notes.

Can you enable nesting and check if it leads to any improvement? You can define "HWIP_NESTED_INTERRUPTS_IRQ_ENABLE" macro at the top of "source\kernel\freertos\dpl\r5\HwiP_armv7r_handlers_freertos.c" file to enable it.

Regards
Dhaval

0 Dominic Rath over 3 years ago in reply to Dhaval Khandla

Mastermind 7720 points

Hi Dhaval,

we're aware of the lack of support for nested interrupts, but we're very confident that this isn't the issue.

When reading NextSync1 it is always one Syn0 cycle + latency late, not just occasionally.
We've added the ability to trace execution of IRQs and tasks (the table above is a very condensed version), and there is no other activity that would defer the Sync1 task for that amount of time (a few us latency are observed, but not a millisecond).

Please note that this only occurs when Sync1 is a multiple of Sync0, and that you can only observe this in relation to the DC time. The Sync1 period is fine, just the relation to the absolute DC time is off.

Regards,

Dominic

0 Dhaval Khandla over 3 years ago in reply to Dominic Rath

TI__Mastermind 28504 points

Dominic
According to you, the problem is only with ESC_ADDR_NEXT_SYNC1_PULSE register if I understand correctly. I will look into this and provide more details.

Regards

Dhaval

0 Dominic Rath over 3 years ago in reply to Dhaval Khandla

Mastermind 7720 points

Hello Dhaval,

thank you for looking into this.

I'm not 100% sure whether the problem is just with the ESC_ADDR_NEXT_SYNC1_PULSE or with the Sync1 pulse itself. I think it's rather that the first Sync1 pulse is one Sync0 period too late:

In my original post with 1ms Sync0 vs. 5ms Sync1 the <CycleTime1> is set to 4ms -> the Sync1 pulse should trigger 4ms after the (first) Sync0 pulse. From our trace we can see that Sync1 pulse was actually 1ms too late. That means the ESC_ADDR_NEXT_SYNC1_PULSE register would have been correct, and the Sync1 pulse was late.

From then on the Sync1 period is correct (every 5ms), but the NEXT_SYNC1_PULSE register (which I assume just increments based on the cycle time, without any actual relation to the IEP hardware) and the actual Sync1 pulses are always off by one Sync0 period.

Regards,

Dominic