| Line | Branch | Decision | Exec | Source |
|---|---|---|---|---|
| 1 | /** | |||
| 2 | * @file loggingcentral.cpp | |||
| 3 | * | |||
| 4 | * This file implements text logging. | |||
| 5 | * | |||
| 6 | * Uses a queue of buffers so that the expensive printf operation doesn't require exclusive access | |||
| 7 | * (ie, global system lock) to log. In the past there have been serious performance problems caused | |||
| 8 | * by heavy logging on a low priority thread that blocks the rest of the system running (trigger errors, etc). | |||
| 9 | * | |||
| 10 | * Uses ChibiOS message queues to maintain one queue of free buffers, and one queue of used buffers. | |||
| 11 | * When a thread wants to write, it acquires a free buffer, prints to it, and pushes it in to the | |||
| 12 | * used queue. A dedicated thread then dequeues and writes lines from the used buffer in to the | |||
| 13 | * large output buffer. | |||
| 14 | * | |||
| 15 | * Later, the binary TS thread will request access to the output log buffer for reading, so a lock is taken, | |||
| 16 | * buffers, swapped, and the back buffer returned. This blocks neither output nor logging in any case, as | |||
| 17 | * each operation operates on a different buffer. | |||
| 18 | * | |||
| 19 | * @date Mar 8, 2015, heavily revised April 2021 | |||
| 20 | * @author Andrey Belomutskiy, (c) 2012-2021 | |||
| 21 | * @author Matthew Kennedy | |||
| 22 | */ | |||
| 23 | ||||
| 24 | #include "pch.h" | |||
| 25 | ||||
| 26 | ||||
| 27 | #include "thread_controller.h" | |||
| 28 | ||||
| 29 | /* for isprint() */ | |||
| 30 | #include <ctype.h> | |||
| 31 | ||||
| 32 | template <size_t TBufferSize> | |||
| 33 | 2 | void LogBuffer<TBufferSize>::writeLine(LogLineBuffer* line) { | ||
| 34 | 2 | writeInternal(line->buffer); | ||
| 35 | 2 | } | ||
| 36 | ||||
| 37 | template <size_t TBufferSize> | |||
| 38 | ✗ | void LogBuffer<TBufferSize>:: writeLogger(Logging* logging) { | ||
| 39 | ✗ | writeInternal(logging->buffer); | ||
| 40 | ✗ | } | ||
| 41 | ||||
| 42 | template <size_t TBufferSize> | |||
| 43 | 2 | size_t LogBuffer<TBufferSize>::length() const { | ||
| 44 | 2 | return m_writePtr - m_buffer; | ||
| 45 | } | |||
| 46 | ||||
| 47 | template <size_t TBufferSize> | |||
| 48 | ✗ | void LogBuffer<TBufferSize>::reset() { | ||
| 49 | ✗ | m_writePtr = m_buffer; | ||
| 50 | ✗ | *m_writePtr = '\0'; | ||
| 51 | ✗ | } | ||
| 52 | ||||
| 53 | template <size_t TBufferSize> | |||
| 54 | ✗ | const char* LogBuffer<TBufferSize>::get() const { | ||
| 55 | ✗ | return m_buffer; | ||
| 56 | } | |||
| 57 | ||||
| 58 | template <size_t TBufferSize> | |||
| 59 | 2 | void LogBuffer<TBufferSize>::writeInternal(const char* buffer) { | ||
| 60 | 2 | size_t len = std::strlen(buffer); | ||
| 61 | // leave one byte extra at the end to guarantee room for a null terminator | |||
| 62 | 2 | size_t available = TBufferSize - length() - 1; | ||
| 63 | ||||
| 64 | // If we can't fit the whole thing, write as much as we can | |||
| 65 | 2 | len = minI(available, len); | ||
| 66 | // Ensure the output buffer is always null terminated (in case we did a partial write) | |||
| 67 | 2 | *(m_writePtr + len) = '\0'; | ||
| 68 | 2 | memcpy(m_writePtr, buffer, len); | ||
| 69 | 2 | m_writePtr += len; | ||
| 70 | 2 | } | ||
| 71 | ||||
| 72 | // for unit tests | |||
| 73 | template class LogBuffer<10>; | |||
| 74 | ||||
| 75 | #if (EFI_PROD_CODE || EFI_SIMULATOR) && EFI_TEXT_LOGGING | |||
| 76 | ||||
| 77 | // This mutex protects the LogBuffer instances below | |||
| 78 | chibios_rt::Mutex logBufferMutex; | |||
| 79 | ||||
| 80 | // Two buffers: | |||
| 81 | // - we copy line buffers to writeBuffer in LoggingBufferFlusher | |||
| 82 | // - and read from readBuffer via TunerStudio protocol commands | |||
| 83 | using LB = LogBuffer<DL_OUTPUT_BUFFER>; | |||
| 84 | LB buffers[2]; | |||
| 85 | LB* writeBuffer = &buffers[0]; | |||
| 86 | LB* readBuffer = &buffers[1]; | |||
| 87 | ||||
| 88 | /** | |||
| 89 | * Actual communication layer invokes this method when it's ready to send some data out | |||
| 90 | * | |||
| 91 | * @return pointer to the buffer which should be print to console | |||
| 92 | */ | |||
| 93 | const char* swapOutputBuffers(size_t* actualOutputBufferSize) { | |||
| 94 | { | |||
| 95 | chibios_rt::MutexLocker lock(logBufferMutex); | |||
| 96 | ||||
| 97 | // Swap buffers under lock | |||
| 98 | auto temp = writeBuffer; | |||
| 99 | writeBuffer = readBuffer; | |||
| 100 | readBuffer = temp; | |||
| 101 | ||||
| 102 | // Reset the front buffer - it's now empty | |||
| 103 | writeBuffer->reset(); | |||
| 104 | } | |||
| 105 | ||||
| 106 | *actualOutputBufferSize = readBuffer->length(); | |||
| 107 | #if EFI_ENABLE_ASSERTS | |||
| 108 | size_t expectedOutputSize = std::strlen(readBuffer->get()); | |||
| 109 | ||||
| 110 | // Check that the actual length of the buffer matches the expected length of how much we thought we wrote | |||
| 111 | if (*actualOutputBufferSize != expectedOutputSize) { | |||
| 112 | firmwareError(ObdCode::ERROR_LOGGING_SIZE_CALC, "lsize mismatch %d vs strlen %d", *actualOutputBufferSize, expectedOutputSize); | |||
| 113 | ||||
| 114 | return nullptr; | |||
| 115 | } | |||
| 116 | #endif /* EFI_ENABLE_ASSERTS */ | |||
| 117 | return readBuffer->get(); | |||
| 118 | } | |||
| 119 | ||||
| 120 | // These buffers store lines queued to be written to the writeBuffer | |||
| 121 | constexpr size_t lineBufferCount = 24; | |||
| 122 | static LogLineBuffer lineBuffers[lineBufferCount]; | |||
| 123 | ||||
| 124 | // freeBuffers contains a queue of buffers that are not in use | |||
| 125 | static chibios_rt::Mailbox<LogLineBuffer*, lineBufferCount> freeBuffers; | |||
| 126 | // filledBuffers contains a queue of buffers currently waiting to be written to the output buffer | |||
| 127 | static chibios_rt::Mailbox<LogLineBuffer*, lineBufferCount> filledBuffers; | |||
| 128 | ||||
| 129 | class LoggingBufferFlusher : public ThreadController<UTILITY_THREAD_STACK_SIZE> { | |||
| 130 | public: | |||
| 131 | LoggingBufferFlusher() : ThreadController("log flush", PRIO_TEXT_LOG) { } | |||
| 132 | ||||
| 133 | void ThreadTask() override { | |||
| 134 | while (true) { | |||
| 135 | // Fetch a queued message | |||
| 136 | LogLineBuffer* line; | |||
| 137 | msg_t msg = filledBuffers.fetch(&line, TIME_INFINITE); | |||
| 138 | ||||
| 139 | if (msg != MSG_OK) { | |||
| 140 | // This should be impossible - neither timeout or reset should happen | |||
| 141 | } else { | |||
| 142 | { | |||
| 143 | // Lock the buffer mutex - inhibit buffer swaps while writing | |||
| 144 | chibios_rt::MutexLocker lock(logBufferMutex); | |||
| 145 | ||||
| 146 | // Write the line out to the output buffer | |||
| 147 | writeBuffer->writeLine(line); | |||
| 148 | } | |||
| 149 | ||||
| 150 | // Return this line buffer to the free list | |||
| 151 | freeBuffers.post(line, TIME_INFINITE); | |||
| 152 | } | |||
| 153 | } | |||
| 154 | } | |||
| 155 | }; | |||
| 156 | ||||
| 157 | static LoggingBufferFlusher lbf; | |||
| 158 | ||||
| 159 | void startLoggingProcessor() { | |||
| 160 | // Push all buffers in to the free queue | |||
| 161 | for (size_t i = 0; i < lineBufferCount; i++) { | |||
| 162 | freeBuffers.post(&lineBuffers[i], TIME_INFINITE); | |||
| 163 | } | |||
| 164 | ||||
| 165 | // Start processing used buffers | |||
| 166 | lbf.start(); | |||
| 167 | } | |||
| 168 | ||||
| 169 | #endif // EFI_PROD_CODE | |||
| 170 | ||||
| 171 | #if EFI_UNIT_TEST || EFI_SIMULATOR | |||
| 172 | extern bool verboseMode; | |||
| 173 | #endif | |||
| 174 | ||||
| 175 | namespace priv | |||
| 176 | { | |||
| 177 | 60192 | void efiPrintfInternal(const char *format, ...) { | ||
| 178 | #if EFI_UNIT_TEST || EFI_SIMULATOR | |||
| 179 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 60192 times.
|
1/2✗ Decision 'true' not taken.
✓ Decision 'false' taken 60192 times.
|
60192 | if (verboseMode) { |
| 180 | ✗ | printf("[%dus]efiPrintfInternal:", time2print(getTimeNowUs())); | ||
| 181 | ✗ | va_list ap; | ||
| 182 | ✗ | va_start(ap, format); | ||
| 183 | ✗ | vprintf(format, ap); | ||
| 184 | ✗ | va_end(ap); | ||
| 185 | ✗ | printf("\r\n"); | ||
| 186 | } | |||
| 187 | #endif | |||
| 188 | #if (EFI_PROD_CODE || EFI_SIMULATOR) && EFI_TEXT_LOGGING | |||
| 189 | LogLineBuffer* lineBuffer; | |||
| 190 | msg_t msg; | |||
| 191 | ||||
| 192 | { | |||
| 193 | // Acquire a buffer we can write to | |||
| 194 | chibios_rt::CriticalSectionLocker csl; | |||
| 195 | msg = freeBuffers.fetchI(&lineBuffer); | |||
| 196 | } | |||
| 197 | ||||
| 198 | // No free buffers available, so we can't log | |||
| 199 | if (msg != MSG_OK) { | |||
| 200 | return; | |||
| 201 | } | |||
| 202 | ||||
| 203 | // Write the formatted string to the output buffer | |||
| 204 | va_list ap; | |||
| 205 | va_start(ap, format); | |||
| 206 | size_t len = chvsnprintf(lineBuffer->buffer, sizeof(lineBuffer->buffer), format, ap); | |||
| 207 | va_end(ap); | |||
| 208 | ||||
| 209 | // Ensure that the string is comma-terminated in case it overflowed | |||
| 210 | lineBuffer->buffer[sizeof(lineBuffer->buffer) - 1] = LOG_DELIMITER[0]; | |||
| 211 | ||||
| 212 | if (len > sizeof(lineBuffer->buffer) - 1) | |||
| 213 | len = sizeof(lineBuffer->buffer) - 1; | |||
| 214 | for (size_t i = 0; i < len; i++) { | |||
| 215 | /* just replace all non-printable chars with space | |||
| 216 | * TODO: is there any other "prohibited" chars? */ | |||
| 217 | if (isprint(lineBuffer->buffer[i]) == 0) | |||
| 218 | lineBuffer->buffer[i] = ' '; | |||
| 219 | } | |||
| 220 | ||||
| 221 | { | |||
| 222 | // Push the buffer in to the written list so it can be written back | |||
| 223 | chibios_rt::CriticalSectionLocker csl; | |||
| 224 | ||||
| 225 | filledBuffers.postI(lineBuffer); | |||
| 226 | } | |||
| 227 | #endif | |||
| 228 | 60192 | } | ||
| 229 | } // namespace priv | |||
| 230 | ||||
| 231 | /** | |||
| 232 | * This method appends the content of specified thread-local logger into the global buffer | |||
| 233 | * of logging content. | |||
| 234 | * | |||
| 235 | * This is a legacy function, most normal logging should use efiPrintf | |||
| 236 | */ | |||
| 237 | ✗ | void scheduleLogging(Logging *logging) { | ||
| 238 | #if (EFI_PROD_CODE || EFI_SIMULATOR) && EFI_TEXT_LOGGING | |||
| 239 | // Lock the buffer mutex - inhibit buffer swaps while writing | |||
| 240 | { | |||
| 241 | chibios_rt::MutexLocker lock(logBufferMutex); | |||
| 242 | ||||
| 243 | writeBuffer->writeLogger(logging); | |||
| 244 | } | |||
| 245 | ||||
| 246 | // Reset the logging now that it's been written out | |||
| 247 | logging->reset(); | |||
| 248 | #endif | |||
| 249 | ✗ | } | ||
| 250 |