hm2 TRACER - interested adding it to the official repository

[zz912]

Hello,

I am testing Mesa card with Xenomai 4 #4199

It has amazing results, but on my PC configuration I sometimes get 800 000 ns spikes.

I created hm2_tracer for this.
https://github.com/zz912/linuxcnc/tree/feature/hm2-trace

You can read more about it here:
https://github.com/zz912/linuxcnc/blob/feature/hm2-trace/src/hal/drivers/mesa-hostmot2/hm2_tracer-readme.md

If anyone would like to try it out, just add to the hal file:

loadrt hm2_eth ......
loadusr hm2-trace-log

The program works in such a way that if the (hm2_7i96s.0.read + hm2_7i96s.0.write > 50% Realtime Threads Period) it creates a log file in ~.

For testing, I reduce the ratio: https://github.com/zz912/linuxcnc/blob/9a56334cd81756fcd5a9ddf861a7df0ed0bdd39e/src/hal/drivers/mesa-hostmot2/hm2_trace_trigger.c#L31

The log file looks like this:

HM2 TRACE

version           : 1
generation        : 1
trigger_reason    : LATENCY
trigger_ratio     : 15 %

read_runtime_ns   : 105024
write_runtime_ns  : 4119
total_runtime_ns  : 109143

read_tmax_ns      : 144604
write_tmax_ns     : 17003
total_tmax_ns     : 158941

ring_size         : 4096
ring_head         : 2153
trigger_index     : 104
samples_written   : 2153

Ring buffer:
------------
 idx        timestamp    snapshot(ns)      cycle(ns)      event(ns)  event
---- ---------------- --------------- --------------- --------------- ------------

....

  91   81878499561176       +13003605              +0         +880125 CYCLE_START 
  92   81878499561274       +13003703             +98             +98 READ_ENTER  
  93   81878499561299       +13003728            +123             +25 RECV_ENTER  
  94   81878499667685       +13110114         +106509         +106386 RECV_EXIT   
  95   81878499673268       +13115697         +112092           +5583 READ_EXIT   
  96   81878499687697       +13130126         +126521          +14429 WRITE_ENTER 
  97   81878499698230       +13140659         +137054          +10533 WRITE_EXIT  

  98   81878500558931       +14001360              +0         +860701 CYCLE_START 
  99   81878500559025       +14001454             +94             +94 READ_ENTER  
 100   81878500559050       +14001479            +119             +25 RECV_ENTER  
 101   81878500694149       +14136578         +135218         +135099 RECV_EXIT   
 102   81878500703629       +14146058         +144698           +9480 READ_EXIT   
 103   81878500725404       +14167833         +166473          +21775 WRITE_ENTER 


========================================================================
========================== TRIGGER DETECTED ============================
========================================================================


 104   81878500739741       +14182170         +180810          +14337 WRITE_EXIT  

 105   81878501555862       +14998291              +0         +816121 CYCLE_START 
 106   81878501555919       +14998348             +57             +57 READ_ENTER  
 107   81878501555994       +14998423            +132             +75 RECV_ENTER  
 108   81878501671492       +15113921         +115630         +115498 RECV_EXIT   
 109   81878501673620       +15116049         +117758           +2128 READ_EXIT   
 110   81878501679328       +15121757         +123466           +5708 WRITE_ENTER 
 111   81878501684921       +15127350         +129059           +5593 WRITE_EXIT  

 112   81878502555892       +15998321              +0         +870971 CYCLE_START 
 113   81878502555934       +15998363             +42             +42 READ_ENTER  
 114   81878502555985       +15998414             +93             +51 RECV_ENTER  
 115   81878502652085       +16094514          +96193          +96100 RECV_EXIT   
 116   81878502653360       +16095789          +97468           +1275 READ_EXIT   
 117   81878502658396       +16100825         +102504           +5036 WRITE_ENTER 
 118   81878502662937       +16105366         +107045           +4541 WRITE_EXIT  

hm2_trace_2026_07_11-06_41_47.log

I made the program with the help of ChatGPT. The project is in the "It works" phase. This phase is sufficient for my needs. However, if I wanted to make a proper code suitable for PR, I would like to redo the tracer architecture and its activation in the hal file.

I would like to ask if there would be interest in this hm2_tracer if I redid it?

@pcw-mesa what is your opinion?

[hdiethelm]

