GCC Code Coverage Report


Directory: ./
File: firmware/util/loggingcentral.cpp
Date: 2025-10-03 00:57:22
Coverage Exec Excl Total
Lines: 48.5% 16 0 33
Functions: 50.0% 4 0 8
Branches: 16.7% 1 0 6
Decisions: 50.0% 1 - 2

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 44717 void efiPrintfInternal(const char *format, ...) {
178 #if EFI_UNIT_TEST || EFI_SIMULATOR
179
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 44717 times.
1/2
✗ Decision 'true' not taken.
✓ Decision 'false' taken 44717 times.
44717 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 44717 }
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