From e8745583810f183053a744fcf697f8cef9388989 Mon Sep 17 00:00:00 2001 From: "Jack Chen (chendo)" Date: Sat, 10 Oct 2020 16:59:29 +1100 Subject: [PATCH 1/3] Add M576 which allows reporting of queue statistics, specifically planner/command buffer space remaining, as well as command buffer underruns, and time the command buffer remained empty since last M576 output --- Marlin/Configuration_adv.h | 9 +++++ Marlin/src/MarlinCore.cpp | 4 +++ Marlin/src/gcode/gcode.cpp | 4 +++ Marlin/src/gcode/gcode.h | 2 ++ Marlin/src/gcode/queue.cpp | 59 ++++++++++++++++++++++++++++++++- Marlin/src/gcode/queue.h | 29 ++++++++++++++++ Marlin/src/gcode/stats/M576.cpp | 43 ++++++++++++++++++++++++ 7 files changed, 149 insertions(+), 1 deletion(-) create mode 100644 Marlin/src/gcode/stats/M576.cpp diff --git a/Marlin/Configuration_adv.h b/Marlin/Configuration_adv.h index 59a1813610..2a49ff3800 100644 --- a/Marlin/Configuration_adv.h +++ b/Marlin/Configuration_adv.h @@ -1958,6 +1958,15 @@ // Some clients will have this feature soon. This could make the NO_TIMEOUTS unnecessary. //#define ADVANCED_OK +/** + * Buffer monitoring + * + * To help diagnose print quality issues stemming from command buffers being empty, + * we add M576 which enables reporting of buffer empty + */ + +#define BUFFER_MONITORING + // Printrun may have trouble receiving long strings all at once. // This option inserts short delays between lines of serial output. #define SERIAL_OVERRUN_PROTECTION diff --git a/Marlin/src/MarlinCore.cpp b/Marlin/src/MarlinCore.cpp index 672858d05a..e9056fe98e 100644 --- a/Marlin/src/MarlinCore.cpp +++ b/Marlin/src/MarlinCore.cpp @@ -761,6 +761,10 @@ void idle(TERN_(ADVANCED_PAUSE_FEATURE, bool no_stepper_sleep/*=false*/)) { if (!gcode.autoreport_paused) { TERN_(AUTO_REPORT_TEMPERATURES, thermalManager.auto_report_temperatures()); TERN_(AUTO_REPORT_SD_STATUS, card.auto_report_sd_status()); + + #if ENABLED(BUFFER_MONITORING) + queue.auto_report_buffer_statistics(); + #endif } #endif diff --git a/Marlin/src/gcode/gcode.cpp b/Marlin/src/gcode/gcode.cpp index cbf62e0fcf..24f20dd06b 100644 --- a/Marlin/src/gcode/gcode.cpp +++ b/Marlin/src/gcode/gcode.cpp @@ -770,6 +770,10 @@ void GcodeSuite::process_parsed_command(const bool no_ok/*=false*/) { case 575: M575(); break; // M575: Set serial baudrate #endif + #if ENABLED(BUFFER_MONITORING) // M576: Buffer monitoring + case 576: M576(); break; + #endif + #if ENABLED(ADVANCED_PAUSE_FEATURE) case 600: M600(); break; // M600: Pause for Filament Change case 603: M603(); break; // M603: Configure Filament Change diff --git a/Marlin/src/gcode/gcode.h b/Marlin/src/gcode/gcode.h index 73a3727813..881d19c1b8 100644 --- a/Marlin/src/gcode/gcode.h +++ b/Marlin/src/gcode/gcode.h @@ -779,6 +779,8 @@ private: TERN_(BAUD_RATE_GCODE, static void M575()); + TERN_(BUFFER_MONITORING, static void M576()); + #if ENABLED(ADVANCED_PAUSE_FEATURE) static void M600(); static void M603(); diff --git a/Marlin/src/gcode/queue.cpp b/Marlin/src/gcode/queue.cpp index b9169d90e1..e8f408a1ea 100644 --- a/Marlin/src/gcode/queue.cpp +++ b/Marlin/src/gcode/queue.cpp @@ -85,6 +85,20 @@ static int serial_count[NUM_SERIAL] = { 0 }; bool send_ok[BUFSIZE]; +/* + * Track buffer underruns + */ +#if ENABLED(BUFFER_MONITORING) + uint32_t GCodeQueue::command_buffer_underruns = 0; + bool GCodeQueue::command_buffer_empty = false; + + millis_t GCodeQueue::max_command_buffer_empty_duration = 0; + millis_t GCodeQueue::command_buffer_empty_at = 0; + + uint8_t GCodeQueue::auto_buffer_report_interval; + millis_t GCodeQueue::next_buffer_report_ms; +#endif + /** * Next Injected PROGMEM Command pointer. (nullptr == empty) * Internal commands are enqueued ahead of serial / SD commands. @@ -613,7 +627,26 @@ void GCodeQueue::advance() { if (process_injected_command_P() || process_injected_command()) return; // Return if the G-code buffer is empty - if (!length) return; + if (!length) { + #if ENABLED(BUFFER_MONITORING) + if (!command_buffer_empty) { + command_buffer_empty = true; + command_buffer_underruns++; + command_buffer_empty_at = millis(); + } + #endif + return; + } + + #if ENABLED(BUFFER_MONITORING) + static millis_t command_buffer_empty_duration; + command_buffer_empty_duration = millis() - command_buffer_empty_at; + if (command_buffer_empty_duration > max_command_buffer_empty_duration) { + max_command_buffer_empty_duration = command_buffer_empty_duration; + } + command_buffer_empty = false; + #endif + #if ENABLED(SDSUPPORT) @@ -658,3 +691,27 @@ void GCodeQueue::advance() { if (++index_r >= BUFSIZE) index_r = 0; } + +#if ENABLED(BUFFER_MONITORING) +void GCodeQueue::report_buffer_statistics() { + SERIAL_ECHO("M576"); + SERIAL_ECHOLNPAIR(SP_P_STR, int(planner.moves_free()), + SP_B_STR, int(BUFSIZE - length), + " BU", queue.command_buffer_underruns, + " BD", queue.max_command_buffer_empty_duration, + ); + + command_buffer_underruns = 0; + max_command_buffer_empty_duration = 0; +} + +void GCodeQueue::auto_report_buffer_statistics() { + if (queue.auto_buffer_report_interval && ELAPSED(millis(), queue.next_buffer_report_ms)) { + queue.next_buffer_report_ms = millis() + 1000UL * queue.auto_buffer_report_interval; + PORT_REDIRECT(SERIAL_BOTH); + report_buffer_statistics(); + PORT_RESTORE(); + } +} + +#endif \ No newline at end of file diff --git a/Marlin/src/gcode/queue.h b/Marlin/src/gcode/queue.h index 966af2871f..aa7bc92c5e 100644 --- a/Marlin/src/gcode/queue.h +++ b/Marlin/src/gcode/queue.h @@ -147,6 +147,35 @@ public: */ static void flush_and_request_resend(); + #if ENABLED(BUFFER_MONITORING) + /* + * Track buffer underruns + */ + static uint32_t command_buffer_underruns; + static bool command_buffer_empty; + static millis_t max_command_buffer_empty_duration; + static millis_t command_buffer_empty_at; + + /** + * Report buffer statistics to the host to be able to detect buffer underruns + * + * Returns "M576 " followed by: + * P Planner space remaining + * B Command buffer space remaining + * U Number of command buffer underruns since last report + */ + static void report_buffer_statistics(); + + static uint8_t auto_buffer_report_interval; + static millis_t next_buffer_report_ms; + static void auto_report_buffer_statistics(); + static inline void set_auto_report_interval(uint8_t v) { + NOMORE(v, 60); + auto_buffer_report_interval = v; + next_buffer_report_ms = millis() + 1000UL * v; + } + #endif + private: static uint8_t index_w; // Ring buffer write position diff --git a/Marlin/src/gcode/stats/M576.cpp b/Marlin/src/gcode/stats/M576.cpp new file mode 100644 index 0000000000..ba7f89b3fc --- /dev/null +++ b/Marlin/src/gcode/stats/M576.cpp @@ -0,0 +1,43 @@ +/** + * Marlin 3D Printer Firmware + * Copyright (c) 2020 MarlinFirmware [https://github.com/MarlinFirmware/Marlin] + * + * + * Based on Sprinter and grbl. + * Copyright (c) 2011 Camiel Gubbels / Erik van der Zalm + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see . + * + */ + +#include "../../inc/MarlinConfig.h" +#include "../../MarlinCore.h" // for SP_P/B_STR, etc. + +#if ENABLED(BUFFER_MONITORING) + +#include "../gcode.h" +#include "../queue.h" + +/** + * M576: Return buffer stats, and optionally set auto-report interval. M576 [S] + */ +void GcodeSuite::M576() { + if (parser.seenval('S')) { + queue.set_auto_report_interval((uint8_t)parser.value_byte()); + } + + queue.report_buffer_statistics(); +} + +#endif // BUFFER_MONITORING From f560ab9ab748d8ef6193f1760fa8a05067c94301 Mon Sep 17 00:00:00 2001 From: "Jack Chen (chendo)" Date: Sat, 10 Oct 2020 19:22:19 +1100 Subject: [PATCH 2/3] Try to monitor planner buffer underruns in the auto_report_buffer_statistics loop as modifying the stepper ISR loop seems like a bad idea --- Marlin/src/gcode/queue.cpp | 43 ++++++++++++++++++++++++++++----- Marlin/src/gcode/queue.h | 14 ++++++++--- Marlin/src/gcode/stats/M576.cpp | 13 +++++++++- 3 files changed, 60 insertions(+), 10 deletions(-) diff --git a/Marlin/src/gcode/queue.cpp b/Marlin/src/gcode/queue.cpp index e8f408a1ea..eabae9363a 100644 --- a/Marlin/src/gcode/queue.cpp +++ b/Marlin/src/gcode/queue.cpp @@ -91,10 +91,14 @@ bool send_ok[BUFSIZE]; #if ENABLED(BUFFER_MONITORING) uint32_t GCodeQueue::command_buffer_underruns = 0; bool GCodeQueue::command_buffer_empty = false; - millis_t GCodeQueue::max_command_buffer_empty_duration = 0; millis_t GCodeQueue::command_buffer_empty_at = 0; + uint32_t GCodeQueue::planner_buffer_underruns = 0; + bool GCodeQueue::planner_buffer_empty = false; + millis_t GCodeQueue::max_planner_buffer_empty_duration = 0; + millis_t GCodeQueue::planner_buffer_empty_at = 0; + uint8_t GCodeQueue::auto_buffer_report_interval; millis_t GCodeQueue::next_buffer_report_ms; #endif @@ -639,12 +643,14 @@ void GCodeQueue::advance() { } #if ENABLED(BUFFER_MONITORING) - static millis_t command_buffer_empty_duration; - command_buffer_empty_duration = millis() - command_buffer_empty_at; - if (command_buffer_empty_duration > max_command_buffer_empty_duration) { - max_command_buffer_empty_duration = command_buffer_empty_duration; + if (command_buffer_empty) { + static millis_t command_buffer_empty_duration; + command_buffer_empty_duration = millis() - command_buffer_empty_at; + if (command_buffer_empty_duration > max_command_buffer_empty_duration) { + max_command_buffer_empty_duration = command_buffer_empty_duration; + } + command_buffer_empty = false; } - command_buffer_empty = false; #endif @@ -697,15 +703,40 @@ void GCodeQueue::report_buffer_statistics() { SERIAL_ECHO("M576"); SERIAL_ECHOLNPAIR(SP_P_STR, int(planner.moves_free()), SP_B_STR, int(BUFSIZE - length), + " PU", queue.planner_buffer_underruns, + " PD", queue.max_planner_buffer_empty_duration, " BU", queue.command_buffer_underruns, " BD", queue.max_command_buffer_empty_duration, ); command_buffer_underruns = 0; max_command_buffer_empty_duration = 0; + + planner_buffer_underruns = 0; + max_planner_buffer_empty_duration = 0; } void GCodeQueue::auto_report_buffer_statistics() { + // Bit of a hack to try to catch planner buffer underruns without having logic + // running inside Stepper::block_phase_isr + if (planner.movesplanned() == 0) { + if (!planner_buffer_empty) { // if the planner buffer wasn't empty, but now it is + planner_buffer_empty = true; + planner_buffer_underruns++; + planner_buffer_empty_at = millis(); + } + } else if (planner_buffer_empty) { // if the planner buffer was empty, but now it ain't + static millis_t planner_buffer_empty_duration; + planner_buffer_empty_duration = millis() - planner_buffer_empty_at; + + // if it's longer than the currently tracked max duration, replace it + if (planner_buffer_empty_duration > max_planner_buffer_empty_duration) { + max_planner_buffer_empty_duration = planner_buffer_empty_duration; + } + + planner_buffer_empty = false; + } + if (queue.auto_buffer_report_interval && ELAPSED(millis(), queue.next_buffer_report_ms)) { queue.next_buffer_report_ms = millis() + 1000UL * queue.auto_buffer_report_interval; PORT_REDIRECT(SERIAL_BOTH); diff --git a/Marlin/src/gcode/queue.h b/Marlin/src/gcode/queue.h index aa7bc92c5e..a579ea7ef9 100644 --- a/Marlin/src/gcode/queue.h +++ b/Marlin/src/gcode/queue.h @@ -156,13 +156,21 @@ public: static millis_t max_command_buffer_empty_duration; static millis_t command_buffer_empty_at; + static uint32_t planner_buffer_underruns; + static bool planner_buffer_empty; + static millis_t max_planner_buffer_empty_duration; + static millis_t planner_buffer_empty_at; + /** * Report buffer statistics to the host to be able to detect buffer underruns * * Returns "M576 " followed by: - * P Planner space remaining - * B Command buffer space remaining - * U Number of command buffer underruns since last report + * P Planner space remaining + * B Command buffer space remaining + * PU Number of planner buffer underruns since last report + * PD Max time in ms the planner buffer was empty since last report + * BU Number of command buffer underruns since last report + * BD Max time in ms the command buffer was empty since last report */ static void report_buffer_statistics(); diff --git a/Marlin/src/gcode/stats/M576.cpp b/Marlin/src/gcode/stats/M576.cpp index ba7f89b3fc..dfa9a1cad0 100644 --- a/Marlin/src/gcode/stats/M576.cpp +++ b/Marlin/src/gcode/stats/M576.cpp @@ -30,7 +30,18 @@ #include "../queue.h" /** - * M576: Return buffer stats, and optionally set auto-report interval. M576 [S] + * M576: Return buffer stats, and optionally set auto-report interval. + * Usage: M576 [S] + * + * When called, printer emits the following output: + * "M576 P B PU PD BU BD" + * Where: + * P: Planner buffers available + * B: Command buffers available + * PU: Planner buffer underruns since last report + * PD: Maximum time in ms planner buffer was empty since last report + * BU: Command buffer underruns since last report + * BD: Maximum time in ms command buffer was empty since last report */ void GcodeSuite::M576() { if (parser.seenval('S')) { From 3655c9f40af92e8a396181806a90796d68734ead Mon Sep 17 00:00:00 2001 From: "Jack Chen (chendo)" Date: Sat, 10 Oct 2020 21:26:45 +1100 Subject: [PATCH 3/3] Disable BUFFER_MONITORING by default --- Marlin/Configuration_adv.h | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/Marlin/Configuration_adv.h b/Marlin/Configuration_adv.h index 2a49ff3800..a7b85a585b 100644 --- a/Marlin/Configuration_adv.h +++ b/Marlin/Configuration_adv.h @@ -1964,8 +1964,7 @@ * To help diagnose print quality issues stemming from command buffers being empty, * we add M576 which enables reporting of buffer empty */ - -#define BUFFER_MONITORING +//#define BUFFER_MONITORING // Printrun may have trouble receiving long strings all at once. // This option inserts short delays between lines of serial output.