Hmm, 800 000 ns sounds like a timeout was hit.

https://linuxcnc.org/docs/html/man/man9/hm2_eth.9.html
Looks like not all pins / parameters are documented. These are all the parameters / pins concerning Ethernet IO:

• hm2_7i96.packet-read-timeout = 80 -> 80% of the thread time -> 800 000 ns
• hm2_7i96.packet-error-total -> If you hit a read timeout, this value will increase every time it happens

Can you try to hit the 800 000 ns and create the same screenshot from halshow with all this pins / parameters? I would expect "hm2_7i96.packet-error-total" being 1 or more after this.

This happened to me with a crap realtek driver all the time. For your setup, it could be:

• Bad network card or driver
• Bad network cable
• Disturbance from other electrical part
• Issue in the mesa card. You can try to update to the newest firmware

[hdiethelm]

BTW: Your trace shows what I would expect: Your read is slow. The question is just why.
This was also visible in the Wireshark traces, so nothing new there.

So I don't really see a benefit of such a tracer. It just shows what was already visible.

[hdiethelm]

BTW2:
https://networkengineering.stackexchange.com/questions/67473/what-is-an-acceptable-bit-error-ratio
At the actual 254 Bytes / Cycle and 10 bits per byte, you will hit a bit error every 1÷(254×10×1000×10⁻¹²)÷3600 = 109h
It can be easily 10x more or less, depending on many factors.

As soon as a bit error hits, you will run into a timeout, due to it is UDP, so no re-transmit. The package is most probably doped due to a checksum error. Never the less, it is not a big deal, you just hit 800 us for one cycle and the next it continues just if nothing has happened.

[zz912]

BTW: Your trace shows what I would expect: Your read is slow. The question is just why.
This was also visible in the Wireshark traces, so nothing new there.

So I don't really see a benefit of such a tracer. It just shows what was already visible.

Once I finished this tracer, I can't simulate this error. :-)

I currently have tracepoints HM2_TRACE(&hm2->trace, XXXXXXXXXXX); here:
https://github.com/zz912/linuxcnc/blob/9a56334cd81756fcd5a9ddf861a7df0ed0bdd39e/src/hal/drivers/mesa-hostmot2/hostmot2.c#L95-L134

The point is that I placed tracepoints where I can verify the TRACER functionality. This way I can confirm that the tracer is working properly.

When this error reappears, I can simply add more tracepoints and get information that I can't get otherwise.

That's the goal of my efforts.

[hdiethelm]

What will happen is that hm2_eth read timeouts at 800us. This is this loop:
https://github.com/zz912/linuxcnc/blob/9a56334cd81756fcd5a9ddf861a7df0ed0bdd39e/src/hal/drivers/mesa-hostmot2/hm2_eth.c#L1032
The max. time you see is just to near to the default timeout value to be a coincidence.

Then, record_soft_error() will increase *board->hal->packet_error_total which you see in hm2_7i96.packet-error-total.

Due to no interface is 100% error free, this will happen from time to time. With bad hardware of course more often than with good one. As long as there is no Unexpected realtime delay on task 0 with period 1000000 this is all fine and should cause no issues whatever.

If you have Unexpected realtime delay on task 0 with period 1000000, just set hm2_7i96.packet-read-timeout lower, for example 50 and it should be gone.

You can try wiggle your ethernet cable or switch on / off the spindle or servos to try to get the timeout reproducible.

We lost like a full week of work due to crap cheep Ethernet cables in our company once, was just a random emergency stop from time to time. By randomly exchanging cables it was gone and never appeared again.

[pcw-mesa]

In terms of inherent error rate, my experience is that if system latency issues are fixed,
you will never get timeouts. I have had multiple systems running more than 4 months
without a single timeout. This is at least 30/40 X the 109 hour estimate

I think by far, most timeouts are kernel/driver related, For example, on my home test machine
(a HP EliteDesk 800 G1) I could never get more than a day or two without packet loss until
I installed a 7.x kernel. Now (in conjunction with isolcpus and pinning the Ethernet IRQ)
I can run for months and never get a timeout, even when doing compilations or viewing YouTube
videos.

[zz912]

Thank you for the responses and explanations.
Currently, when I started testing the tracer, the tests are at about 33% for the 3rd day. :-)

