klippy.log does not contain timestamps. They would be useful to troubleshoot problems.
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
2 Likes
Hi anda,
when I started with Klipper, I had the same idea/question 
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.
2 Likes
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!
1 Like
This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.