sittner / linuxcnc-ethercat

LinuxCNC EtherCAT HAL driver
GNU General Public License v2.0
209 stars 142 forks source link

Unexcepted realtime delay on task 0 with period 1000000 #94

Open ibXCM opened 4 years ago

ibXCM commented 4 years ago

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.

sirop commented 4 years ago

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:

  1. Mismatch between LinuxCNC thread and EtherCAT cycle times.
  2. Latency too high because you use a generic EtherCAT driver.
  3. Something else...
ibXCM commented 4 years ago

Hi,Boris Thanks for your reply,I‘ll check it now Thanks & Best Regards wade

Boris Skegin notifications@github.com 于2020年9月17日周四 下午2:30写道:

First try to undersrtand 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:

  1. Mismatch between LinuxCNC thread and EtherCAT cycle times.
  2. Latency too high because you use a generic EtherCAT driver.
  3. Something else...

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/sittner/linuxcnc-ethercat/issues/94#issuecomment-693969179, or unsubscribe https://github.com/notifications/unsubscribe-auth/AK7EBE6KQN75ILLRJZ6D5G3SGGUHXANCNFSM4RP47WIQ .