From my observation, it turned out that it would be a good idea to delay the evaluation of packet-error-total for example by 1E6 periods (1 second) from the start of LCNC. After turning on LCNC, I always get 1 error packet with some configurations.

[pcw-mesa]

There is a bug in hm2_modbus that causes 1 timeout at startup.
That's the only startup packet drop issue I know about.

[BsAtHome]

There is a bug in hm2_modbus that causes 1 timeout at startup. That's the only startup packet drop issue I know about.

Please elaborate.

[pcw-mesa]

I don't really know anything else, just that if you run a hm2-modbus config
you always get 1 packet dropped at startup. I think mesa modbus has the same
issue but it's been a while since I have run that.

[zz912]

I finally got to the slow read record:

HM2 TRACE

version           : 1
generation        : 1
trigger_reason    : LATENCY
trigger_ratio     : 69 %

read_runtime_ns   : 106228
write_runtime_ns  : 4013
total_runtime_ns  : 110241

read_tmax_ns      : 693048
write_tmax_ns     : 37910
total_tmax_ns     : 696944

ring_size         : 4096
ring_head         : 847
trigger_index     : 2894
samples_written   : 3898491727

Ring buffer:
------------
 idx        timestamp    snapshot(ns)      cycle(ns)      event(ns)  event
---- ---------------- --------------- --------------- --------------- ------------

2881  639738525906559      -294104548              +0         +895847 CYCLE_START 
2882  639738525906603      -294104504             +44             +44 READ_ENTER  
2883  639738525906639      -294104468             +80             +36 RECV_ENTER  
2884  639738526010716      -294000391         +104157         +104077 RECV_EXIT   
2885  639738526011831      -293999276         +105272           +1115 READ_EXIT   
2886  639738526014823      -293996284         +108264           +2992 WRITE_ENTER 
2887  639738526018628      -293992479         +112069           +3805 WRITE_EXIT  

2888  639738526906595      -293104512              +0         +887967 CYCLE_START 
2889  639738526906640      -293104467             +45             +45 READ_ENTER  
2890  639738526906676      -293104431             +81             +36 RECV_ENTER  
2891  639738527598561      -292412546         +691966         +691885 RECV_EXIT   
2892  639738527599688      -292411419         +693093           +1127 READ_EXIT   
2893  639738527602839      -292408268         +696244           +3151 WRITE_ENTER 


========================================================================
========================== TRIGGER DETECTED ============================
========================================================================


2894  639738527606735      -292404372         +700140           +3896 WRITE_EXIT  

2895  639738527906595      -292104512              +0         +299860 CYCLE_START 
2896  639738527906659      -292104448             +64             +64 READ_ENTER  
2897  639738527906732      -292104375            +137             +73 RECV_ENTER  
2898  639738528011356      -291999751         +104761         +104624 RECV_EXIT   
2899  639738528012535      -291998572         +105940           +1179 READ_EXIT   
2900  639738528015786      -291995321         +109191           +3251 WRITE_ENTER 
2901  639738528019805      -291991302         +113210           +4019 WRITE_EXIT  

hm2_trace_2026_07_17-17_39_27.log

[hdiethelm]

As expected, you hit a read timeout, identified by packet_error_total = 1.

• Did this happen right at start or after a few hours?
• Any other effects except the bad time?
• Did you do anything while this happened? Like powering on the spindle, compressor or anything that could generate EMI?

@pcw-mesa
In logs posted in #4199, I see Please consider upgrading.:

hm2_modbus.0: warning: PktUART version is less than 3 (Rx=2 Tx=2). Please consider upgrading.
hm2_modbus.0: inst->name     : hm2_modbus.0
hm2_modbus.0: inst->uart     : hm2_7i96s.0.pktuart.0
hm2_modbus.0: inst->mbccbsize: 320
hm2_modbus.0: inst->ninit    : 0
hm2_modbus.0: inst->ncmds    : 5
hm2_modbus.0: inst->npins    : 5
hm2_modbus.0: inst->icdelay  : 0
hm2_modbus.0: inst->rxdelay  : 34
hm2_modbus.0: inst->txdelay  : 36
hm2_modbus.0: inst->drvdelay : 1
hm2_modbus.0: PktUART serial port 'hm2_7i96s.0.pktuart.0' configured to 8N1@9600

Might this be an issue connected to older Mesa Firmware?

[zz912]

As expected, you hit a read timeout, identified by packet_error_total = 1.

