Unexcepted realtime delay on task 0 with period 1000000
ibXCM opened this issue · 2 comments
Dears
When I run linuxcnc,there is always an error exist as following:
Unexcepted realtime delay on task 0 with period 1000000
This message will only display once per session.
Run the Latency Test and resolve before continuing.
task: main loop took 0.022446 seconds
task: main loop took 0.010904 seconds
task: main loop took 0.011113 seconds
task: main loop took 0.011344 seconds
task: main loop took 0.030612 seconds
Shutting down and cleaning uo LinuxCNC
task: 44863 cycles, min=0.000744, max=0.081036, avg=0.002223, 159 latency excurs
ions (> 10x excepted cycle time of 0.001000s)
Note: Using POSIX realtime
I'm using debian9 with kernel 4.19.132-rt59. and when I run rt-tests, the max jitter is 90us.
The following is my "demsg" printed
what should I do now？
[16733.892777] ravb e6800000.ethernet eth0: Link is Down
[16733.898024] EtherCAT 0: Link state of ecm0 changed to DOWN.
[16733.903653] EtherCAT WARNING 0: 1 datagram TIMED OUT!
[16733.908741] EtherCAT WARNING 0: 19 datagrams UNMATCHED!
[16733.914019] EtherCAT 0: 0 slave(s) responding on main device.
[16741.137057] ravb e6800000.ethernet eth0: Link is Up - 100Mbps/Full - flow control off
[16741.137876] EtherCAT 0: Link state of ecm0 changed to UP.
[16741.147419] EtherCAT WARNING 0: 1 datagram TIMED OUT!
[16741.362502] EtherCAT 0: 1 slave(s) responding on main device.
[16741.368298] EtherCAT 0: Slave states on main device: INIT.
[16741.374126] EtherCAT 0: Scanning bus.
[16741.577344] EtherCAT 0: Bus scanning completed in 200 ms.
[16741.582790] EtherCAT 0: Using slave 0 as DC reference clock.
[16741.592662] EtherCAT 0: Slave states on main device: PREOP.
[16774.389669] EtherCAT 0: Master thread exited.
[16774.394799] EtherCAT 0: Releasing main device 00:03:82:FE:20:98.
[16774.417715] ec_generic: Unloading.
[16774.444273] EtherCAT: Master module cleaned up.
[16776.520944] EtherCAT: Master driver 1.5.2 unknown
[16776.527372] EtherCAT: 1 master waiting for devices.
[16776.546774] ec_generic: EtherCAT master generic Ethernet device module 1.5.2 unknown
[16776.554641] EtherCAT: Accepting 00:03:82:FE:20:98 as main device for master 0.
[16776.561984] ec_generic: Binding socket to interface 4 (eth0).
[16776.581612] EtherCAT 0: Starting EtherCAT-IDLE thread.
[16776.586977] EtherCAT 0: Link state of ecm0 changed to UP.
[16776.591249] EtherCAT 0: 1 slave(s) responding on main device.
[16776.591259] EtherCAT 0: Slave states on main device: PREOP.
[16776.591672] EtherCAT 0: Scanning bus.
[16776.787515] EtherCAT 0: Bus scanning completed in 196 ms.
[16776.792955] EtherCAT 0: Using slave 0 as DC reference clock.
[16802.516971] EtherCAT: Requesting master 0...
[16802.521311] EtherCAT: Successfully requested master 0.
[16802.528703] EtherCAT 0: Domain0: Logical address 0x00000000, 32 byte, expected working counter 3.
[16802.538527] EtherCAT 0: Datagram domain0-0-main: Logical offset 0x00000000, 32 byte, type LRW.
[16802.551591] EtherCAT 0: Master thread exited.
[16802.556011] EtherCAT 0: Starting EtherCAT-OP thread.
[16808.125764] EtherCAT WARNING 0-0: Slave did not sync after 5000 ms.
[16808.143958] EtherCAT 0: Domain 0: Working counter changed to 3/3
[16808.143965] .
[16808.272611] EtherCAT 0: Slave states on main device: OP.
[16808.558010] EtherCAT WARNING 0: 14 datagrams UNMATCHED!
[16808.785913] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 7 times.
[16809.145873] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16809.145879] .
[16809.559962] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16809.789905] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16810.149899] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16810.149906] .
[16810.561092] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16810.793900] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16811.153888] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16811.153893] .
[16811.558529] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16811.797899] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16812.157898] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16812.157904] .
[16812.560430] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16812.801898] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16813.161897] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16813.161903] .
[16813.559364] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16813.805913] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16814.165893] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16814.165899] .
[16814.558506] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16814.809893] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16815.169896] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16815.169902] .
[16815.559329] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16815.813904] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16816.173897] EtherCAT 0: Domain 0: 8 working counter changes - now 3/3
[16816.173903] .
[16816.558702] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16816.817906] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16817.177900] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16817.177906] .
[16817.559332] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16817.821892] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16818.181869] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16818.181875] .
[16818.560764] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16818.825894] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16819.185895] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16819.185901] .
[16819.561389] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16819.829911] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16820.189905] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16820.189912] .
[16820.561512] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16820.833898] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16821.193904] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16821.193910] .
[16821.558742] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16821.837914] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16822.197910] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16822.197916] .
[16822.559733] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16822.841897] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16823.201889] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16823.201895] .
[16823.560775] EtherCAT WARNING 0: 36 datagrams UNMATCHED!
[16823.845859] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 18 times.
[16824.205894] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16824.205900] .
[16824.558505] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16824.849895] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16825.209879] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16825.209884] .
[16825.557758] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16825.853896] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16826.213898] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16826.213903] .
[16826.558925] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16826.857870] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16827.217884] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16827.217890] .
[16827.560576] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16827.861900] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16828.221908] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16828.221914] .
[16828.559327] EtherCAT WARNING 0: 36 datagrams UNMATCHED!
[16828.865919] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 18 times.
[16829.225855] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16829.225861] .
[16829.559312] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16829.869906] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16830.229843] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16830.229854] .
[16830.559334] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16830.873920] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16831.233892] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16831.233898] .
[16831.560359] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16831.877892] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16832.237901] EtherCAT 0: Domain 0: 8 working counter changes - now 3/3
[16832.237908] .
[16832.557727] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16832.881852] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16833.241904] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16833.241911] .
[16833.558874] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16833.885917] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16834.245883] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16834.245889] .
[16834.557694] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16834.889858] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16835.249932] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16835.249940] .
[16835.560869] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16835.893898] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16836.253853] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16836.253859] .
[16836.561528] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16836.897904] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16837.257917] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16837.257924] .
[16837.558614] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16837.901904] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16838.261903] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16838.261909] .
[16838.557817] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16838.905898] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16839.265884] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16839.265890] .
[16839.559634] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16839.909919] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16840.269881] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16840.269886] .
[16840.558048] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16840.913853] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16841.273899] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16841.273905] .
[16841.559161] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16841.917874] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16842.035093] EtherCAT 0: 0 slave(s) responding on main device.
[16842.046817] EtherCAT 0: 1 slave(s) responding on main device.
[16842.052637] EtherCAT 0: Slave states on main device: OP.
[16842.067570] EtherCAT 0: Scanning bus.
[16842.277878] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16842.277883] .
[16842.560969] EtherCAT WARNING 0: 25 datagrams UNMATCHED!
[16842.863365] EtherCAT WARNING: Datagram 000000009709d9b5 (master-fsm) was SKIPPED 1 time.
[16842.921913] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16843.281897] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16843.281904] .
[16843.560394] EtherCAT WARNING 0: 16 datagrams UNMATCHED!
[16843.925884] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16844.285894] EtherCAT 0: Domain 0: 8 working counter changes - now 3/3
[16844.285901] .
[16844.558353] EtherCAT WARNING 0: 16 datagrams UNMATCHED!
[16844.929911] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16845.279272] EtherCAT 0: Bus scanning completed in 3220 ms.
[16845.285100] EtherCAT 0: Using slave 0 as DC reference clock.
[16845.289855] EtherCAT 0: Domain 0: 4 working counter changes - now 3/3
[16845.289861] .
[16845.559029] EtherCAT WARNING 0: 10 datagrams UNMATCHED!
[16845.933893] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 9 times.
[16846.293902] EtherCAT 0: Domain 0: 2 working counter changes - now 3/3
[16846.293909] .
[16846.560366] EtherCAT WARNING 0: 32 datagrams UNMATCHED!
[16846.937895] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 16 times.
[16847.297881] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16847.297887] .
[16847.560378] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16847.941881] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16848.301898] EtherCAT 0: Domain 0: 6 working counter changes - now 3/3
[16848.301904] .
[16848.560487] EtherCAT WARNING 0: 34 datagrams UNMATCHED!
[16848.945876] EtherCAT WARNING: Datagram 0000000034347194 (domain0-0-main) was SKIPPED 17 times.
[16849.078481] EtherCAT 0: Master thread exited.
[16849.082914] EtherCAT 0: Starting EtherCAT-IDLE thread.
[16849.088856] EtherCAT 0: Releasing master...
[16849.093155] EtherCAT 0: Released.
[16849.097545] EtherCAT WARNING 0-0: Changed to SAFEOP + ERROR in the meantime.
[16849.215460] EtherCAT 0: Slave states on main device: PREOP.
[16849.892503] EtherCAT WARNING: Datagram 000000009709d9b5 (master-fsm) was SKIPPED 1 time.
First try to understand if this issue is EtherCAT specific or if it comes up with any other LinuxCNC script.
If it is EtherCAT specific, try to understand this https://etherlab-users.etherlab.narkive.com/W9esJT3e/unmatched-and-skipped-datagrams#post2 .
Possible reasons:
- Mismatch between LinuxCNC thread and EtherCAT cycle times.
- Latency too high because you use a generic EtherCAT driver.
- Something else...