D576 Buffer Monitoring (#19674)

This commit is contained in:
chendo 2021-07-23 13:53:00 +10:00 committed by Scott Lahteine
parent 416234f43a
commit 51d954a4fd
7 changed files with 366 additions and 213 deletions

View file

@ -4177,6 +4177,14 @@
// Enable Marlin dev mode which adds some special commands
//#define MARLIN_DEV_MODE
#if ENABLED(MARLIN_DEV_MODE)
/**
* D576 - Buffer Monitoring
* To help diagnose print quality issues stemming from empty command buffers.
*/
//#define BUFFER_MONITORING
#endif
/**
* Postmortem Debugging captures misbehavior and outputs the CPU status and backtrace to serial.
* When running in the debugger it will break for debugging. This is useful to help understand

View file

@ -868,6 +868,7 @@ void idle(bool no_stepper_sleep/*=false*/) {
TERN_(AUTO_REPORT_TEMPERATURES, thermalManager.auto_reporter.tick());
TERN_(AUTO_REPORT_SD_STATUS, card.auto_reporter.tick());
TERN_(AUTO_REPORT_POSITION, position_auto_reporter.tick());
TERN_(BUFFER_MONITORING, queue.auto_report_buffer_statistics());
}
#endif

View file

@ -242,6 +242,7 @@
* M553 - Get or set IP netmask. (Requires enabled Ethernet port)
* M554 - Get or set IP gateway. (Requires enabled Ethernet port)
* M569 - Enable stealthChop on an axis. (Requires at least one _DRIVER_TYPE to be TMC2130/2160/2208/2209/5130/5160)
* M575 - Change the serial baud rate. (Requires BAUD_RATE_GCODE)
* M600 - Pause for filament change: "M600 X<pos> Y<pos> Z<raise> E<first_retract> L<later_retract>". (Requires ADVANCED_PAUSE_FEATURE)
* M603 - Configure filament change: "M603 T<tool> U<unload_length> L<load_length>". (Requires ADVANCED_PAUSE_FEATURE)
* M605 - Set Dual X-Carriage movement mode: "M605 S<mode> [X<x_offset>] [R<temp_offset>]". (Requires DUAL_X_CARRIAGE)
@ -298,6 +299,7 @@
* M997 - Perform in-application firmware update
* M999 - Restart after being stopped by error
* D... - Custom Development G-code. Add hooks to 'gcode_D.cpp' for developers to test features. (Requires MARLIN_DEV_MODE)
* D576 - Set buffer monitoring options. (Requires BUFFER_MONITORING)
*
* "T" Codes
*

View file

