PoC reactor: timers tracker

[nefelim4ag]

While reading logs and now rare TTC, I sometimes had an itch idea to track if step generations takes more time then there is time between flushes, so if generation happens every 50ms, and takes 51ms we are lagging behind.
But adding such tracker inside "each" function seems suboptiomal.

Then there is logs like in #7168 where something paused the klippy.
Or when webhook request is large (Exclude object and msgspec).

So, I had an idea: "what if we log if timer takes > X time (idk, 50ms?)".
But even so, if this indicates something, this can be okayish.

So, it seems to me that ability to "profile" timers, and by so distinct calls can shine a light upon what happens and where.
This is an attempt to achive this.

Upon shutdown, there is a new output:

8523.685959 0.000126 TMCErrorCheck._do_periodic_check (tmc.py:178)
8523.717709 0.000975 QueryStatusHelper._do_query (webhooks.py:487)
8523.751250 0.000852 PrinterMotionQueuing._flush_handler (motion_queuing.py:180)
8523.761183 0.000346 BatchBulkHelper._proc_batch (bulk_sensor.py:70)
8523.772346 0.000106 PrinterTemplateEvaluator._render (output_pin.py:130)
8523.781523 0.000099 HeaterPredictControl._render (heater_pc.py:56)
8523.811693 0.000063 HeaterPredictControl._render (heater_pc.py:56)
8523.826827 0.000188 TMCErrorCheck._do_periodic_check (tmc.py:178)
8523.829724 0.000152 TMCErrorCheck._do_periodic_check (tmc.py:178)
8523.850672 0.000004 ToolHead._priming_handler (toolhead.py:327)
8523.861749 0.000231 BatchBulkHelper._proc_batch (bulk_sensor.py:70)
8523.886758 0.000028 PrinterSensorCombined._temperature_update_event (temperature_combined.py:103)
8523.886758 0.000016 PrinterSensorCombined._temperature_update_event (temperature_combined.py:103)
8523.900871 0.000065 HeaterPredictControl._render (heater_pc.py:56)
8523.952006 0.000048 Temperature_HOST._sample_pi_temperature (temperature_host.py:48)
8523.952006 0.000007 HeaterCheck.check_event (verify_heater.py:47)
8523.962139 0.000215 BatchBulkHelper._proc_batch (bulk_sensor.py:70)
8523.968103 0.000574 QueryStatusHelper._do_query (webhooks.py:487)
8524.000755 0.001229 PrinterMotionQueuing._flush_handler (motion_queuing.py:180)
8524.017060 0.000013 ClockSync._get_clock_event (clocksync.py:59)
8524.028143 0.000009 ClockSync._get_clock_event (clocksync.py:59)
8524.037224 0.000009 HeaterCheck.check_event (verify_heater.py:47)
8524.062311 0.000258 BatchBulkHelper._proc_batch (bulk_sensor.py:70)
8524.082356 0.000139 HeaterPredictControl._render (heater_pc.py:56)
8524.112034 0.000073 HeaterPredictControl._render (heater_pc.py:56)
8524.162800 0.000323 BatchBulkHelper._proc_batch (bulk_sensor.py:70)
8524.148177 0.000158 BME280._sample_bme680 (bme280.py:513)
8524.186994 0.000028 PrinterSensorCombined._temperature_update_event (temperature_combined.py:103)
8524.186994 0.000016 PrinterSensorCombined._temperature_update_event (temperature_combined.py:103)
8524.190110 0.000004 ToolHead._priming_handler (toolhead.py:327)
8524.201181 0.000068 HeaterPredictControl._render (heater_pc.py:56)
8524.218319 0.000593 QueryStatusHelper._do_query (webhooks.py:487)
8524.224000 0.000013 IdleTimeout.timeout_handler (idle_timeout.py:75)

This is the whole raw idea.
Probably it makes sense to filter timer events <0.001s.
Probably there is a different way to run analyze shutdown.

Overall, even if I know the practical usage for this, I'm not sure about practical application.
Pros:

• We know what happens on the host side mostly, better than "cpu usage" high/low
• We probably see the code from custom "extensions."

Cons:

• Runtime overhead seems to be too small
• Complexity
• Another 100 lines upon shutdown

Thanks,
-Timofey

---

git fetch origin pull/7170/head
git checkout FETCH_HEAD
sudo systemctl restart klipper

[github-actions]

Thank you for your contribution to Klipper. Unfortunately, a reviewer has not assigned themselves to this GitHub Pull Request. All Pull Requests are reviewed before merging, and a reviewer will need to volunteer. Further information is available at: https://www.klipper3d.org/CONTRIBUTING.html

There are some steps that you can take now:

1. Perform a self-review of your Pull Request by following the steps at: https://www.klipper3d.org/CONTRIBUTING.html#what-to-expect-in-a-review
   If you have completed a self-review, be sure to state the results of that self-review explicitly in the Pull Request comments. A reviewer is more likely to participate if the bulk of a review has already been completed.
2. Consider opening a topic on the Klipper Discourse server to discuss this work. The Discourse server is a good place to discuss development ideas and to engage users interested in testing. Reviewers are more likely to prioritize Pull Requests with an active community of users.
3. Consider helping out reviewers by reviewing other Klipper Pull Requests. Taking the time to perform a careful and detailed review of others work is appreciated. Regular contributors are more likely to prioritize the contributions of other regular contributors.

Unfortunately, if a reviewer does not assign themselves to this GitHub Pull Request then it will be automatically closed. If this happens, then it is a good idea to move further discussion to the Klipper Discourse server. Reviewers can reach out on that forum to let you know if they are interested and when they are available.

Best regards,
~ Your friendly GitIssueBot

PS: I'm just an automated script, not a human being.