firmware/util/loggingcentral.cpp - GCC Code Coverage Report

Directory:	./
File:	firmware/util/loggingcentral.cpp
Date:	2025-10-23 21:17:20

	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
    
      /**
    
       * @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 priority 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 <ctype.h>
    
      template <size_t TBufferSize>
    
      2
      void LogBuffer<TBufferSize>::writeLine(LogLineBuffer* line) {
    
      2
      	writeInternal(line->buffer);
    
      2
      }
    
      template <size_t TBufferSize>
    
      ✗
      void LogBuffer<TBufferSize>:: writeLogger(Logging* logging) {
    
      ✗
      	writeInternal(logging->buffer);
    
      ✗
      }
    
      template <size_t TBufferSize>
    
      2
      size_t LogBuffer<TBufferSize>::length() const {
    
      2
      	return m_writePtr - m_buffer;
    
      }
    
      template <size_t TBufferSize>
    
      ✗
      void LogBuffer<TBufferSize>::reset() {
    
      ✗
      	m_writePtr = m_buffer;
    
      ✗
      	*m_writePtr = '\0';
    
      ✗
      }
    
      template <size_t TBufferSize>
    
      ✗
      const char* LogBuffer<TBufferSize>::get() const {
    
      ✗
      	return m_buffer;
    
      }
    
      template <size_t TBufferSize>
    
      2
      void LogBuffer<TBufferSize>::writeInternal(const char* buffer) {
    
      2
      	size_t len = std::strlen(buffer);
    
      	// leave one byte extra at the end to guarantee room for a null terminator
    
      2
      	size_t available = TBufferSize - length() - 1;
    
      	// If we can't fit the whole thing, write as much as we can
    
      2
      	len = minI(available, len);
    
      	// Ensure the output buffer is always null terminated (in case we did a partial write)
    
      2
      	*(m_writePtr + len) = '\0';
    
      2
      	memcpy(m_writePtr, buffer, len);
    
      2
      	m_writePtr += len;
    
      2
      }
    
      // 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<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
    
       *
    
       * @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 = std::strlen(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<LogLineBuffer*, lineBufferCount> freeBuffers;
    
      // filledBuffers contains a queue of buffers currently waiting to be written to the output buffer
    
      static chibios_rt::Mailbox<LogLineBuffer*, lineBufferCount> filledBuffers;
    
      class LoggingBufferFlusher : public ThreadController<UTILITY_THREAD_STACK_SIZE> {
    
      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_OK) {
    
      				// This should be impossible - neither timeout or reset should happen
    
      			} 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
    
      {
    
      60192
      void efiPrintfInternal(const char *format, ...) {
    
      #if EFI_UNIT_TEST || EFI_SIMULATOR
    
        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) {
    
      ✗
      		printf("[%dus]efiPrintfInternal:", time2print(getTimeNowUs()));
    
      ✗
      		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
    
      60192
      }
    
      } // 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
    
      ✗
      }

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

Function (Line)	Call count	Line coverage	Branch coverage	Block coverage
LogBuffer<10ul>::get() const (line 54)	not called	0.0%	-%	0.0%
LogBuffer<10ul>::length() const (line 43)	called 2 times	100.0%	-%	100.0%
LogBuffer<10ul>::reset() (line 48)	not called	0.0%	-%	0.0%
LogBuffer<10ul>::writeInternal(char const*) (line 59)	called 2 times	100.0%	-%	100.0%
LogBuffer<10ul>::writeLine(LogLineBuffer*) (line 33)	called 2 times	100.0%	-%	100.0%
LogBuffer<10ul>::writeLogger(Logging*) (line 38)	not called	0.0%	-%	0.0%
priv::efiPrintfInternal(char const*, ...) (line 177)	called 60192 times	33.3%	16.7%	27.0%
scheduleLogging(Logging*) (line 237)	not called	0.0%	-%	0.0%