@ -23,248 +23,279 @@
#if ENABLED(MARLIN_DEV_MODE)
#include "gcode.h"
#include "../module/settings.h"
#include "../module/temperature.h"
#include "../libs/hex_print.h"
#include "../HAL/shared/eeprom_if.h"
#include "../HAL/shared/Delay.h"
#include "../sd/cardreader.h"
#include "../MarlinCore.h" // for kill
#include "gcode.h"
extern void dump_delay_accuracy_check();
#if ENABLED(BUFFER_MONITORING)
#include "queue.h"
#endif
/**
* Dn: G-code for development and testing
*
* See https://reprap.org/wiki/G-code#D:_Debug_codes
*
* Put whatever else you need here to test ongoing development.
*/
void GcodeSuite::D(const int16_t dcode) {
switch (dcode) {
#include "../module/settings.h"
#include "../module/temperature.h"
#include "../libs/hex_print.h"
#include "../HAL/shared/eeprom_if.h"
#include "../HAL/shared/Delay.h"
#include "../sd/cardreader.h"
#include "../MarlinCore.h" // for kill
case -1:
for (;;) { /* loop forever (watchdog reset) */ }
extern void dump_delay_accuracy_check();
case 0:
HAL_reboot();
break;
/**
* Dn: G-code for development and testing
*
* See https://reprap.org/wiki/G-code#D:_Debug_codes
*
* Put whatever else you need here to test ongoing development.
*/
void GcodeSuite::D(const int16_t dcode) {
switch (dcode) {
case 10:
kill(PSTR("D10"), PSTR("KILL TEST"), parser.seen_test('P'));
break;
case -1:
for (;;) { /* loop forever (watchdog reset) */ }
case 1: {
// Zero or pattern-fill the EEPROM data
#if ENABLED(EEPROM_SETTINGS)
persistentStore.access_start();
size_t total = persistentStore.capacity();
int pos = 0;
const uint8_t value = 0x0;
while (total--) persistentStore.write_data(pos, &value, 1);
persistentStore.access_finish();
#else
settings.reset();
settings.save();
#endif
HAL_reboot();
} break;
case 0:
HAL_reboot();
break;
case 2: { // D2 Read / Write SRAM
#define SRAM_SIZE 8192
uint8_t *pointer = parser.hex_adr_val('A');
uint16_t len = parser.ushortval('C', 1);
uintptr_t addr = (uintptr_t)pointer;
NOMORE(addr, size_t(SRAM_SIZE - 1));
NOMORE(len, SRAM_SIZE - addr);
if (parser.seenval('X')) {
// Write the hex bytes after the X
uint16_t val = parser.hex_val('X');
while (len--) {
*pointer = val;
pointer++;
}
}
else {
while (len--) print_hex_byte(*(pointer++));
SERIAL_EOL();
}
} break;
case 10:
kill(PSTR("D10"), PSTR("KILL TEST"), parser.seen_test('P'));
break;
case 1: {
// Zero or pattern-fill the EEPROM data
#if ENABLED(EEPROM_SETTINGS)
case 3: { // D3 Read / Write EEPROM
uint8_t *pointer = parser.hex_adr_val('A');
uint16_t len = parser.ushortval('C', 1);
uintptr_t addr = (uintptr_t)pointer;
NOMORE(addr, size_t(persistentStore.capacity() - 1));
NOMORE(len, persistentStore.capacity() - addr);
if (parser.seenval('X')) {
uint16_t val = parser.hex_val('X');
#if ENABLED(EEPROM_SETTINGS)
persistentStore.access_start();
while (len--) {
int pos = 0;
persistentStore.write_data(pos, (uint8_t *)&val, sizeof(val));
}
SERIAL_EOL();
persistentStore.access_finish();
#else
SERIAL_ECHOLNPGM("NO EEPROM");
#endif
}
else {
// Read bytes from EEPROM
#if ENABLED(EEPROM_SETTINGS)
persistentStore.access_start();
int pos = 0;
uint8_t val;
while (len--) if (!persistentStore.read_data(pos, &val, 1)) print_hex_byte(val);
SERIAL_EOL();
persistentStore.access_finish();
#else
SERIAL_ECHOLNPGM("NO EEPROM");
len = 0;
#endif
SERIAL_EOL();
}
} break;
persistentStore.access_start();
size_t total = persistentStore.capacity();
int pos = 0;
const uint8_t value = 0x0;
while (total--) persistentStore.write_data(pos, &value, 1);
persistentStore.access_finish();
#else
settings.reset();
settings.save();
#endif
HAL_reboot();
} break;
case 4: { // D4 Read / Write PIN
//const bool is_out = parser.boolval('F');
//const uint8_t pin = parser.byteval('P'),
// val = parser.byteval('V', LOW);
if (parser.seenval('X')) {
// TODO: Write the hex bytes after the X
//while (len--) {
//}
case 2: { // D2 Read / Write SRAM
#define SRAM_SIZE 8192
uint8_t *pointer = parser.hex_adr_val('A');
uint16_t len = parser.ushortval('C', 1);
uintptr_t addr = (uintptr_t)pointer;
NOMORE(addr, size_t(SRAM_SIZE - 1));
NOMORE(len, SRAM_SIZE - addr);
if (parser.seenval('X')) {
// Write the hex bytes after the X
uint16_t val = parser.hex_val('X');
while (len--) {
*pointer = val;
pointer++;
}
else {
//while (len--) {
//// TODO: Read bytes from EEPROM
// print_hex_byte(eeprom_read_byte(adr++));
//}
SERIAL_EOL();
}
} break;
}
else {
while (len--) print_hex_byte(*(pointer++));
SERIAL_EOL();
}
} break;
case 5: { // D5 Read / Write onboard Flash
#define FLASH_SIZE 1024
#if ENABLED(EEPROM_SETTINGS)
case 3: { // D3 Read / Write EEPROM
uint8_t *pointer = parser.hex_adr_val('A');
uint16_t len = parser.ushortval('C', 1);
uintptr_t addr = (uintptr_t)pointer;
NOMORE(addr, size_t(FLASH_SIZE - 1));
NOMORE(len, FLASH_SIZE - addr);
NOMORE(addr, size_t(persistentStore.capacity() - 1));
NOMORE(len, persistentStore.capacity() - addr);
if (parser.seenval('X')) {
// TODO: Write the hex bytes after the X
//while (len--) {}
uint16_t val = parser.hex_val('X');
#if ENABLED(EEPROM_SETTINGS)
persistentStore.access_start();
while (len--) {
int pos = 0;
persistentStore.write_data(pos, (uint8_t *)&val, sizeof(val));
}
SERIAL_EOL();
persistentStore.access_finish();
#else
SERIAL_ECHOLNPGM("NO EEPROM");
#endif
}
else {
//while (len--) {
//// TODO: Read bytes from EEPROM
// print_hex_byte(eeprom_read_byte(adr++));
//}
// Read bytes from EEPROM
#if ENABLED(EEPROM_SETTINGS)
persistentStore.access_start();
int pos = 0;
uint8_t val;
while (len--) if (!persistentStore.read_data(pos, &val, 1)) print_hex_byte(val);
SERIAL_EOL();
persistentStore.access_finish();
#else
SERIAL_ECHOLNPGM("NO EEPROM");
len = 0;
#endif
SERIAL_EOL();
}
} break;
#endif
case 6: // D6 Check delay loop accuracy
dump_delay_accuracy_check();
break;
case 4: { // D4 Read / Write PIN
//const bool is_out = parser.boolval('F');
//const uint8_t pin = parser.byteval('P'),
// val = parser.byteval('V', LOW);
if (parser.seenval('X')) {
// TODO: Write the hex bytes after the X
//while (len--) {
//}
}
else {
//while (len--) {
//// TODO: Read bytes from EEPROM
// print_hex_byte(eeprom_read_byte(adr++));
//}
SERIAL_EOL();
}
} break;
case 7: // D7 dump the current serial port type (hence configuration)
SERIAL_ECHOLNPAIR("Current serial configuration RX_BS:", RX_BUFFER_SIZE, ", TX_BS:", TX_BUFFER_SIZE);
SERIAL_ECHOLN(gtn(&SERIAL_IMPL));
break;
case 5: { // D5 Read / Write onboard Flash
#define FLASH_SIZE 1024
uint8_t *pointer = parser.hex_adr_val('A');
uint16_t len = parser.ushortval('C', 1);
uintptr_t addr = (uintptr_t)pointer;
NOMORE(addr, size_t(FLASH_SIZE - 1));
NOMORE(len, FLASH_SIZE - addr);
if (parser.seenval('X')) {
// TODO: Write the hex bytes after the X
//while (len--) {}
}
else {
//while (len--) {
//// TODO: Read bytes from EEPROM
// print_hex_byte(eeprom_read_byte(adr++));
//}
SERIAL_EOL();
}
} break;
case 100: { // D100 Disable heaters and attempt a hard hang (Watchdog Test)
SERIAL_ECHOLNPGM("Disabling heaters and attempting to trigger Watchdog");
SERIAL_ECHOLNPGM("(USE_WATCHDOG " TERN(USE_WATCHDOG, "ENABLED", "DISABLED") ")");
thermalManager.disable_all_heaters();
delay(1000); // Allow time to print
DISABLE_ISRS();
// Use a low-level delay that does not rely on interrupts to function
// Do not spin forever, to avoid thermal risks if heaters are enabled and
// watchdog does not work.
for (int i = 10000; i--;) DELAY_US(1000UL);
ENABLE_ISRS();
SERIAL_ECHOLNPGM("FAILURE: Watchdog did not trigger board reset.");
case 6: // D6 Check delay loop accuracy
dump_delay_accuracy_check();
break;
case 7: // D7 dump the current serial port type (hence configuration)
SERIAL_ECHOLNPAIR("Current serial configuration RX_BS:", RX_BUFFER_SIZE, ", TX_BS:", TX_BUFFER_SIZE);
SERIAL_ECHOLN(gtn(&SERIAL_IMPL));
break;
case 100: { // D100 Disable heaters and attempt a hard hang (Watchdog Test)
SERIAL_ECHOLNPGM("Disabling heaters and attempting to trigger Watchdog");
SERIAL_ECHOLNPGM("(USE_WATCHDOG " TERN(USE_WATCHDOG, "ENABLED", "DISABLED") ")");
thermalManager.disable_all_heaters();
delay(1000); // Allow time to print
DISABLE_ISRS();
// Use a low-level delay that does not rely on interrupts to function
// Do not spin forever, to avoid thermal risks if heaters are enabled and
// watchdog does not work.
for (int i = 10000; i--;) DELAY_US(1000UL);
ENABLE_ISRS();
SERIAL_ECHOLNPGM("FAILURE: Watchdog did not trigger board reset.");
} break;
#if ENABLED(SDSUPPORT)
case 101: { // D101 Test SD Write
card.openFileWrite("test.gco");
if (!card.isFileOpen()) {
SERIAL_ECHOLNPAIR("Failed to open test.gco to write.");
return;
}
__attribute__((aligned(sizeof(size_t)))) uint8_t buf[512];
uint16_t c;
for (c = 0; c < COUNT(buf); c++)
buf[c] = 'A' + (c % ('Z' - 'A'));
c = 1024 * 4;
while (c--) {
TERN_(USE_WATCHDOG, watchdog_refresh());
card.write(buf, COUNT(buf));
}
SERIAL_ECHOLNPGM(" done");
card.closefile();
} break;
#if ENABLED(SDSUPPORT)
case 101: { // D101 Test SD Write
card.openFileWrite("test.gco");
if (!card.isFileOpen()) {
SERIAL_ECHOLNPAIR("Failed to open test.gco to write.");
return;
}
__attribute__((aligned(sizeof(size_t)))) uint8_t buf[512];
uint16_t c;
for (c = 0; c < COUNT(buf); c++)
buf[c] = 'A' + (c % ('Z' - 'A'));
c = 1024 * 4;
while (c--) {
TERN_(USE_WATCHDOG, watchdog_refresh());
card.write(buf, COUNT(buf));
}
SERIAL_ECHOLNPGM(" done");
card.closefile();
} break;
case 102: { // D102 Test SD Read
char testfile[] = "test.gco";
card.openFileRead(testfile);
if (!card.isFileOpen()) {
SERIAL_ECHOLNPAIR("Failed to open test.gco to read.");
return;
}
__attribute__((aligned(sizeof(size_t)))) uint8_t buf[512];
uint16_t c = 1024 * 4;
while (c--) {
TERN_(USE_WATCHDOG, watchdog_refresh());
card.read(buf, COUNT(buf));
bool error = false;
for (uint16_t i = 0; i < COUNT(buf); i++) {
if (buf[i] != ('A' + (i % ('Z' - 'A')))) {
error = true;
break;
}
}
if (error) {
SERIAL_ECHOLNPGM(" Read error!");
case 102: { // D102 Test SD Read
char testfile[] = "test.gco";
card.openFileRead(testfile);
if (!card.isFileOpen()) {
SERIAL_ECHOLNPAIR("Failed to open test.gco to read.");
return;
}
__attribute__((aligned(sizeof(size_t)))) uint8_t buf[512];
uint16_t c = 1024 * 4;
while (c--) {
TERN_(USE_WATCHDOG, watchdog_refresh());
card.read(buf, COUNT(buf));
bool error = false;
for (uint16_t i = 0; i < COUNT(buf); i++) {
if (buf[i] != ('A' + (i % ('Z' - 'A')))) {
error = true;
break;
}
}
SERIAL_ECHOLNPGM(" done");
card.closefile();
} break;
#endif // SDSUPPORT
#if ENABLED(POSTMORTEM_DEBUGGING)
case 451: { // Trigger all kind of faults to test exception catcher
SERIAL_ECHOLNPGM("Disabling heaters");
thermalManager.disable_all_heaters();
delay(1000); // Allow time to print
volatile uint8_t type[5] = { parser.byteval('T', 1) };
// The code below is obviously wrong and it's full of quirks to fool the compiler from optimizing away the code
switch (type[0]) {
case 1: default: *(int*)0 = 451; break; // Write at bad address
case 2: { volatile int a = 0; volatile int b = 452 / a; *(int*)&a = b; } break; // Divide by zero (some CPUs accept this, like ARM)
case 3: { *(uint32_t*)&type[1] = 453; volatile int a = *(int*)&type[1]; type[0] = a / 255; } break; // Unaligned access (some CPUs accept this)
case 4: { volatile void (*func)() = (volatile void (*)()) 0xE0000000; func(); } break; // Invalid instruction
if (error) {
SERIAL_ECHOLNPGM(" Read error!");
break;
}
break;
}
SERIAL_ECHOLNPGM(" done");
card.closefile();
} break;
#endif
}
#endif // SDSUPPORT
#if ENABLED(POSTMORTEM_DEBUGGING)
case 451: { // Trigger all kind of faults to test exception catcher
SERIAL_ECHOLNPGM("Disabling heaters");
thermalManager.disable_all_heaters();
delay(1000); // Allow time to print
volatile uint8_t type[5] = { parser.byteval('T', 1) };
// The code below is obviously wrong and it's full of quirks to fool the compiler from optimizing away the code
switch (type[0]) {
case 1: default: *(int*)0 = 451; break; // Write at bad address
case 2: { volatile int a = 0; volatile int b = 452 / a; *(int*)&a = b; } break; // Divide by zero (some CPUs accept this, like ARM)
case 3: { *(uint32_t*)&type[1] = 453; volatile int a = *(int*)&type[1]; type[0] = a / 255; } break; // Unaligned access (some CPUs accept this)
case 4: { volatile void (*func)() = (volatile void (*)()) 0xE0000000; func(); } break; // Invalid instruction
}
break;
}
#endif
#if ENABLED(BUFFER_MONITORING)
/**
* D576: Return buffer stats or set the auto-report interval.
* Usage: D576 [S<seconds>]
*
* With no parameters emits the following output:
* "D576 P<nn> B<nn> PU<nn> PD<nn> BU<nn> BD<nn>"
* Where:
* P : Planner buffers free
* B : Command buffers free
* PU: Planner buffer underruns (since the last report)
* PD: Longest duration (ms) the planner buffer was empty (since the last report)
* BU: Command buffer underruns (since the last report)
* BD: Longest duration (ms) command buffer was empty (since the last report)
*/
case 576: {
if (parser.seenval('S'))
queue.set_auto_report_interval((uint8_t)parser.value_byte());
else
queue.report_buffer_statistics();
break;
}
#endif // BUFFER_MONITORING
}
}
#endif
#endif // MARLIN_DEV_MODE

View file

@ -67,6 +67,23 @@ GCodeQueue::RingBuffer GCodeQueue::ring_buffer = { 0 };
static millis_t last_command_time = 0;
#endif
/**
* Track buffer underruns
*/
#if ENABLED(BUFFER_MONITORING)
uint32_t GCodeQueue::command_buffer_underruns = 0,
GCodeQueue::planner_buffer_underruns = 0;
bool GCodeQueue::command_buffer_empty = false,
GCodeQueue::planner_buffer_empty = false;
millis_t GCodeQueue::max_command_buffer_empty_duration = 0,
GCodeQueue::max_planner_buffer_empty_duration = 0,
GCodeQueue::command_buffer_empty_at = 0,
GCodeQueue::planner_buffer_empty_at = 0;
uint8_t GCodeQueue::auto_buffer_report_interval;
millis_t GCodeQueue::next_buffer_report_ms;
#endif
/**
* Serial command injection
*/
@ -82,7 +99,6 @@ PGM_P GCodeQueue::injected_commands_P; // = nullptr
*/
char GCodeQueue::injected_commands[64]; // = { 0 }
void GCodeQueue::RingBuffer::commit_command(bool skip_ok
OPTARG(HAS_MULTI_SERIAL, serial_index_t serial_ind/*=-1*/)
) {
@ -621,7 +637,24 @@ void GCodeQueue::advance() {
if (process_injected_command_P() || process_injected_command()) return;
// Return if the G-code buffer is empty
if (ring_buffer.empty()) return;
if (ring_buffer.empty()) {
#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)
if (command_buffer_empty) {
command_buffer_empty = false;
const millis_t command_buffer_empty_duration = millis() - command_buffer_empty_at;
NOLESS(max_command_buffer_empty_duration, command_buffer_empty_duration);
}
#endif
#if ENABLED(SDSUPPORT)
@ -664,3 +697,41 @@ void GCodeQueue::advance() {
// The queue may be reset by a command handler or by code invoked by idle() within a handler
ring_buffer.advance_pos(ring_buffer.index_r, -1);
}
#if ENABLED(BUFFER_MONITORING)
void GCodeQueue::report_buffer_statistics() {
SERIAL_ECHOLNPAIR("D576"
" P:", planner.moves_free(), " ", -queue.planner_buffer_underruns, " (", queue.max_planner_buffer_empty_duration, ")"
" B:", BUFSIZE - ring_buffer.length, " ", -queue.command_buffer_underruns, " (", queue.max_command_buffer_empty_duration, ")"
);
command_buffer_underruns = planner_buffer_underruns = 0;
max_command_buffer_empty_duration = 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
const millis_t ms = millis();
if (planner.movesplanned() == 0) {
if (!planner_buffer_empty) { // the planner buffer wasn't empty, but now it is
planner_buffer_empty = true;
planner_buffer_underruns++;
planner_buffer_empty_at = ms;
}
}
else if (planner_buffer_empty) { // the planner buffer was empty, but now it's not
planner_buffer_empty = false;
const millis_t planner_buffer_empty_duration = ms - planner_buffer_empty_at;
NOLESS(max_planner_buffer_empty_duration, planner_buffer_empty_duration); // if it's longer than the currently tracked max duration, replace it
}
if (queue.auto_buffer_report_interval && ELAPSED(ms, queue.next_buffer_report_ms)) {
queue.next_buffer_report_ms = ms + 1000UL * queue.auto_buffer_report_interval;
PORT_REDIRECT(SERIAL_BOTH);
report_buffer_statistics();
PORT_RESTORE();
}
}
#endif // BUFFER_MONITORING

View file

@ -197,6 +197,46 @@ public:
*/
static inline void set_current_line_number(long n) { serial_state[ring_buffer.command_port().index].last_N = n; }
#if ENABLED(BUFFER_MONITORING)
private:
/**
* Track buffer underruns
*/
static uint32_t command_buffer_underruns, planner_buffer_underruns;
static bool command_buffer_empty, planner_buffer_empty;
static millis_t max_command_buffer_empty_duration, max_planner_buffer_empty_duration,
command_buffer_empty_at, planner_buffer_empty_at;
/**
* Report buffer statistics to the host to be able to detect buffer underruns
*
* Returns "D576 " followed by:
* P<uint> Planner space remaining
* B<uint> Command buffer space remaining
* PU<uint> Number of planner buffer underruns since last report
* PD<uint> Max time in ms the planner buffer was empty since last report
* BU<uint> Number of command buffer underruns since last report
* BD<uint> Max time in ms the command buffer was empty since last report
*/
static void report_buffer_statistics();
static uint8_t auto_buffer_report_interval;
static millis_t next_buffer_report_ms;
public:
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 // BUFFER_MONITORING
private:
static void get_serial_commands();

View file

@ -10,7 +10,7 @@ set -e
# Build with configs included in the PR
#
use_example_configs "Creality/Ender-3 V2/CrealityUI"
opt_enable MARLIN_DEV_MODE
opt_enable MARLIN_DEV_MODE BUFFER_MONITORING
exec_test $1 $2 "Ender 3 v2 with CrealityUI" "$3"
use_example_configs "Creality/Ender-3 V2/CrealityUI"