/** * @file loggingcentral.cpp * * This file implements text logging. * * Uses a queue of buffers so that the expensive printf operation doesn't require exclusive access * (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). * * Uses ChibiOS message queues to maintain one queue of free buffers, and one queue of used buffers. * 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 "pch.h" #include "thread_controller.h" /* for isprint() */ #include template void LogBuffer::writeLine(LogLineBuffer* line) { writeInternal(line->buffer); } template void LogBuffer:: writeLogger(Logging* logging) { writeInternal(logging->buffer); } template size_t LogBuffer::length() const { return m_writePtr - m_buffer; } template void LogBuffer::reset() { m_writePtr = m_buffer; memset(m_buffer, 0, TBufferSize); } template const char* LogBuffer::get() const { return m_buffer; } template void LogBuffer::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_SIMULATOR) && 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; 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 * * @return pointer to the buffer which should be print to console */ const char* swapOutputBuffers(size_t* actualOutputBufferSize) { { chibios_rt::MutexLocker lock(logBufferMutex); // Swap buffers under lock auto temp = writeBuffer; writeBuffer = readBuffer; readBuffer = temp; // Reset the front buffer - it's now empty writeBuffer->reset(); } *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) { firmwareError(ObdCode::ERROR_LOGGING_SIZE_CALC, "lsize mismatch %d vs strlen %d", *actualOutputBufferSize, expectedOutputSize); return nullptr; } #endif /* EFI_ENABLE_ASSERTS */ return readBuffer->get(); } // These buffers store lines queued to be written to the writeBuffer constexpr size_t lineBufferCount = 24; static LogLineBuffer lineBuffers[lineBufferCount]; // freeBuffers contains a queue of buffers that are not in use static chibios_rt::Mailbox freeBuffers; // filledBuffers contains a queue of buffers currently waiting to be written to the output buffer static chibios_rt::Mailbox filledBuffers; class LoggingBufferFlusher : public ThreadController { 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_UNIT_TEST || EFI_SIMULATOR extern bool verboseMode; #endif namespace priv { void efiPrintfInternal(const char *format, ...) { #if EFI_UNIT_TEST || EFI_SIMULATOR if (verboseMode) { printf("efiPrintfInternal:"); va_list ap; va_start(ap, format); vprintf(format, ap); va_end(ap); printf("\r\n"); } #endif #if (EFI_PROD_CODE || EFI_SIMULATOR) && EFI_TEXT_LOGGING LogLineBuffer* lineBuffer; 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; } // Write the formatted string to the output buffer va_list ap; va_start(ap, format); size_t len = chvsnprintf(lineBuffer->buffer, sizeof(lineBuffer->buffer), format, ap); va_end(ap); // Ensure that the string is comma-terminated in case it overflowed lineBuffer->buffer[sizeof(lineBuffer->buffer) - 1] = LOG_DELIMITER[0]; if (len > sizeof(lineBuffer->buffer) - 1) len = sizeof(lineBuffer->buffer) - 1; for (size_t i = 0; i < len; i++) { /* just replace all non-printable chars with space * TODO: is there any other "prohibited" chars? */ if (isprint(lineBuffer->buffer[i]) == 0) lineBuffer->buffer[i] = ' '; } { // Push the buffer in to the written list so it can be written back chibios_rt::CriticalSectionLocker csl; 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 efiPrintf */ void scheduleLogging(Logging *logging) { #if (EFI_PROD_CODE || EFI_SIMULATOR) && 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 }