rewrite text logging system (#2439)

* minor cleanup

* enable mailboxes

* priority

* implement new logger

* more cleaning

* signature

* remove debug

* put the assertion back in

* remove debugging

* spelling

* doy

* tweaks & comments

* cleaning

* size_t

* guard more

* test build now

* needs more ram until we can remove LogginWithSTorage

* hunt for memory

* bootloader

* unused

* stub simulator

* it would help to get the signature right

* geez kinetis only has 64k ram

* more guarding because kinetis

* that's now very legal and very cool

* templatify

* s

* force null terminate

* probably fix

* const

* write a test

* disable sensor chart for now

* hide SC ui

* oh nope that breaks many things

This reverts commit c3c1bb324fb484c3d9cc44b7715c234bc0392e1e.

* missed one

* reset after scheduleLogging

* we can't print out the full message because it contains commas which break parsing

* force terminate long buffers

* let's see how much memory we have to play with

* a lot, is the answer

* real thread name

* shrink this for now before its deleted

* turn that back on

* biiig comment

Co-authored-by: Matthew Kennedy <makenne@microsoft.com>

firmware/bootloader/src/rusefi_stubs.cpp

@@ -12,7 +12,10 @@
 void chDbgPanic3(const char* /*msg*/, const char* /*file*/, int /*line*/) {
 }
 
-void scheduleMsg(Logging* /*logging*/, const char* /*fmt*/, ...) {
+namespace priv
+{
+void efiPrintfInternal(const char* /*fmt*/, ...) {
+}
 }
 
 void firmwareError(obd_code_e /*code*/, const char* /*fmt*/, ...) {

firmware/controllers/engine_controller.cpp

@@ -709,7 +709,7 @@ void initEngineContoller(Logging *sharedLogger DECLARE_ENGINE_PARAMETER_SUFFIX)
  * UNUSED_SIZE constants.
  */
 #ifndef RAM_UNUSED_SIZE
-#define RAM_UNUSED_SIZE 4350
+#define RAM_UNUSED_SIZE 2000
 #endif
 #ifndef CCM_UNUSED_SIZE
 #define CCM_UNUSED_SIZE 2000

firmware/controllers/thread_priority.h

@@ -25,7 +25,10 @@
 #define PRIO_CJ125 (NORMALPRIO + 5)
 
 // Console thread 
-#define PRIO_CONSOLE (NORMALPRIO + 1)
+#define PRIO_CONSOLE (NORMALPRIO + 3)
+
+// Logging buffer flush is *slightly* above NORMALPRIO so that we don't starve logging buffers during initialization
+#define PRIO_TEXT_LOG (NORMALPRIO + 1)
 
 // Less important things
 #define PRIO_MMC (NORMALPRIO - 1)

firmware/hw_layer/ports/stm32/stm32f4/cfg/chconf.h

@@ -345,7 +345,7 @@
  * @note    Requires @p CH_CFG_USE_SEMAPHORES.
  */
 #if !defined(CH_CFG_USE_MAILBOXES)
-#define CH_CFG_USE_MAILBOXES                FALSE
+#define CH_CFG_USE_MAILBOXES                TRUE
 #endif
 
 /**

firmware/hw_layer/ports/stm32/stm32f7/cfg/chconf.h

@@ -345,7 +345,7 @@
  * @note    Requires @p CH_CFG_USE_SEMAPHORES.
  */
 #if !defined(CH_CFG_USE_MAILBOXES)
-#define CH_CFG_USE_MAILBOXES                FALSE
+#define CH_CFG_USE_MAILBOXES                TRUE
 #endif
 
 /**

firmware/hw_layer/ports/stm32/stm32h7/cfg/chconf.h

@@ -329,7 +329,7 @@
  * @note    Requires @p CH_CFG_USE_SEMAPHORES.
  */
 #if !defined(CH_CFG_USE_MAILBOXES)
-#define CH_CFG_USE_MAILBOXES                FALSE
+#define CH_CFG_USE_MAILBOXES                TRUE
 #endif
 
 /**

firmware/rusefi.cpp

@@ -175,6 +175,12 @@ void runRusEfi(void) {
 	efiAssertVoid(CUSTOM_RM_STACK_1, getCurrentRemainingStack() > 512, "init s");
 	assertEngineReference();
 	engine->setConfig();
+
+#if EFI_TEXT_LOGGING
+	// Initialize logging system early - we can't log until this is called
+	startLoggingProcessor();
+#endif
+
 	addConsoleAction(CMD_REBOOT, scheduleReboot);
 	addConsoleAction(CMD_REBOOT_DFU, jump_to_bootloader);
 

firmware/util/datalogging.h

@@ -72,25 +72,10 @@ public:
 class LoggingWithStorage : public Logging {
 public:
 	explicit LoggingWithStorage(const char *name);
-	char DEFAULT_BUFFER[200];
+	char DEFAULT_BUFFER[100];
 };
 
 void initLoggingExt(Logging *logging, const char *name, char *buffer, int bufferSize);
 
 void appendMsgPrefix(Logging *logging);
 void appendMsgPostfix(Logging *logging);
-
-
-#ifdef __cplusplus
-extern "C"
-{
-#endif /* __cplusplus */
-/**
- * this method copies the line into the intermediate buffer for later output by
- * the main thread
- */
-void scheduleLogging(Logging *logging);
-
-#ifdef __cplusplus
-}
-#endif /* __cplusplus */

firmware/util/loggingcentral.cpp

@@ -1,147 +1,185 @@
 /**
  * @file	loggingcentral.cpp
  *
+ * This file implements text logging.
  * 
- * As of May 2019 we have given up on text-based 'push' terminal mode. At the moment binary protocol
+ * Uses a queue of buffers so that the expensive printf operation doesn't require exclusive access
- * is the consumen of this logging buffer.
+ * (ie, global system lock) to log.  In the past there have been serious performance problems caused
+ * by heavy logging on a low prioriy thread that blocks the rest of the system running (trigger errors, etc).
  * 
- * @date Mar 8, 2015
+ * Uses ChibiOS message queues to maintain one queue of free buffers, and one queue of used buffers.
- * @author Andrey Belomutskiy, (c) 2012-2020
+ * When a thread wants to write, it acquires a free buffer, prints to it, and pushes it in to the
+ * used queue. A dedicated thread then dequeues and writes lines from the used buffer in to the
+ * large output buffer.
+ * 
+ * Later, the binary TS thread will request access to the output log buffer for reading, so a lock is taken,
+ * buffers, swapped, and the back buffer returned.  This blocks neither output nor logging in any case, as
+ * each operation operates on a different buffer.
+ *
+ * @date Mar 8, 2015, heavily revised April 2021
+ * @author Andrey Belomutskiy, (c) 2012-2021
+ * @author Matthew Kennedy
  */
 
 #include "global.h"
 #include "os_access.h"
 #include "efilib.h"
+#include "loggingcentral.h"
+#include "thread_controller.h"
+#include "thread_priority.h"
 
-#if EFI_UNIT_TEST || EFI_SIMULATOR
+template <size_t TBufferSize>
-extern bool verboseMode;
+void LogBuffer<TBufferSize>::writeLine(LogLineBuffer* line) {
-#endif /* EFI_UNIT_TEST */
+	writeInternal(line->buffer);
-
-typedef char log_buf_t[DL_OUTPUT_BUFFER];
-
-/**
- * we need to leave a byte for zero terminator, also two bytes for the \r\n in
- * printWithLength, also couple of bytes just in case
- */
-#define MAX_DL_CAPACITY (DL_OUTPUT_BUFFER - 5)
-
-/**
- * This is the buffer into which all the data providers write
- */
-static char *accumulationBuffer;
-
-static log_buf_t pendingBuffers0;
-static log_buf_t pendingBuffers1;
-
-/**
- * We copy all the pending data into this buffer once we are ready to push it out
- */
-static char * outputBuffer;
-
-
-class LoggingCentral {
-public:
-	/**
-	 * Class constructors are a great way to have simple initialization sequence
-	 */
-	LoggingCentral() {
-		pendingBuffers0[0] = 0;
-		pendingBuffers1[0] = 0;
-		accumulationBuffer = pendingBuffers0;
-		outputBuffer = pendingBuffers1;
-		accumulatedSize = 0;
-	}
-
-	/**
-	 * amount of data accumulated so far
-	 */
-	uint32_t accumulatedSize;
-};
-
-static LoggingCentral loggingCentral;
-
-
-/**
- * This method appends the content of specified thread-local logger into the global buffer
- * of logging content.
- */
-static void scheduleLoggingInternal(Logging *logging) {
-#if EFI_TEXT_LOGGING
-#ifdef EFI_PRINT_MESSAGES_TO_TERMINAL
-	print(logging->buffer);
-	print("\r\n");
-#endif /* EFI_PRINT_MESSAGES_TO_TERMINAL */
-	// this could be done without locking
-	int newLength = efiStrlen(logging->buffer);
-
-	chibios_rt::CriticalSectionLocker csl;
-	if (loggingCentral.accumulatedSize + newLength >= MAX_DL_CAPACITY) {
-		/**
-		 * if no one is consuming the data we have to drop it
-		 * this happens in case of serial-over-USB, todo: find a better solution?
-		 */
-		return;
-	}
-	// memcpy is faster then strcpy because it is not looking for line terminator
-	memcpy(accumulationBuffer + loggingCentral.accumulatedSize, logging->buffer, newLength + 1);
-	loggingCentral.accumulatedSize += newLength;
-#endif /* EFI_TEXT_LOGGING */
 }
 
-void scheduleLogging(Logging* logging) {
+template <size_t TBufferSize>
-	scheduleLoggingInternal(logging);
+void LogBuffer<TBufferSize>:: writeLogger(Logging* logging) {
-	logging->reset();
+	writeInternal(logging->buffer);
 }
 
+template <size_t TBufferSize>
+size_t LogBuffer<TBufferSize>::length() const {
+	return m_writePtr - m_buffer;
+}
+
+template <size_t TBufferSize>
+void LogBuffer<TBufferSize>::reset() {
+	m_writePtr = m_buffer;
+	memset(m_buffer, 0, TBufferSize);
+}
+
+template <size_t TBufferSize>
+const char* LogBuffer<TBufferSize>::get() const {
+	return m_buffer;
+}
+
+template <size_t TBufferSize>
+void LogBuffer<TBufferSize>::writeInternal(const char* buffer) {
+	size_t len = efiStrlen(buffer);
+	// leave one byte extra at the end to guarantee room for a null terminator
+	size_t available = TBufferSize - length() - 1;
+
+	// If we can't fit the whole thing, write as much as we can
+	len = minI(available, len);
+	memcpy(m_writePtr, buffer, len);
+	m_writePtr += len;
+
+	// Ensure the output buffer is always null terminated (in case we did a partial write)
+	*m_writePtr = '\0';
+}
+
+// for unit tests
+template class LogBuffer<10>;
+
+#if EFI_PROD_CODE && EFI_TEXT_LOGGING
+
+// This mutex protects the LogBuffer instances below
+chibios_rt::Mutex logBufferMutex;
+
+// Two buffers:
+//  - we copy line buffers to writeBuffer in LoggingBufferFlusher
+//  - and read from readBuffer via TunerStudio protocol commands
+using LB = LogBuffer<DL_OUTPUT_BUFFER>;
+LB buffers[2];
+LB* writeBuffer = &buffers[0];
+LB* readBuffer = &buffers[1];
+
 /**
  * Actual communication layer invokes this method when it's ready to send some data out
  *
- * this method should always be invoked from the same thread!
  * @return pointer to the buffer which should be print to console
  */
 const char* swapOutputBuffers(size_t* actualOutputBufferSize) {
-#if EFI_ENABLE_ASSERTS
+	{
-	int expectedOutputSize;
+		chibios_rt::MutexLocker lock(logBufferMutex);
-#endif /* EFI_ENABLE_ASSERTS */
-	{ // start of critical section
-		chibios_rt::CriticalSectionLocker csl;
-		/**
-		 * we cannot output under syslock, we simply rotate which buffer is which
-		 */
-		char *temp = outputBuffer;
 
-#if EFI_ENABLE_ASSERTS
+		// Swap buffers under lock
-		expectedOutputSize = loggingCentral.accumulatedSize;
+		auto temp = writeBuffer;
-#endif /* EFI_ENABLE_ASSERTS */
+		writeBuffer = readBuffer;
-		outputBuffer = accumulationBuffer;
+		readBuffer = temp;
 
-		accumulationBuffer = temp;
+		// Reset the front buffer - it's now empty
-		loggingCentral.accumulatedSize = 0;
+		writeBuffer->reset();
-		accumulationBuffer[0] = 0;
+	}
-	} // end of critical section
 
-	*actualOutputBufferSize = efiStrlen(outputBuffer);
+	*actualOutputBufferSize = readBuffer->length();
 #if EFI_ENABLE_ASSERTS
+	size_t expectedOutputSize = efiStrlen(readBuffer->get());
+
+	// Check that the actual length of the buffer matches the expected length of how much we thought we wrote
 	if (*actualOutputBufferSize != expectedOutputSize) {
-		int sizeToShow = minI(10, *actualOutputBufferSize);
+		firmwareError(ERROR_LOGGING_SIZE_CALC, "lsize mismatch %d vs strlen %d", *actualOutputBufferSize, expectedOutputSize);
-		int offsetToShow = *actualOutputBufferSize - sizeToShow;
+
-		firmwareError(ERROR_LOGGING_SIZE_CALC, "lsize mismatch %d/%d [%s]", *actualOutputBufferSize, expectedOutputSize,
+		return nullptr;
-				&outputBuffer[offsetToShow]);
-		return NULL;
 	}
 #endif /* EFI_ENABLE_ASSERTS */
-	return outputBuffer;
+	return readBuffer->get();
 }
 
-/**
+// These buffers store lines queued to be written to the writeBuffer
- * rusEfi business logic invokes this method in order to eventually print stuff to rusEfi console
+constexpr size_t lineBufferCount = 24;
- *
+static LogLineBuffer lineBuffers[lineBufferCount];
- * this whole method is executed under syslock so that we can have multiple threads use the same shared buffer
+
- * in order to reduce memory usage
+// freeBuffers contains a queue of buffers that are not in use
- *
+chibios_rt::Mailbox<LogLineBuffer*, lineBufferCount> freeBuffers;
- * this is really 'global lock + printf + scheduleLogging + unlock' a bit more clear
+// filledBuffers contains a queue of buffers currently waiting to be written to the output buffer
- */
+chibios_rt::Mailbox<LogLineBuffer*, lineBufferCount> filledBuffers;
-void scheduleMsg(Logging *logging, const char *format, ...) {
+
+class LoggingBufferFlusher : public ThreadController<256> {
+public:
+	LoggingBufferFlusher() : ThreadController("log flush", PRIO_TEXT_LOG) { }
+
+	void ThreadTask() override {
+		while (true) {
+			// Fetch a queued message
+			LogLineBuffer* line;
+			msg_t msg = filledBuffers.fetch(&line, TIME_INFINITE);
+
+			if (msg == MSG_RESET) {
+				// todo?
+				// what happens if MSG_RESET?
+			} else {
+				// Lock the buffer mutex - inhibit buffer swaps while writing
+				chibios_rt::MutexLocker lock(logBufferMutex);
+
+				// Write the line out to the output buffer
+				writeBuffer->writeLine(line);
+
+				// Return this line buffer to the free list
+				freeBuffers.post(line, TIME_INFINITE);
+			}
+		}
+	}
+};
+
+static LoggingBufferFlusher lbf;
+
+void startLoggingProcessor() {
+	// Push all buffers in to the free queue
+	for (size_t i = 0; i < lineBufferCount; i++) {
+		freeBuffers.post(&lineBuffers[i], TIME_INFINITE);
+	}
+
+	// Start processing used buffers
+	lbf.Start();
+}
+
+#endif // EFI_PROD_CODE
+
+#if EFI_SIMULATOR
+const char* swapOutputBuffers(size_t* actualOutputBufferSize) {
+	return nullptr;
+}
+#endif
+
+#if EFI_UNIT_TEST || EFI_SIMULATOR
+extern bool verboseMode;
+#endif
+
+namespace priv
+{
+void efiPrintfInternal(const char *format, ...) {
 #if EFI_UNIT_TEST || EFI_SIMULATOR
 	if (verboseMode) {
 		va_list ap;
@@ -150,29 +188,66 @@ void scheduleMsg(Logging *logging, const char *format, ...) {
 		va_end(ap);
 		printf("\r\n");
 	}
-#else
+#endif
-	for (unsigned int i = 0;i<strlen(format);i++) {
+#if EFI_PROD_CODE && EFI_TEXT_LOGGING
+	for (unsigned int i = 0; i < strlen(format); i++) {
 		// todo: open question which layer would not handle CR/LF properly?
 		efiAssertVoid(OBD_PCM_Processor_Fault, format[i] != '\n', "No CRLF please");
 	}
-#if EFI_TEXT_LOGGING
+
-	if (logging == NULL) {
+	LogLineBuffer* lineBuffer;
-		warning(CUSTOM_ERR_LOGGING_NULL, "logging NULL");
+	msg_t msg;
+
+	{
+		// Acquire a buffer we can write to
+		chibios_rt::CriticalSectionLocker csl;
+		msg = freeBuffers.fetchI(&lineBuffer);
+	}
+
+	// No free buffers available, so we can't log
+	if (msg != MSG_OK) {
 		return;
 	}
 
-	chibios_rt::CriticalSectionLocker csl;
+	// Write the formatted string to the output buffer
-	logging->reset(); // todo: is 'reset' really needed here?
-	appendMsgPrefix(logging);
-
 	va_list ap;
 	va_start(ap, format);
-	logging->vappendPrintf(format, ap);
+	chvsnprintf(lineBuffer->buffer, sizeof(lineBuffer->buffer), format, ap);
 	va_end(ap);
 
-	appendMsgPostfix(logging);
+	// Ensure that the string is comma-terminated in case it overflowed
-	scheduleLogging(logging);
+	lineBuffer->buffer[sizeof(lineBuffer->buffer) - 1] = ',';
-#endif /* EFI_TEXT_LOGGING */
-#endif /* EFI_UNIT_TEST */
-}
 
+	{
+		// Push the buffer in to the written list so it can be written back
+		chibios_rt::CriticalSectionLocker csl;
+
+		if ((void*)lineBuffer == (void*)&filledBuffers) {
+			__asm volatile("BKPT #0\n");
+		}
+
+		filledBuffers.postI(lineBuffer);
+	}
+#endif
+}
+} // namespace priv
+
+/**
+ * This method appends the content of specified thread-local logger into the global buffer
+ * of logging content.
+ * 
+ * This is a legacy function, most normal logging should use scheduleMsg
+ */
+void scheduleLogging(Logging *logging) {
+#if EFI_PROD_CODE && EFI_TEXT_LOGGING
+	// Lock the buffer mutex - inhibit buffer swaps while writing
+	{
+		chibios_rt::MutexLocker lock(logBufferMutex);
+
+		writeBuffer->writeLogger(logging);
+	}
+
+	// Reset the logging now that it's been written out
+	logging->reset();
+#endif
+}

firmware/util/loggingcentral.h

@@ -6,7 +6,49 @@
  */
 #pragma once
 
+#include <cstddef>
+
 class Logging;
 
-const char* swapOutputBuffers(size_t* actualOutputBufferSize);
+void startLoggingProcessor();
-void scheduleMsg(Logging *logging, const char *fmt, ...);
+
+const char* swapOutputBuffers(size_t *actualOutputBufferSize);
+
+namespace priv
+{
+	// internal implementation, use scheduleMsg below
+	void efiPrintfInternal(const char *fmt, ...);
+}
+
+// "normal" logging messages need a header and footer, so put them in
+// the format string at compile time
+#define scheduleMsg(logging, fmt, ...) priv::efiPrintfInternal(PROTOCOL_MSG DELIMETER fmt DELIMETER, ##__VA_ARGS__)
+
+/**
+ * This is the legacy function to copy the contents of a local Logging object in to the output buffer
+ */
+void scheduleLogging(Logging *logging);
+
+// Stores the result of one call to efiPrintfInternal in the queue to be copied out to the output buffer
+struct LogLineBuffer {
+	char buffer[128];
+};
+
+template <size_t TBufferSize>
+class LogBuffer {
+public:
+	void writeLine(LogLineBuffer* line);
+	void writeLogger(Logging* logging);
+
+	size_t length() const;
+	void reset();
+	const char* get() const;
+
+#if !EFI_UNIT_TEST
+private:
+#endif
+	void writeInternal(const char* buffer);
+
+	char m_buffer[TBufferSize];
+	char* m_writePtr = m_buffer;
+};

unit_tests/tests/test_log_buffer.cpp

@@ -0,0 +1,38 @@
+#include "loggingcentral.h"
+#include <gtest/gtest.h>
+#include <gmock/gmock.h>
+
+using ::testing::ElementsAre;
+
+TEST(logBuffer, writeSmall) {
+	LogBuffer<10> dut;
+	memset(dut.m_buffer, 0x55, sizeof(dut.m_buffer));
+
+	LogLineBuffer line;
+
+	strcpy(line.buffer, "test");
+
+	dut.writeLine(&line);
+
+	EXPECT_THAT(dut.m_buffer, ElementsAre(
+		't', 'e', 's', 't', '\0',	// this part got copied in
+		0x55, 0x55, 0x55, 0x55, 0x55	// rest of the buffer is untouched
+	));
+}
+
+TEST(logBuffer, writeOverflow) {
+	LogBuffer<10> dut;
+	memset(dut.m_buffer, 0x55, sizeof(dut.m_buffer));
+
+	LogLineBuffer line;
+
+	strcpy(line.buffer, "testtesttest");
+
+	dut.writeLine(&line);
+
+	EXPECT_THAT(dut.m_buffer, ElementsAre(
+		't', 'e', 's', 't',
+		't', 'e', 's', 't',
+		't', 0
+	));
+}

unit_tests/tests/tests.mk

@@ -40,6 +40,7 @@ TESTS_SRC_CPP = \
 	tests/test_tunerstudio.cpp \
 	tests/test_pwm_generator.cpp \
 	tests/test_logic_expression.cpp \
+	tests/test_log_buffer.cpp \
 	tests/test_signal_executor.cpp \
 	tests/test_cpp_memory_layout.cpp \
 	tests/test_sensors.cpp \