Hi Hakan,
Thanks for the trace, it pointed straight at the bug. I reproduced your observation on my hardware and the root cause is exactly the "bad initial reference time" you flagged, but only in M2R mode. R2M is unaffected because it only writes the ref clock (sync_reference_clock_to) and never reads it back.
I added a small debug capture inside the dcsync callbacks (same columns as yours: cycle, pll-err, ref_time_lo, app_time) and logged the first 10 cycles. Before the fix on M2R:
Code:
# cycle pll_err ref_time_lo app_time_ns app_time_lo
0 0 1875535147 829958931561087328 1037861216
1 0 1037346343 829958931562087328 1038861216
2 -385754 1038312400 829958935857087328 1038893920
3 -382546 1039366179 829958935858087328 1039893920
...
Between cycles 1 and 2, app_time_ns jumps by 4,295,000,000 ns (4.3sec). Same shape as your lcec.write-all trace.
Mechanism, walked through the code:
1. Cycle 0 pre_send reads ref_time_lo = 1,875,535,147. At this point our first frame carrying ecrt_master_application_time() has NOT yet been sent (cycle_start queues it, the actual send happens later in pre_send). So the read is the slave's own free-running DC SystemTime from before it received our epoch, exactly your speculation about the 0x92C offset register. lcec's unwrap code then seeds master->ref_time_ns = (app_time & 0xFFFFFFFF00000000) | 1,875,535,147.
2. Cycle 1 pre_send reads ref_time_lo = 1,037,346,343 (now valid, slave has received our app_time and rebased). The 32-to-64-bit wrap detector sees 1,037,346,343 < 1,875,535,147 and adds (1LL << 32) to master->ref_time_ns. False wrap.
3. With ref_time_ns now 4.3 billion ns ahead of dc_time_ns, the resnap logic in pre_send divides the diff by the period and snaps app_time backwards by 4295 periods. That's your +4.295e9 jump.
4. PI then only has to absorb the sub-period residual, which is why your cycle 3+ looks normal.
Fix is in v1.41.0-pre2. A ref_seeded flag discards the first nonzero read; the second nonzero read seeds the unwrap state without wrap detection; steady-state wrap detect takes over from cycle 2 onward.
After the fix on the same hardware:
Code:
# cycle pll_err ref_time_lo app_time_ns app_time_lo
0 0 3928128362 829970359148090426 4011856954
1 0 4043140737 829970359149090426 4012856954
2 -192285 4044085554 829970359181090426 4044856954
3 -187787 4045074812 829970359182090426 4045856954
...
No phantom 4.3sec. The cycle 1 to 2 delta is now 32 ms (32 periods), which is the real initial phase error between the slave's rebased SystemTime and our app_time at startup, snapped to whole periods by resnap. PI absorbs the ~190 us sub-period residual over the settle time. pll_reset_count stays at 0 because the first resnap fires with dc_diff_ns == 0 and skips the counter increment.
So your speculation about the slave maintaining its own time and adding an offset after rebase is consistent with what we observe. The lcec bug was specifically the wrap detector treating the pre-rebase read as the baseline for the post-rebase read.
R2M in the current master was already correct in this respect (no read, no bad baseline), so no change there.
Thanks again for the clear debug output, it was the whole reason this was easy to pin down.
Could you test my 1.41~pre2 release on GitHub, to confirm you get the same result?
github.com/grandixximo/linuxcnc-ethercat...ses/tag/v1.41.0-pre2
But be warned even with this fix the OP time in my case remain about the same, the hardware has to do OP to run in DC, and it does take time, I agree with Rob's assessment, having the first device on the network be a good DC device is a must if you want good DC, I could try to debug what is the problem with papagno's first device, and I am also trying to get Ethercat to fix the function where we will be allowed to move the DC reference to arbitrary devices in the network, at the moment this function is present in the API but does NOT work.
This is simply restart after few minutes LinuxCNC was closed (servos had time to drift apart)
12s OP
Then quickly close and open again (servos had NO time to drift apart)
3s OP
if you want to get similar logs
File Attachment:
File Name:
debug.zip
File Size:426.17 KB
As far as AssignActivate 0x300 to 0x730 I don't use this type of sync as i run in pos-cmd I don't think is necessary in my use case, but it should work, I think 0x300 should work fine for pos-cmd, if you use vel or torque command with internal PID you might want to look at 0x700 or 0x730