Improvements to CAN logging to SD to significantly improve performance for busy CAN networks (#752)

- Migrate from SPI SD library to SD_MMC
- Minimise the number of individual file writes by batching writes where possible
- Write a binary stream to the buffer to stop corruption

Software/src/devboard/sdcard/sdcard.cpp

@@ -26,7 +26,7 @@ void delete_can_log() {
 
 void resume_can_writing() {
   can_logging_paused = false;
-  can_log_file = SD.open(CAN_LOG_FILE, FILE_APPEND);
+  can_log_file = SD_MMC.open(CAN_LOG_FILE, FILE_APPEND);
   can_file_open = true;
 }
 
@@ -40,13 +40,13 @@ void delete_log() {
     log_file.close();
     log_file_open = false;
   }
-  SD.remove(LOG_FILE);
+  SD_MMC.remove(LOG_FILE);
   logging_paused = false;
 }
 
 void resume_log_writing() {
   logging_paused = false;
-  log_file = SD.open(LOG_FILE, FILE_APPEND);
+  log_file = SD_MMC.open(LOG_FILE, FILE_APPEND);
   log_file_open = true;
 }
 
@@ -59,11 +59,33 @@ void add_can_frame_to_buffer(CAN_frame frame, frameDirection msgDir) {
   if (!sd_card_active)
     return;
 
-  CAN_log_frame log_frame = {frame, msgDir};
+  unsigned long currentTime = millis();
-  if (xRingbufferSend(can_bufferHandle, &log_frame, sizeof(log_frame), 0) != pdTRUE) {
+  static char messagestr_buffer[32];
-    Serial.println("Failed to send CAN frame to ring buffer!");
+  size_t size =
+      snprintf(messagestr_buffer + size, sizeof(messagestr_buffer) - size, "(%lu.%03lu) %s %X [%u] ",
+               currentTime / 1000, currentTime % 1000, (msgDir == MSG_RX ? "RX0" : "TX1"), frame.ID, frame.DLC);
+
+  if (xRingbufferSend(can_bufferHandle, &messagestr_buffer, size, pdMS_TO_TICKS(2)) != pdTRUE) {
+#ifdef DEBUG_VIA_USB
+    Serial.println("Failed to send message to can ring buffer!");
+#endif  // DEBUG_VIA_USB
     return;
   }
+
+  uint8_t i = 0;
+  for (i = 0; i < frame.DLC; i++) {
+    if (i < frame.DLC - 1)
+      size = snprintf(messagestr_buffer, sizeof(messagestr_buffer), "%02X ", frame.data.u8[i]);
+    else
+      size = snprintf(messagestr_buffer, sizeof(messagestr_buffer), "%02X\n", frame.data.u8[i]);
+
+    if (xRingbufferSend(can_bufferHandle, &messagestr_buffer, size, pdMS_TO_TICKS(2)) != pdTRUE) {
+#ifdef DEBUG_VIA_USB
+      Serial.println("Failed to send message to can ring buffer!");
+#endif  // DEBUG_VIA_USB
+      return;
+    }
+  }
 }
 
 void write_can_frame_to_sdcard() {
@@ -72,10 +94,9 @@ void write_can_frame_to_sdcard() {
     return;
 
   size_t receivedMessageSize;
-  CAN_log_frame* log_frame =
+  uint8_t* buffer = (uint8_t*)xRingbufferReceive(can_bufferHandle, &receivedMessageSize, pdMS_TO_TICKS(10));
-      (CAN_log_frame*)xRingbufferReceive(can_bufferHandle, &receivedMessageSize, pdMS_TO_TICKS(10));
 
-  if (log_frame != NULL) {
+  if (buffer != NULL) {
 
     if (can_logging_paused) {
       if (can_file_open) {
@@ -83,37 +104,23 @@ void write_can_frame_to_sdcard() {
         can_file_open = false;
       }
       if (delete_can_file) {
-        SD.remove(CAN_LOG_FILE);
+        SD_MMC.remove(CAN_LOG_FILE);
         delete_can_file = false;
         can_logging_paused = false;
       }
-      vRingbufferReturnItem(can_bufferHandle, (void*)log_frame);
+      vRingbufferReturnItem(can_bufferHandle, (void*)buffer);
       return;
     }
 
     if (can_file_open == false) {
-      can_log_file = SD.open(CAN_LOG_FILE, FILE_APPEND);
+      can_log_file = SD_MMC.open(CAN_LOG_FILE, FILE_APPEND);
       can_file_open = true;
     }
 
-    uint8_t i = 0;
+    can_log_file.write(buffer, receivedMessageSize);
-    can_log_file.print("(");
-    can_log_file.print(millis() / 1000.0);
-    (log_frame->direction == MSG_RX) ? can_log_file.print(") RX0 ") : can_log_file.print(") TX1 ");
-    can_log_file.print(log_frame->frame.ID, HEX);
-    can_log_file.print(" [");
-    can_log_file.print(log_frame->frame.DLC);
-    can_log_file.print("] ");
-    for (i = 0; i < log_frame->frame.DLC; i++) {
-      can_log_file.print(log_frame->frame.data.u8[i] < 16 ? "0" : "");
-      can_log_file.print(log_frame->frame.data.u8[i], HEX);
-      if (i < log_frame->frame.DLC - 1)
-        can_log_file.print(" ");
-    }
-    can_log_file.println("");
     can_log_file.flush();
 
-    vRingbufferReturnItem(can_bufferHandle, (void*)log_frame);
+    vRingbufferReturnItem(can_bufferHandle, (void*)buffer);
   }
 }
 
@@ -122,8 +129,10 @@ void add_log_to_buffer(const uint8_t* buffer, size_t size) {
   if (!sd_card_active)
     return;
 
-  if (xRingbufferSend(log_bufferHandle, buffer, size, 0) != pdTRUE) {
+  if (xRingbufferSend(log_bufferHandle, buffer, size, pdMS_TO_TICKS(1)) != pdTRUE) {
-    Serial.println("Failed to send log to ring buffer!");
+#ifdef DEBUG_VIA_USB
+    Serial.println("Failed to send message to log ring buffer!");
+#endif  // DEBUG_VIA_USB
     return;
   }
 }
@@ -144,7 +153,7 @@ void write_log_to_sdcard() {
     }
 
     if (log_file_open == false) {
-      log_file = SD.open(LOG_FILE, FILE_APPEND);
+      log_file = SD_MMC.open(LOG_FILE, FILE_APPEND);
       log_file_open = true;
     }
 
@@ -158,7 +167,9 @@ void init_logging_buffers() {
 #if defined(LOG_CAN_TO_SD)
   can_bufferHandle = xRingbufferCreate(32 * 1024, RINGBUF_TYPE_BYTEBUF);
   if (can_bufferHandle == NULL) {
-    Serial.println("Failed to create CAN ring buffer!");
+#ifdef DEBUG_LOG
+    logging.println("Failed to create CAN ring buffer!");
+#endif  // DEBUG_LOG
     return;
   }
 #endif  // defined(LOG_CAN_TO_SD)
@@ -166,7 +177,9 @@ void init_logging_buffers() {
 #if defined(LOG_TO_SD)
   log_bufferHandle = xRingbufferCreate(1024, RINGBUF_TYPE_BYTEBUF);
   if (log_bufferHandle == NULL) {
-    Serial.println("Failed to create log ring buffer!");
+#ifdef DEBUG_LOG
+    logging.println("Failed to create log ring buffer!");
+#endif  // DEBUG_LOG
     return;
   }
 #endif  // defined(LOG_TO_SD)
@@ -174,57 +187,60 @@ void init_logging_buffers() {
 
 void init_sdcard() {
 
-  pinMode(SD_CS_PIN, OUTPUT);
+  pinMode(SD_MISO_PIN, INPUT_PULLUP);
-  digitalWrite(SD_CS_PIN, HIGH);
-  pinMode(SD_SCLK_PIN, OUTPUT);
-  pinMode(SD_MOSI_PIN, OUTPUT);
-  pinMode(SD_MISO_PIN, INPUT);
 
-  SPI.begin(SD_SCLK_PIN, SD_MISO_PIN, SD_MOSI_PIN, SD_CS_PIN);
+  SD_MMC.setPins(SD_SCLK_PIN, SD_MOSI_PIN, SD_MISO_PIN);
-  if (!SD.begin(SD_CS_PIN)) {
+  if (!SD_MMC.begin("/root", true, true, SDMMC_FREQ_HIGHSPEED)) {
-    Serial.println("SD Card initialization failed!");
+#ifdef DEBUG_LOG
+    logging.println("SD Card initialization failed!");
+#endif  // DEBUG_LOG
     return;
   }
 
-  Serial.println("SD Card initialization successful.");
+#ifdef DEBUG_LOG
+  logging.println("SD Card initialization successful.");
+#endif  // DEBUG_LOG
+
   sd_card_active = true;
 
-  print_sdcard_details();
+#ifdef DEBUG_LOG
+  log_sdcard_details();
+#endif  // DEBUG_LOG
 }
 
-void print_sdcard_details() {
+void log_sdcard_details() {
 
-  Serial.print("SD Card Type: ");
+  logging.print("SD Card Type: ");
-  switch (SD.cardType()) {
+  switch (SD_MMC.cardType()) {
     case CARD_MMC:
-      Serial.println("MMC");
+      logging.println("MMC");
       break;
     case CARD_SD:
-      Serial.println("SD");
+      logging.println("SD");
       break;
     case CARD_SDHC:
-      Serial.println("SDHC");
+      logging.println("SDHC");
       break;
     case CARD_UNKNOWN:
-      Serial.println("UNKNOWN");
+      logging.println("UNKNOWN");
       break;
     case CARD_NONE:
-      Serial.println("No SD Card found");
+      logging.println("No SD Card found");
       break;
   }
 
-  if (SD.cardType() != CARD_NONE) {
+  if (SD_MMC.cardType() != CARD_NONE) {
-    Serial.print("SD Card Size: ");
+    logging.print("SD Card Size: ");
-    Serial.print(SD.cardSize() / 1024 / 1024);
+    logging.print(SD_MMC.cardSize() / 1024 / 1024);
-    Serial.println(" MB");
+    logging.println(" MB");
 
-    Serial.print("Total space: ");
+    logging.print("Total space: ");
-    Serial.print(SD.totalBytes() / 1024 / 1024);
+    logging.print(SD_MMC.totalBytes() / 1024 / 1024);
-    Serial.println(" MB");
+    logging.println(" MB");
 
-    Serial.print("Used space: ");
+    logging.print("Used space: ");
-    Serial.print(SD.usedBytes() / 1024 / 1024);
+    logging.print(SD_MMC.usedBytes() / 1024 / 1024);
-    Serial.println(" MB");
+    logging.println(" MB");
   }
 }
 #endif  // defined(SD_CS_PIN) && defined(SD_SCLK_PIN) && defined(SD_MOSI_PIN) && defined(SD_MISO_PIN)

Software/src/devboard/sdcard/sdcard.h

@@ -1,8 +1,7 @@
 #ifndef SDCARD_H
 #define SDCARD_H
 
-#include <SD.h>
+#include <SD_MMC.h>
-#include <SPI.h>
 #include "../../communication/can/comm_can.h"
 #include "../hal/hal.h"
 
@@ -14,7 +13,7 @@
 void init_logging_buffers();
 
 void init_sdcard();
-void print_sdcard_details();
+void log_sdcard_details();
 
 void add_can_frame_to_buffer(CAN_frame frame, frameDirection msgDir);
 void write_can_frame_to_sdcard();

Software/src/devboard/webserver/webserver.cpp

@@ -112,7 +112,7 @@ void init_webserver() {
   // Define the handler to export can log
   server.on("/export_can_log", HTTP_GET, [](AsyncWebServerRequest* request) {
     pause_can_writing();
-    request->send(SD, CAN_LOG_FILE, String(), true);
+    request->send(SD_MMC, CAN_LOG_FILE, String(), true);
     resume_can_writing();
   });
 
@@ -133,7 +133,7 @@ void init_webserver() {
   // Define the handler to export debug log
   server.on("/export_log", HTTP_GET, [](AsyncWebServerRequest* request) {
     pause_log_writing();
-    request->send(SD, LOG_FILE, String(), true);
+    request->send(SD_MMC, LOG_FILE, String(), true);
     resume_log_writing();
   });
 #endif