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 |