No. packet_error_total is actually 0. I'm using modbus, so that's where the bug is.
#4236 (comment)

The spike that created the log file occurred after 5 days. I had the PC + Mesa turned on for 5 days. I occasionally worked on the PC (Firefox, FreeCAD, milling, ...) On the day the spike appeared, nothing was happening on the PC, and no one was home.

I'm not a PC expert. I don't know if such a short Spike should be considered a problem.

If such a short Spike is not a problem, maybe there's no point in looking for its cause, but read.tmax should be filtered.

Let me explain what I mean. Imagine you are a CNC machine manufacturer who wants to ship your machine to a customer. You are not a PC expert. First you check the latency, then you use the GUI Mesa tests in Gmoccapy. You check the servo thread test and the nic test. If both tests pass, you can ship the machine.

I would like to make using LCNC as easy as this. I know I am not able to test the whole LCNC, that is why I chose to test Optiplex 9010 + Gmoccapy + mesa 7i96S all the time. Nothing more.

At the moment I think the "Servo Thread Test" is working properly. If the Integrator finds out that it is more than 70%, he should start looking for a solution.

At the moment I think the "NIC Test" is NOT working properly.

1. read.tmax + write.tmax is not read-and-write.tmax
   Would you be willing to create such a pin? Better named of course.
2. read-and-write.tmax should also have a read-and-write-limit pin for filtering, like a packet-error pin

[hdiethelm]

As expected, you hit a read timeout, identified by packet_error_total = 1.

No. packet_error_total is actually 0. I'm using modbus, so that's where the bug is. #4236 (comment)

Can you create an issue for this or is there already one?

The spike that created the log file occurred after 5 days. I had the PC + Mesa turned on for 5 days. I occasionally worked on the PC (Firefox, FreeCAD, milling, ...) On the day the spike appeared, nothing was happening on the PC, and no one was home.

I'm not a PC expert. I don't know if such a short Spike should be considered a problem.

If such a short Spike is not a problem, maybe there's no point in looking for its cause, but read.tmax should be filtered.

As long as you don't get an Unexpected realtime delay on task 0 with period 1000000 error, it should be fine. Not perfect but good enough.
read.tmax is exactly to detect single spikes, so it should never be filtered.

Due to this time, it took 5 days for a spike, I would just live with it. If you are still motivated, it's a long process, you would need to run several tests for at least 10 days to see if the issue is now in a specific configuration.

Did you have this spikes only with Xenomai or also with branch master / PREEMT_RT?

What I would suggest:

• On PREEMT_RT: Use cyclictest to detect if its an unconnected realtime issue of your hardware

sudo modprobe msr
sudo cyclictest --mlockall -a 3 --priority=97 -N --interval=1000 --smi

• On PREEMT_RT: Use sudo taskset 8 chrt 90 ping -i .001 -q 192.168.1.121 to check for network issues
• On Xenomai4: Use sudo latmus to detect xenomai related timing issues
• On Xenomai4: Use oob-net-ping Mesa Hostmot2 Xenomai4 OOB networking support #4199 (comment) to detect xenomai related network issues
• Remove MODBUS: Mesa Hostmot2 Xenomai4 OOB networking support #4199 (comment)
• Use an Intel I250 or I350 network card
• Branch master / PREEMT_RT
• Branch 2.9 / PREEMT_RT
• Update mesa card firmware to latest / Branch master / PREEMT_RT
• Other PC of the same type (It might well be a Mainboard / CPU problem)

Let me explain what I mean. Imagine you are a CNC machine manufacturer who wants to ship your machine to a customer. You are not a PC expert. First you check the latency, then you use the GUI Mesa tests in Gmoccapy. You check the servo thread test and the nic test. If both tests pass, you can ship the machine.

If you are a manufacturer, you should hire someone who knows about PC's, is able to debug real time issues and invest in hardware that behaves well. I know about Beckhoff, they even build their own PC's including custom BIOS due to with consumer and even industrial PC's is always a gamble if they meet real time of if some BIOS non maskable interrupt / crap hardware just trashes everything after a random update by the manufacturer and you have no way of fixing it and no way of buying hardware that works any more.

If it is a hobby, of course you can invest some time in manual tuning and find a hardware that works well. And live with the fact that it might crash after running for a long time. But as soon it is a industrial device, it gets way harder.

