Closed AnHardt closed 6 years ago
Add debug counters to find out what Marlin is doing all the time. With example code for counters in most of the subsystems.
Example for a Pi3 clone homing and levelling 14:13:34.219 : echo:jitter: 0, idle(): 11110.00, loop(): 11110.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:999.00, lines parsed:1.00, moves planed:0.00 14:13:35.219 : echo:jitter: 0, idle(): 11134.00, loop(): 11134.00, watchdog reset: 5.00, tempISR: 977.00, stepISR:1000.00, lines parsed:0.00, moves planed:0.00 14:13:36.218 : echo:jitter: 0, idle(): 11123.00, loop(): 11123.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:999.00, lines parsed:0.00, moves planed:0.00 14:13:36.938 : N19 M105*31 14:13:36.956 : ok T:20.0 /0.0 B:19.3 /0.0 @:0 B@:0 14:13:37.121 : N20 G28*33 14:13:37.221 : echo:jitter: 0, idle(): 10731.00, loop(): 10092.00, watchdog reset: 5.00, tempISR: 978.00, stepISR:1546.00, lines parsed:2.00, moves planed:2.00 14:13:38.216 : echo:jitter: 0, idle(): 7547.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 974.00, stepISR:7145.00, lines parsed:0.00, moves planed:1.00 14:13:39.220 : echo:jitter: 0, idle(): 9335.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6126.00, lines parsed:0.00, moves planed:3.00 14:13:40.219 : echo:jitter: 0, idle(): 9577.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 977.00, stepISR:4110.00, lines parsed:0.00, moves planed:4.00 14:13:41.219 : echo:jitter: 0, idle(): 7202.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6635.00, lines parsed:0.00, moves planed:2.00 14:13:42.218 : echo:jitter: 0, idle(): 6954.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6965.00, lines parsed:0.00, moves planed:0.00 14:13:43.218 : echo:jitter: 0, idle(): 6944.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6958.00, lines parsed:0.00, moves planed:0.00 14:13:44.491 : echo:jitter: 272, idle(): 5288.52, loop(): 0.00, watchdog reset: 3.93, tempISR: 977.20, stepISR:5552.67, lines parsed:0.00, moves planed:1.57 // servo delay!!! 14:13:45.491 : echo:jitter: 0, idle(): 6699.00, loop(): 0.00, watchdog reset: 6.00, tempISR: 974.00, stepISR:6954.00, lines parsed:0.00, moves planed:0.00 14:13:46.490 : echo:jitter: 0, idle(): 6723.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6966.00, lines parsed:0.00, moves planed:0.00 14:13:47.489 : echo:jitter: 0, idle(): 6711.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6957.00, lines parsed:0.00, moves planed:0.00 14:13:48.489 : echo:jitter: 0, idle(): 6723.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6965.00, lines parsed:0.00, moves planed:0.00 14:13:49.488 : echo:jitter: 0, idle(): 6713.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6958.00, lines parsed:0.00, moves planed:0.00 14:13:50.488 : echo:jitter: 0, idle(): 6722.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6965.00, lines parsed:0.00, moves planed:0.00 14:13:51.487 : echo:jitter: 0, idle(): 6712.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6957.00, lines parsed:0.00, moves planed:0.00 14:13:52.487 : echo:jitter: 0, idle(): 6714.00, loop(): 0.00, watchdog reset: 6.00, tempISR: 976.00, stepISR:6966.00, lines parsed:0.00, moves planed:0.00 14:13:53.486 : echo:jitter: 0, idle(): 7887.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6022.00, lines parsed:0.00, moves planed:2.00 14:13:54.485 : echo:jitter: 0, idle(): 10457.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 977.00, stepISR:4013.00, lines parsed:0.00, moves planed:2.00 14:13:55.485 : echo:jitter: 0, idle(): 6951.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6965.00, lines parsed:0.00, moves planed:0.00 14:13:56.484 : echo:jitter: 0, idle(): 6947.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6959.00, lines parsed:0.00, moves planed:0.00 14:13:57.484 : echo:jitter: 0, idle(): 6952.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6965.00, lines parsed:0.00, moves planed:0.00 14:13:58.765 : X:100.00 Y:50.00 Z:15.00 E:0.00 Count X: 9412 Y:4706 Z:60000 14:13:58.765 : ok N20 P15 B3 14:13:58.765 : N21 M105*20 14:13:58.770 : echo:jitter: 285, idle(): 5312.84, loop(): 0.00, watchdog reset: 3.89, tempISR: 977.43, stepISR:5547.86, lines parsed:0.00, moves planed:0.78 // sevo delay!!! 14:13:58.784 : ok T:20.2 /0.0 B:19.5 /0.0 @:0 B@:0 14:13:59.769 : echo:jitter: 0, idle(): 11080.00, loop(): 11080.00, watchdog reset: 6.00, tempISR: 974.00, stepISR:997.00, lines parsed:1.00, moves planed:0.00 14:14:00.768 : echo:jitter: 0, idle(): 11131.00, loop(): 11131.00, watchdog reset: 5.00, tempISR: 977.00, stepISR:999.00, lines parsed:0.00, moves planed:0.00 14:14:01.398 : N22 M105*23 ... 14:14:07.533 : ok T:20.2 /0.0 B:19.5 /0.0 @:0 B@:0 14:14:07.764 : echo:jitter: 0, idle(): 11119.00, loop(): 11119.00, watchdog reset: 5.00, tempISR: 977.00, stepISR:999.00, lines parsed:1.00, moves planed:0.00 14:14:08.763 : echo:jitter: 0, idle(): 11121.00, loop(): 11121.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:998.00, lines parsed:0.00, moves planed:0.00 14:14:09.763 : echo:jitter: 0, idle(): 11133.00, loop(): 11133.00, watchdog reset: 5.00, tempISR: 977.00, stepISR:999.00, lines parsed:0.00, moves planed:0.00 14:14:09.769 : N25 G29*37 14:14:09.774 : G29 Auto Bed Leveling 14:14:10.765 : echo:jitter: 0, idle(): 5409.00, loop(): 89.00, watchdog reset: 6.00, tempISR: 976.00, stepISR:4083.00, lines parsed:1.00, moves planed:2.00 14:14:11.765 : echo:jitter: 0, idle(): 6825.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6806.00, lines parsed:0.00, moves planed:2.00 14:14:12.764 : echo:jitter: 1, idle(): 6693.31, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.02, stepISR:6961.04, lines parsed:0.00, moves planed:0.00 14:14:13.764 : echo:jitter: 0, idle(): 6700.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6961.00, lines parsed:0.00, moves planed:0.00 14:14:14.763 : echo:jitter: 0, idle(): 6701.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6964.00, lines parsed:0.00, moves planed:0.00 14:14:15.763 : echo:jitter: 0, idle(): 7289.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6933.00, lines parsed:0.00, moves planed:4.00 14:14:16.762 : echo:jitter: 0, idle(): 7239.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6675.00, lines parsed:0.00, moves planed:1.00 14:14:17.762 : echo:jitter: 0, idle(): 7039.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6707.00, lines parsed:0.00, moves planed:2.00 14:14:18.765 : echo:jitter: 0, idle(): 7242.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6939.00, lines parsed:0.00, moves planed:4.00 14:14:19.760 : echo:jitter: 0, idle(): 6929.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6958.00, lines parsed:0.00, moves planed:0.00 14:14:20.764 : echo:jitter: 0, idle(): 7435.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6420.00, lines parsed:0.00, moves planed:3.00 14:14:21.759 : echo:jitter: 0, idle(): 6973.00, loop(): 0.00, watchdog reset: 6.00, tempISR: 976.00, stepISR:6948.00, lines parsed:0.00, moves planed:2.00 14:14:22.762 : echo:jitter: 0, idle(): 7017.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6952.00, lines parsed:0.00, moves planed:2.00 14:14:23.762 : echo:jitter: 0, idle(): 7328.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6549.00, lines parsed:0.00, moves planed:3.00 14:14:24.760 : echo:jitter: 0, idle(): 6692.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6957.00, lines parsed:0.00, moves planed:0.00 14:14:25.760 : echo:jitter: 0, idle(): 7356.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6934.00, lines parsed:0.00, moves planed:4.00 14:14:26.759 : echo:jitter: 0, idle(): 7380.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6484.00, lines parsed:0.00, moves planed:1.00 14:14:27.759 : echo:jitter: 0, idle(): 6934.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6770.00, lines parsed:0.00, moves planed:2.00 14:14:28.758 : echo:jitter: 0, idle(): 7241.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6933.00, lines parsed:0.00, moves planed:4.00 14:14:29.758 : echo:jitter: 0, idle(): 7013.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6871.00, lines parsed:0.00, moves planed:1.00 14:14:30.758 : echo:jitter: 0, idle(): 7262.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6518.00, lines parsed:0.00, moves planed:2.00 14:14:31.757 : echo:jitter: 0, idle(): 7123.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6932.00, lines parsed:0.00, moves planed:4.00 14:14:32.760 : echo:jitter: 0, idle(): 6911.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6990.00, lines parsed:0.00, moves planed:0.00 14:14:33.756 : echo:jitter: 0, idle(): 7292.00, loop(): 0.00, watchdog reset: 6.00, tempISR: 975.00, stepISR:6547.00, lines parsed:0.00, moves planed:3.00 14:14:34.755 : echo:jitter: 0, idle(): 6806.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6948.00, lines parsed:0.00, moves planed:2.00 14:14:35.758 : echo:jitter: 0, idle(): 7164.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6952.00, lines parsed:0.00, moves planed:2.00 14:14:36.754 : echo:jitter: 0, idle(): 7418.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6515.00, lines parsed:0.00, moves planed:1.00 14:14:37.757 : echo:jitter: 0, idle(): 6809.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6874.00, lines parsed:0.00, moves planed:2.00 14:14:38.757 : echo:jitter: 0, idle(): 7236.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6933.00, lines parsed:0.00, moves planed:4.00 14:14:39.755 : echo:jitter: 0, idle(): 7165.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6741.00, lines parsed:0.00, moves planed:1.00 14:14:40.755 : echo:jitter: 0, idle(): 7129.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6644.00, lines parsed:0.00, moves planed:2.00 14:14:41.754 : echo:jitter: 0, idle(): 7255.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6940.00, lines parsed:0.00, moves planed:4.00 14:14:42.753 : echo:jitter: 0, idle(): 6925.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 975.00, stepISR:6958.00, lines parsed:0.00, moves planed:0.00 14:14:43.754 : echo:jitter: 0, idle(): 6919.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6953.00, lines parsed:0.00, moves planed:2.00 14:14:44.752 : echo:jitter: 0, idle(): 6917.00, loop(): 0.00, watchdog reset: 6.00, tempISR: 975.00, stepISR:6958.00, lines parsed:0.00, moves planed:0.00 14:14:45.752 : echo:jitter: 0, idle(): 6936.00, loop(): 0.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:6953.00, lines parsed:0.00, moves planed:0.00 14:14:46.063 : Eqn coefficients: a: -0.00019630 b: -0.00001147 d: 0.61903419 14:14:46.063 : Bed Level Correction Matrix: 14:14:46.067 : +1.000000 +0.000000 -0.000196 14:14:46.067 : -0.000000 +1.000000 -0.000011 14:14:46.067 : +0.000196 +0.000011 +1.000000 14:14:46.071 : X:189.99 Y:139.00 Z:15.04 E:0.00 Count X: 17882 Y:13082 Z:59998 14:14:46.071 : ok N25 P15 B3 14:14:46.071 : N26 M105*19 14:14:46.086 : ok T:20.3 /0.0 B:19.6 /0.0 @:0 B@:0 14:14:46.751 : echo:jitter: 0, idle(): 7421.00, loop(): 7420.00, watchdog reset: 5.00, tempISR: 977.00, stepISR:1000.00, lines parsed:1.00, moves planed:1.00 14:14:47.265 : N27 M105*18 14:14:47.282 : ok T:20.1 /0.0 B:19.5 /0.0 @:0 B@:0 14:14:47.751 : echo:jitter: 0, idle(): 11106.00, loop(): 11106.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:999.00, lines parsed:1.00, moves planed:0.00 14:14:48.750 : echo:jitter: 0, idle(): 11132.00, loop(): 11132.00, watchdog reset: 5.00, tempISR: 977.00, stepISR:1000.00, lines parsed:0.00, moves planed:0.00 14:14:49.750 : echo:jitter: 0, idle(): 11121.00, loop(): 11121.00, watchdog reset: 5.00, tempISR: 976.00, stepISR:998.00, lines parsed:0.00, moves planed:0.00 jitter -> difference from the ideal measurement interval. If different from 0, idle() was not called for at least that long. idle() -> number of idle() calls in that interval. loop() -> number of loop() calls in that interval. watchdog reset -> number of watchdog timer resets in that interval. Ideally 5. One up or down does not matter. Critical if in average below 0.25. (If interval is 1 second.) tempISR -> around 1000 is normal. stepISR -> around 1000 when nothing to do. lines parsed -> number of process_next_command() calls in that interval. moves planed -> number of buffer_line() calls in that interval.
Add debug counters to find out what Marlin is doing all the time. With example code for counters in most of the subsystems.