Add option to print timestamps in klippy.log

klippy.log does not contain timestamps. They would be useful to troubleshoot problems.

Hello @anda !

It does. It’s coded.

You can see it with

https://sineos.github.io/

Well, this gives metrics over time, but we cannot tell at which time a specific error or debug message was printed in the log.

For example, I am trying to understand why my mainboard takes so long to respond after a restart. I get a series of ‘mcu ‘mcu’: Unable to open serial port’ messages in the log, but no way of saying the elapsed time between each and overall.

Klipper is offering tons of timing information to exactly diagnose such topics but unfortunately they all require in-depth understanding of the code and hardware specification to interpret:

Stats 1114061.8: gcodein=0  mcu: mcu_awake=0.006 mcu_task_avg=0.000010 mcu_task_stddev=0.000012 bytes_write=13097 bytes_read=19565 bytes_retransmit=9 bytes_invalid=0 send_seq=617 receive_seq=617 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=119994214 rpi: mcu_awake=0.000 mcu_task_avg=0.000007 mcu_task_stddev=0.000011 bytes_write=1320 bytes_read=6122 bytes_retransmit=0 bytes_invalid=0 send_seq=191 receive_seq=191 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999835 adj=50002281 heater_bed: target=0 temp=22.5 pwm=0.000  raspberry_pi: temp=49.7 sysload=0.06 cputime=7.250 memavail=649664 print_time=582316.574 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.1 pwm=0.000

Timing relevant information:

Stats 1114061.8: 
send_seq=617 
receive_seq=617 
retransmit_seq=2 
srtt=0.000 
rttvar=0.000 
rto=0.025 
freq=119994214  
send_seq=191 
receive_seq=191 
retransmit_seq=0 
srtt=0.000 
rttvar=0.000 
rto=0.025 
freq=49999835 adj=50002281 
print_time=582316.574 
buffer_time=0.000 

Knowing the exact meaning is only relevant in rare cases and if you have such a deep understanding performing a diagnosis upon them then you likely also have the understanding interpreting the entire Klipper code base.

IMO there is no single: “Oh, this timestamp took 3ms longer so definitively my printer is invested with electron eating ants from Alpha Centauri”

2 Likes

again, that is not useful for troubleshooting error messages that are time sensitive. I am a software engineer, so I can understand the code quite well. It would simply need a basic format better than what it is right now…

For example:

Extruder max_extrude_ratio=0.266081
mcu 'mcu': Starting serial connect
mcu 'mcu': Unable to open serial port: [Errno 2] could not open port /dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00: [Errno 2] No such file or directory: '/dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00'
webhooks client 3040718360: New connection
webhooks client 3040718360: Client info {'program': 'Moonraker', 'version': 'v0.8.0-247-g3008a13'}
mcu 'mcu': Unable to open serial port: [Errno 16] could not open port /dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00: [Errno 16] Device or resource busy: '/dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00'
mcu 'mcu': Unable to open serial port: [Errno 16] could not open port /dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00: [Errno 16] Device or resource busy: '/dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00'
mcu 'mcu': Unable to open serial port: [Errno 16] could not open port /dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00: [Errno 16] Device or resource busy: '/dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00'
mcu 'mcu': Unable to open serial port: [Errno 16] could not open port /dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00: [Errno 16] Device or resource busy: '/dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00'
mcu 'mcu': Unable to open serial port: [Errno 16] could not open port /dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00: [Errno 16] Device or resource busy: '/dev/serial/by-id/usb-Klipper_stm32f446xx_2F0035001850534E4E313420-if00'

won’t give me timings between connection attempts

Example of output with a formatter in queuelogger.py:

2024-01-15 09:29:22,500 - INFO - Starting heater checks for heater_bed
2024-01-15 09:29:22,501 - INFO - Starting heater checks for chamber_heater
2024-01-15 09:29:22,536 - INFO - Starting heater checks for extruder
2024-01-15 09:29:23,188 - INFO - webhooks: registering remote method 'shutdown_machine' for connection id: 3038278896
2024-01-15 09:29:23,191 - INFO - webhooks: registering remote method 'reboot_machine' for connection id: 3038278896
2024-01-15 09:29:23,194 - INFO - webhooks: registering remote method 'pause_job_queue' for connection id: 3038278896
2024-01-15 09:29:23,198 - INFO - webhooks: registering remote method 'start_job_queue' for connection id: 3038278896
2024-01-15 09:29:23,201 - INFO - webhooks: registering remote method 'set_device_power' for connection id: 3038278896
1 Like

Hi anda,

when I started with Klipper, I had the same idea/question :wink:
I can’t find the very short discussion, that we had here about “timestamps” in this forum, but I remember even Kevin was involved. Very long time ago!

It took a while for me to halfway understand the Klipper timestamping.

Did you read?
https://www.klipper3d.org/Code_Overview.html?h=time#time

I’m no programmer at all (I just use SW), but try hard to understand code. Sometimes I’m able to change source code a bit, compile it, and it works the way I wanted.

I like Sineos’ https://sineos.github.io/ very much. I think that could be improved a lot.
You may find the sources here GitHub - Sineos/sineos.github.io
Sineos invites you to improve that little web-page (Feedback or improvements are always welcome.)!

…or take Debugging - Klipper documentation and change logextract.py for chronological timestamps.

I’m dreaming about synchronized (translated timestamps from Code overview - Klipper documentation to realtime (realtime= Start printer till shut down in hhmmss)!

I keep my fingers crossed for better timestamps and wish you success!

Kind regards, hcet14

Everyone keeps pointing the timestamps for printer commands, I am talking about klipper debug and error messages that are not stamped in the logs.

1 Like

I’m totally with you!
“klippy.log” needs that!

You might open a pull request!
I don’t know if there might be some obstacles to open a pull request, I never started a pull request.
I will support your pull request, if you file one!