I would like to make using LCNC as easy as this. I know I am not able to test the whole LCNC, that is why I chose to test Optiplex 9010 + Gmoccapy + mesa 7i96S all the time. Nothing more.

At the moment I think the "Servo Thread Test" is working properly. If the Integrator finds out that it is more than 70%, he should start looking for a solution.

At the moment I think the "NIC Test" is NOT working properly.

1. read.tmax + write.tmax is not read-and-write.tmax
   Would you be willing to create such a pin? Better named of course.

2. read-and-write.tmax should also have a read-and-write-limit pin for filtering, like a packet-error pin

This is not a bug.
You can have in cycle:

1. read.time = 100 write.time = 200
2. read.time = 200 write.time = 100
   So you will end up with read.tmax + write.tmax = 400.

Now that's the theoretical worst case time with could happen but never happened. This .time / .tmax values are set generic for every function, so a read-and-write.tmax pin is not easy to do. However, you can cobble it together in hal using sum2 / minmax blocks.

read.tmax should never be > 80% of interval. write.tmax basically does not matter as long as servo-thread.tmax is always < interval.

If you are not happy with the tool, best you contact the original developer. I don't use it, I added a timing display using hal + pyvcp:

It shows:

• Max jitter at start
• Max jitter at end
• Max of servo-thread.time

So I see always if my machine runs well.

The code is the following. I removed other displays.
main.hal

loadrt timedelta count=2

addf timedelta.0                          servo-thread
#other addf functions
addf timedelta.1                          servo-thread

pyvcp.hal

# connect the PyVCP jitter
loadrt conv_s32_float count=3
loadrt minmax count=1

addf conv-s32-float.0 servo-thread
addf conv-s32-float.1 servo-thread
addf conv-s32-float.2 servo-thread
addf minmax.0 servo-thread

net pyvcp-jitter-s0 timedelta.0.jitter => conv-s32-float.0.in
net pyvcp-jitter-s1 timedelta.1.jitter => conv-s32-float.1.in
net pyvcp-jitter0 conv-s32-float.0.out => pyvcp.jitter0
net pyvcp-jitter1 conv-s32-float.1.out => pyvcp.jitter1
net pyvcp-jitter-reset timedelta.0.reset <= pyvcp.jitter-reset
net pyvcp-jitter-reset timedelta.1.reset <= pyvcp.jitter-reset
net pyvcp-jitter-reset minmax.0.reset <= pyvcp.jitter-reset

net pyvcp-tservo-s servo-thread.time => conv-s32-float.2.in
net pyvcp-tservo conv-s32-float.2.out => minmax.0.in
net pyvcp-tmax pyvcp.tmax <= minmax.0.max

pyvcp.xml

<?xml version='1.0' encoding='UTF-8'?>
<pyvcp>
  <vbox>
    <relief>RAISED</relief>
    <bd>3</bd>
    <label>
        <text>"Jitter"</text>
        <font>("Helvetica",16)</font>
    </label>
    <hbox>
      <vbox>
        <bar>
          <halpin>"jitter0"</halpin>
          <max_>50000</max_>
          <fillcolor>"red"</fillcolor>
          <range1>0,10000,"green"</range1>
          <range2>10000,25000,"orange"</range2>
          <range3>25000,50000,"red"</range3>
          <canvas_height>40</canvas_height>
          <bar_height>20</bar_height>
        </bar>
        <bar>
          <halpin>"jitter1"</halpin>
          <max_>100000</max_>
          <fillcolor>"red"</fillcolor>
          <range1>0,50000,"green"</range1>
          <range2>50000,75000,"orange"</range2>
          <range3>75000,100000,"red"</range3>
          <canvas_height>40</canvas_height>
          <bar_height>20</bar_height>
        </bar>
        <bar>
          <halpin>"tmax"</halpin>
          <max_>200000</max_>
          <fillcolor>"red"</fillcolor>
          <range1>0,100000,"green"</range1>
          <range2>100000,150000,"orange"</range2>
          <range3>150000,200000,"red"</range3>
          <canvas_height>40</canvas_height>
          <bar_height>20</bar_height>
        </bar>
      </vbox>
      <button>
          <font>("Helvetica",16)</font>
          <width>1</width>
          <halpin>"jitter-reset"</halpin>
          <text>"Clr"</text>
      </button>
    </hbox>
  </vbox>
</pyvcp>