From 34da988e2ec82103592c0516873b9d58530fdf56 Mon Sep 17 00:00:00 2001 From: Eric Helgeson Date: Mon, 11 Dec 2023 09:04:40 -0600 Subject: [PATCH] Add back Serial USB logging with SRAM optimizations. This commit is derived from code from @morio across the following commits plus my own adjustments for the BlueSCSI platform: Output log over serial USB https://github.com/ZuluSCSI/ZuluSCSI-firmware/commit/573dc60ca91c54363a0bdad20ba37e3029807c6e Fix out SRAM compile time issue https://github.com/ZuluSCSI/ZuluSCSI-firmware/commit/30df3aae306da34df292fc7ce5278a2a891e9f66 Adjust prefetch buffer to fix SRAM overflow https://github.com/ZuluSCSI/ZuluSCSI-firmware/commit/9f61b3cdfbdda92359c23fd0fc12a0b7ccffc486 Get PlatformIO debug to work on RP2040 MCUs https://github.com/ZuluSCSI/ZuluSCSI-firmware/commit/d72012b3bc91539bbcea2c25ad1dec41d94f98a5 Co-authored-by: Morio --- .../BlueSCSI_platform.cpp | 53 ++++++++++----- lib/BlueSCSI_platform_RP2040/rp2040.ld | 2 +- lib/SCSI2SD/src/firmware/log.h | 20 +++++- lib/SCSI2SD/src/firmware/network.c | 62 ++++++----------- platformio.ini | 14 +++- src/BlueSCSI_log.cpp | 68 +++++++++++++++++++ src/BlueSCSI_log.h | 22 +++++- 7 files changed, 179 insertions(+), 62 deletions(-) diff --git a/lib/BlueSCSI_platform_RP2040/BlueSCSI_platform.cpp b/lib/BlueSCSI_platform_RP2040/BlueSCSI_platform.cpp index 153304a1..32f44dc5 100644 --- a/lib/BlueSCSI_platform_RP2040/BlueSCSI_platform.cpp +++ b/lib/BlueSCSI_platform_RP2040/BlueSCSI_platform.cpp @@ -17,11 +17,18 @@ #include #include #include -#ifdef MBED -#include -#include +#ifdef ENABLE_AUDIO_OUTPUT #include "audio.h" #endif + +#ifndef __MBED__ +# include +# include +#else +# include +# include +#endif // __MBED__ + #include #include "scsi_accel_rp2040.h" #include "hardware/i2c.h" @@ -282,6 +289,11 @@ void platform_late_init() gpio_conf(scsi_pins.IN_ATN, GPIO_FUNC_SIO, false, false, false, true, false); gpio_conf(scsi_pins.IN_RST, GPIO_FUNC_SIO, true, false, false, true, false); + +#ifndef __MBED__ + Serial.begin(); +#endif // __MBED__ + #ifdef ENABLE_AUDIO_OUTPUT // one-time control setup for DMA channels and second core audio_setup(); @@ -416,11 +428,27 @@ void mbed_error_hook(const mbed_error_ctx * error_context) // also starts calling this after 2 seconds. // This ensures that log messages get passed even if code hangs, // but does not unnecessarily delay normal execution. -#ifdef MBED static void usb_log_poll() { static uint32_t logpos = 0; +#ifndef __MBED__ + if (Serial.availableForWrite()) + { + // Retrieve pointer to log start and determine number of bytes available. + uint32_t available = 0; + const char *data = log_get_buffer(&logpos, &available); + // Limit to CDC packet size + uint32_t len = available; + if (len == 0) return; + if (len > CFG_TUD_CDC_EP_BUFSIZE) len = CFG_TUD_CDC_EP_BUFSIZE; + // Update log position by the actual number of bytes sent + // If USB CDC buffer is full, this may be 0 + uint32_t actual = 0; + actual = Serial.write(data, len); + logpos -= available - actual; + } +#else if (_SerialUSB.ready()) { // Retrieve pointer to log start and determine number of bytes available. @@ -438,8 +466,8 @@ static void usb_log_poll() _SerialUSB.send_nb((uint8_t*)data, len, &actual); logpos -= available - actual; } +#endif // __MBED__ } -#endif // Use ADC to implement supply voltage monitoring for the +3.0V rail. // This works by sampling the temperature sensor channel, which has @@ -520,13 +548,11 @@ static void watchdog_callback(unsigned alarm_num) { g_watchdog_timeout -= 1000; -#ifdef MBED if (g_watchdog_timeout < WATCHDOG_CRASH_TIMEOUT - 1000) { // Been stuck for at least a second, start dumping USB log usb_log_poll(); } -#endif if (g_watchdog_timeout <= WATCHDOG_CRASH_TIMEOUT - WATCHDOG_BUS_RESET_TIMEOUT) { @@ -573,9 +599,8 @@ static void watchdog_callback(unsigned alarm_num) p += 4; } -#ifdef MBED usb_log_poll(); -#endif + platform_emergency_log_save(); platform_boot_to_main_firmware(); @@ -613,20 +638,17 @@ void platform_reset_watchdog() g_watchdog_initialized = true; } -#ifdef MBED // USB log is polled here also to make sure any log messages in fault states // get passed to USB. usb_log_poll(); -#endif } // Poll function that is called every few milliseconds. // Can be left empty or used for platform-specific processing. void platform_poll() { -#ifdef MBED usb_log_poll(); -#endif + adc_poll(); #ifdef ENABLE_AUDIO_OUTPUT @@ -692,15 +714,14 @@ bool platform_rewrite_flash_page(uint32_t offset, uint8_t buffer[PLATFORM_FLASH_ return false; } } - -#ifdef MBED +#ifdef __MBED__ if (NVIC_GetEnableIRQ(USBCTRL_IRQn)) { log("Disabling USB during firmware flashing"); NVIC_DisableIRQ(USBCTRL_IRQn); usb_hw->main_ctrl = 0; } -#endif +#endif // __MBED__ debuglog("Writing flash at offset ", offset, " data ", bytearray(buffer, 4)); assert(offset % PLATFORM_FLASH_PAGE_SIZE == 0); diff --git a/lib/BlueSCSI_platform_RP2040/rp2040.ld b/lib/BlueSCSI_platform_RP2040/rp2040.ld index acf9b972..57e6e450 100755 --- a/lib/BlueSCSI_platform_RP2040/rp2040.ld +++ b/lib/BlueSCSI_platform_RP2040/rp2040.ld @@ -1,7 +1,7 @@ MEMORY { FLASH(rx) : ORIGIN = 0x10000000, LENGTH = 352k - RAM(rwx) : ORIGIN = 0x20000000, LENGTH = 240k /* Leave space for pico-debug */ + RAM(rwx) : ORIGIN = 0x20000000, LENGTH = 256k /* Leave space for pico-debug */ SCRATCH_X(rwx) : ORIGIN = 0x20040000, LENGTH = 4k SCRATCH_Y(rwx) : ORIGIN = 0x20041000, LENGTH = 4k } diff --git a/lib/SCSI2SD/src/firmware/log.h b/lib/SCSI2SD/src/firmware/log.h index ee6389ea..d70220d7 100644 --- a/lib/SCSI2SD/src/firmware/log.h +++ b/lib/SCSI2SD/src/firmware/log.h @@ -14,14 +14,32 @@ // // You should have received a copy of the GNU General Public License // along with SCSI2SD. If not, see . +#ifndef SCSI2SD_LOG_H +#define SCSI2SD_LOG_H +#include + #ifdef __cplusplus extern "C" { #endif +extern bool g_log_debug; + extern void log_buf(const unsigned char *buf, unsigned long size); extern void log_f(const char *format, ...); +extern void dbgmsg_buf(const unsigned char *buf, unsigned long size); +extern void dbgmsg_f(const char *format, ...); + +// check if debug is enabled before calling the logging function +#define DBGMSG_BUF(buf, size) \ + if (g_log_debug) {dbgmsg_buf(buf, size);} + +#define DBGMSG_F(format, ...) \ + if (g_log_debug) {dbgmsg_f(format, __VA_ARGS__);} + #ifdef __cplusplus } -#endif \ No newline at end of file +#endif + +#endif // SCSI2SD_LOG_H \ No newline at end of file diff --git a/lib/SCSI2SD/src/firmware/network.c b/lib/SCSI2SD/src/firmware/network.c index f51f4377..02f1f750 100644 --- a/lib/SCSI2SD/src/firmware/network.c +++ b/lib/SCSI2SD/src/firmware/network.c @@ -22,8 +22,6 @@ #include "config.h" #include "network.h" -extern bool g_log_debug; - static bool scsiNetworkEnabled = false; struct scsiNetworkPacketQueue { @@ -104,10 +102,7 @@ int scsiNetworkCommand() uint8_t command = scsiDev.cdb[0]; uint8_t cont = (scsiDev.cdb[5] == 0x80); - if (g_log_debug) - { - log_f("in scsiNetworkCommand with command 0x%02x (size %d)", command, size); - } + DBGMSG_F("------ in scsiNetworkCommand with command 0x%02x (size %d)", command, size); switch (command) { case 0x08: @@ -140,10 +135,7 @@ int scsiNetworkCommand() psize = size - 6; } - if (g_log_debug) - { - log_f("%s: sending packet[%d] to host of size %zu + 6", __func__, scsiNetworkInboundQueue.readIndex, psize); - } + DBGMSG_F("%s: sending packet[%d] to host of size %zu + 6", __func__, scsiNetworkInboundQueue.readIndex, psize); scsiDev.dataLen = psize + 6; // 2-byte length + 4-byte flag + packet memcpy(scsiDev.data + 6, scsiNetworkInboundQueue.packets[scsiNetworkInboundQueue.readIndex], psize); @@ -162,10 +154,7 @@ int scsiNetworkCommand() // more data to read? scsiDev.data[5] = (scsiNetworkInboundQueue.readIndex == scsiNetworkInboundQueue.writeIndex ? 0 : 0x10); - if (g_log_debug) - { - log_buf(scsiDev.data, scsiDev.dataLen); - } + DBGMSG_BUF(scsiDev.data, scsiDev.dataLen); } // DaynaPort driver needs a delay between reading the initial packet size and the data so manually do two transfers @@ -217,10 +206,14 @@ int scsiNetworkCommand() parityError = 0; scsiRead(scsiDev.data, size, &parityError); - if (g_log_debug) + if (parityError) { - log_f("%s: read packet from host of size %zu - %d (parity error %d)", __func__, size, (cont ? 4 : 0), parityError); - log_buf(scsiDev.data, size); + DBGMSG_F("%s: read packet from host of size %zu - %d (parity error %d)", __func__, size, (cont ? 4 : 0), parityError); + DBGMSG_F(scsiDev.data, size); + } + else + { + DBGMSG_F("------ %s: read packet from host of size %zu - %d", __func__, size, (cont ? 4 : 0)); } if (cont) @@ -253,11 +246,8 @@ int scsiNetworkCommand() parityError = 0; scsiRead(scsiDev.data, size, &parityError); - if (g_log_debug) - { - log_f("%s: adding multicast address %02x:%02x:%02x:%02x:%02x:%02x", __func__, + DBGMSG_F("%s: adding multicast address %02x:%02x:%02x:%02x:%02x:%02x", __func__, scsiDev.data[0], scsiDev.data[1], scsiDev.data[2], scsiDev.data[3], scsiDev.data[4], scsiDev.data[5]); - } platform_network_add_multicast_address(scsiDev.data); @@ -269,20 +259,16 @@ int scsiNetworkCommand() // toggle interface if (scsiDev.cdb[5] & 0x80) { - if (g_log_debug) - { - log_f("%s: enable interface", __func__); - } + + DBGMSG_F("%s: enable interface", __func__); scsiNetworkEnabled = true; memset(&scsiNetworkInboundQueue, 0, sizeof(scsiNetworkInboundQueue)); memset(&scsiNetworkOutboundQueue, 0, sizeof(scsiNetworkOutboundQueue)); } else { - if (g_log_debug) - { - log_f("%s: disable interface", __func__); - } + + DBGMSG_F("%s: disable interface", __func__); scsiNetworkEnabled = false; } break; @@ -303,10 +289,7 @@ int scsiNetworkCommand() // custom wifi commands all using the same opcode, with a sub-command in cdb[2] case SCSI_NETWORK_WIFI_CMD: - if (g_log_debug) - { - log_f("in scsiNetworkCommand with wi-fi command 0x%02x (size %d)", scsiDev.cdb[1], size); - } + DBGMSG_F("in scsiNetworkCommand with wi-fi command 0x%02x (size %d)", scsiDev.cdb[1], size); switch (scsiDev.cdb[1]) { case SCSI_NETWORK_WIFI_CMD_SCAN: @@ -404,11 +387,8 @@ int scsiNetworkCommand() parityError = 0; scsiRead((uint8_t *)&req, sizeof(req), &parityError); - if (g_log_debug) - { - log_f("%s: read join request from host:", __func__); - log_buf(scsiDev.data, size); - } + DBGMSG_F("%s: read join request from host:", __func__); + DBGMSG_BUF(scsiDev.data, size); platform_network_wifi_join(req.ssid, req.key); @@ -433,8 +413,7 @@ int scsiNetworkEnqueue(const uint8_t *buf, size_t len) if (len + 4 > sizeof(scsiNetworkInboundQueue.packets[0])) { - if (g_log_debug) - log_f("%s: dropping incoming network packet, too large (%zu > %zu)", __func__, len, sizeof(scsiNetworkInboundQueue.packets[0])); + DBGMSG_F("%s: dropping incoming network packet, too large (%zu > %zu)", __func__, len, sizeof(scsiNetworkInboundQueue.packets[0])); return 0; } @@ -454,8 +433,7 @@ int scsiNetworkEnqueue(const uint8_t *buf, size_t len) if (scsiNetworkInboundQueue.writeIndex == scsiNetworkInboundQueue.readIndex) { - if (g_log_debug) - log_f("%s: dropping packets in ring, write index caught up to read index", __func__); + DBGMSG_F("%s: dropping packets in ring, write index caught up to read index", __func__); } return 1; diff --git a/platformio.ini b/platformio.ini index 811aa5a2..0bfff157 100644 --- a/platformio.ini +++ b/platformio.ini @@ -18,12 +18,22 @@ platform_packages = platformio/toolchain-gccarmnoneeabi@1.100301.220327 framework = arduino board = rpipicow board_build.core = earlephilhower +upload_protocol = picoprobe +debug_tool = cmsis-dap ; new picoprobe.uf2's emulate cmsis-dap +; extra_scripts = src/build_bootloader.py +; ldscript_bootloader = lib/BlueSCSI_platform_RP2040/rp2040_btldr.ld lib_deps = SdFat=https://github.com/BlueSCSI/SdFat#2.2.0-gpt minIni BlueSCSI_platform_RP2040 SCSI2SD CUEParser +debug_build_flags = + -O2 -ggdb -g3 +; The values can be adjusted down to get a debug build to fit in to SRAM + -DLOGBUFSIZE=1024 + -DSCSI2SD_BUFFER_SIZE=57344 + -DPREFETCH_BUFFER_SIZE=6144 build_flags = -O2 -Isrc -ggdb -g3 -Wall -Wno-sign-compare -Wno-ignored-qualifiers @@ -32,9 +42,11 @@ build_flags = -DENABLE_DEDICATED_SPI=1 -DHAS_SDIO_CLASS -DUSE_ARDUINO=1 - -DNO_USB=1 -DPICO_DEFAULT_I2C_SDA_PIN=16 -DPICO_DEFAULT_I2C_SCL_PIN=17 + ; -DLOGBUFSIZE=8192 + ; -DPREFETCH_BUFFER_SIZE=6144 + ; -DSCSI2SD_BUFFER_SIZE=57344 ; Experimental Audio build ; Rquires seperate hardware and overclock. diff --git a/src/BlueSCSI_log.cpp b/src/BlueSCSI_log.cpp index 853d68f8..aee68ae3 100644 --- a/src/BlueSCSI_log.cpp +++ b/src/BlueSCSI_log.cpp @@ -222,3 +222,71 @@ const char *log_get_buffer(uint32_t *startpos, uint32_t *available) return result; } +// TODO write directly global log buffer to save some memory +static char shared_log_buf[1500 * 3]; + +// core method for variadic printf like logging +static void log_va(bool debug, const char *format, va_list ap) +{ + vsnprintf(shared_log_buf, sizeof(shared_log_buf), format, ap); + if (debug) + { + debuglog(shared_log_buf); + } + else + { + log(shared_log_buf); + } +} + +void logmsg_f(const char *format, ...) +{ + va_list ap; + va_start(ap, format); + log_va(false, format, ap); + va_end(ap); +} + +void dbgmsg_f(const char *format, ...) +{ + if (!g_log_debug) + return; + va_list ap; + va_start(ap, format); + log_va(true, format, ap); + va_end(ap); +} + +// core method for logging a data buffer into a hex string +void log_hex_buf(const unsigned char *buf, unsigned long size, bool debug) +{ + static char hex[] = "0123456789abcdef"; + int o = 0; + + for (int j = 0; j < size; j++) { + if (o + 3 >= sizeof(shared_log_buf)) + break; + + if (j != 0) + shared_log_buf[o++] = ' '; + shared_log_buf[o++] = hex[(buf[j] >> 4) & 0xf]; + shared_log_buf[o++] = hex[buf[j] & 0xf]; + shared_log_buf[o] = 0; + } + if (debug) + debuglog(shared_log_buf); + else + log(shared_log_buf); +} + +void logmsg_buf(const unsigned char *buf, unsigned long size) +{ + log_hex_buf(buf, size, false); +} + +void dbgmsg_buf(const unsigned char *buf, unsigned long size) +{ + if (!g_log_debug) + return; + log_hex_buf(buf, size, true); +} \ No newline at end of file diff --git a/src/BlueSCSI_log.h b/src/BlueSCSI_log.h index a914b78c..e3915acd 100644 --- a/src/BlueSCSI_log.h +++ b/src/BlueSCSI_log.h @@ -16,7 +16,7 @@ uint32_t log_get_buffer_len(); const char *log_get_buffer(uint32_t *startpos, uint32_t *available = nullptr); // Whether to enable debug messages -extern bool g_log_debug; +extern "C" bool g_log_debug; // Enables output test mode extern bool g_test_mode; @@ -102,3 +102,23 @@ inline void debuglog(Params... params) log_raw("\n"); } } + +#ifdef __cplusplus +extern "C" { +#endif +// Log long hex string +void logmsg_buf(const unsigned char *buf, unsigned long size); + +// Log long hex string +void dbgmsg_buf(const unsigned char *buf, unsigned long size); + +// Log formatted string +void logmsg_f(const char *format, ...); + +// Log formatted string +void dbgmsg_f(const char *format, ...); + + +#ifdef __cplusplus +} +#endif \ No newline at end of file