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.