Add Serial buffer for performance improvement

src/debug.h

@@ -106,10 +106,8 @@
 #define USE_RUNTIME_CALIBRATION true
 #endif
 
-#define DEBUG_MEASURE_SENSOR_TIME_TAKEN false
-
-#ifndef DEBUG_MEASURE_SENSOR_TIME_TAKEN
-#define DEBUG_MEASURE_SENSOR_TIME_TAKEN false
+#ifndef DEBUG_MEASURE_TIME_TAKEN
+#define DEBUG_MEASURE_TIME_TAKEN false
 #endif
 
 #ifndef USE_OTA_TIMEOUT

src/debugging/Benchmark.cpp

@@ -0,0 +1,102 @@
+#include "Benchmark.h"
+#include <limits>
+#include "../debug.h"
+
+namespace SlimeVR::Debugging {
+
+Benchmark::Benchmark(const char *name)
+	: name{name}
+{}
+
+void Benchmark::before() {
+#if DEBUG_MEASURE_TIME_TAKEN
+	if (!registered) {
+		benchmarkInstances.push_back(this);
+		registered = true;
+	}
+
+	currentMeasurementStartMicros = micros();
+#endif
+}
+
+void Benchmark::after() {
+#if DEBUG_MEASURE_TIME_TAKEN
+	auto timeTakenMicros = micros() - currentMeasurementStartMicros;
+
+	totalTimeTakenMicros += timeTakenMicros;
+	minTimeTakenMicros = std::min(minTimeTakenMicros, timeTakenMicros);
+	maxTimeTakenMicros = std::max(maxTimeTakenMicros, timeTakenMicros);
+	measurementCount++;
+#endif
+}
+
+void Benchmark::tick() {
+#if DEBUG_MEASURE_TIME_TAKEN
+	totalLoops++;
+
+	auto timeSinceLastReport = millis() - lastReportMillis;
+	if (timeSinceLastReport < static_cast<uint32_t>(ReportsIntervalSeconds * 1000)) {
+		return;
+	}
+
+	auto printStartMicros = micros();
+	for (auto *instance : benchmarkInstances) {
+		instance->printReport();
+		instance->reset();
+	}
+	auto elapsedMicros = micros() - printStartMicros;
+	logger.info("Time total: %lu ms, loops: %u, report print time: %lu us",
+			timeSinceLastReport,
+			totalLoops,
+			elapsedMicros);
+
+	lastReportMillis = millis();
+	totalLoops = 0;
+#endif
+}
+
+void Benchmark::printReport() const {
+#if DEBUG_MEASURE_TIME_TAKEN
+	if (measurementCount == 0) {
+		return;
+	}
+
+	auto timeSinceLastReport = millis() - lastReportMillis;
+	uint64_t average = totalTimeTakenMicros / measurementCount;
+	float timeTakenPercent = static_cast<float>(totalTimeTakenMicros) / 1000.0f / timeSinceLastReport * 100.0f;
+
+	logger.info("%-24s | "
+			"avg: %5llu us | "
+			"min: %5llu us | "
+			"max: %5llu us | "
+			"time taken: %5llu ms or %5.2f%% of %lu ms | count: %u",
+			name,
+			average,
+			minTimeTakenMicros,
+			maxTimeTakenMicros,
+			totalTimeTakenMicros / 1000,
+			timeTakenPercent,
+			timeSinceLastReport,
+			measurementCount
+		);
+#endif
+}
+
+void Benchmark::reset() {
+#if DEBUG_MEASURE_TIME_TAKEN
+	totalTimeTakenMicros = 0;
+	minTimeTakenMicros = std::numeric_limits<uint64_t>::max();
+	maxTimeTakenMicros = 0;
+	measurementCount = 0;
+#endif
+}
+
+uint32_t Benchmark::lastReportMillis = millis();
+
+std::vector<Benchmark *> Benchmark::benchmarkInstances{};
+
+SlimeVR::Logging::Logger Benchmark::logger("Benchmark");
+
+uint32_t Benchmark::totalLoops = 0;
+
+}

src/debugging/TimeTaken.cpp → src/debugging/Benchmark.h

@@ -1,14 +1,17 @@
 /*
 	SlimeVR Code is placed under the MIT license
-	Copyright (c) 2025 Gorbit99 & SlimeVR Contributors
+	Copyright (c) 2026 Gorbit99, unlogisch04 & SlimeVR Contributors
+
 	Permission is hereby granted, free of charge, to any person obtaining a copy
 	of this software and associated documentation files (the "Software"), to deal
 	in the Software without restriction, including without limitation the rights
 	to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
 	copies of the Software, and to permit persons to whom the Software is
 	furnished to do so, subject to the following conditions:
+
 	The above copyright notice and this permission notice shall be included in
 	all copies or substantial portions of the Software.
+
 	THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 	IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 	FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
@@ -18,38 +21,50 @@
 	THE SOFTWARE.
 */
 
-#include "TimeTaken.h"
+#pragma once
+
+#include <Arduino.h>
+#include <cstdint>
+#include <limits>
+#include <cmath>
+#include <vector>
+#include "../logging/Logger.h"
 
 namespace SlimeVR::Debugging {
 
-TimeTakenMeasurer::TimeTakenMeasurer(const char* name)
-	: name{name} {}
+class Benchmark {
+public:
+	Benchmark(const char *name);
+	Benchmark(const Benchmark &other) = delete;
+	Benchmark(Benchmark &&other) = delete;
+	Benchmark &operator=(const Benchmark &other) = delete;
+	Benchmark &operator=(Benchmark &&other) = delete;
 
-void TimeTakenMeasurer::before() { startMicros = micros(); }
+	void before();
+	void after();
+	static void tick();
 
-void TimeTakenMeasurer::after() {
-	uint64_t elapsedMicros = micros() - startMicros;
-	timeTakenMicros += elapsedMicros;
+private:
+	static constexpr float ReportsIntervalSeconds = 10.0f;
 
-	uint64_t sinceLastReportMillis = millis() - lastTimeTakenReportMillis;
+	void printReport() const;
+	void reset();
 
-	if (sinceLastReportMillis < static_cast<uint64_t>(SecondsBetweenReports * 1e3)) {
-		return;
-	}
+	static uint32_t lastReportMillis;
 
-	float usedPercentage = static_cast<float>(timeTakenMicros) / 1e3f
-						 / static_cast<float>(sinceLastReportMillis) * 100;
+	uint64_t currentMeasurementStartMicros = 0;
 
-	m_Logger.info(
-		"%s: %.2f%% of the last period taken (%.2f/%lld millis)",
-		name,
-		usedPercentage,
-		timeTakenMicros / 1e3f,
-		sinceLastReportMillis
-	);
+	uint64_t totalTimeTakenMicros = 0;
+	uint64_t minTimeTakenMicros = std::numeric_limits<uint64_t>::max();
+	uint64_t maxTimeTakenMicros = 0;
+	uint32_t measurementCount = 0;
 
-	timeTakenMicros = 0;
-	lastTimeTakenReportMillis = millis();
-}
+	const char *name;
+	bool registered = false;
+
+	static SlimeVR::Logging::Logger logger;
+	static std::vector<Benchmark *> benchmarkInstances;
+	static uint32_t totalLoops;
+};
 
-}  // namespace SlimeVR::Debugging
+}

src/logging/Logger.cpp

@@ -1,6 +1,11 @@
 #include "Logger.h"
 
+#include "./SerialBuffer.h"
+
 namespace SlimeVR::Logging {
+
+SerialBuffer serialBuffer;
+
 void Logger::setTag(const char* tag) {
 	m_Tag = (char*)malloc(strlen(tag) + 1);
 	strcpy(m_Tag, tag);
@@ -63,6 +68,11 @@ void Logger::log(Level level, const char* format, va_list args) const {
 		strcat(buf, m_Tag);
 	}
 
-	Serial.printf("[%-5s] [%s] %s\n", levelToString(level), buf, buffer);
+	serialBuffer.printf("[%-5s] [%s] %s\n", levelToString(level), buf, buffer);
 }
+
+void Logger::tick() {
+	serialBuffer.tick();
+}
+
 }  // namespace SlimeVR::Logging

src/logging/Logger.h

@@ -33,61 +33,11 @@ class Logger {
 	void error(const char* str, ...) const __attribute__((format(printf, 2, 3)));
 	void fatal(const char* str, ...) const __attribute__((format(printf, 2, 3)));
 
-	template <typename T>
-	inline void traceArray(const char* str, const T* array, size_t size) const {
-		logArray(TRACE, str, array, size);
-	}
-
-	template <typename T>
-	inline void debugArray(const char* str, const T* array, size_t size) const {
-		logArray(DEBUG, str, array, size);
-	}
-
-	template <typename T>
-	inline void infoArray(const char* str, const T* array, size_t size) const {
-		logArray(INFO, str, array, size);
-	}
-
-	template <typename T>
-	inline void warnArray(const char* str, const T* array, size_t size) const {
-		logArray(WARN, str, array, size);
-	}
-
-	template <typename T>
-	inline void errorArray(const char* str, const T* array, size_t size) const {
-		logArray(ERROR, str, array, size);
-	}
-
-	template <typename T>
-	inline void fatalArray(const char* str, const T* array, size_t size) const {
-		logArray(FATAL, str, array, size);
-	}
+	static void tick();
 
 private:
 	void log(Level level, const char* str, va_list args) const;
 
-	template <typename T>
-	void logArray(Level level, const char* str, const T* array, size_t size) const {
-		if (level < LOG_LEVEL) {
-			return;
-		}
-
-		char buf[strlen(m_Prefix) + (m_Tag == nullptr ? 0 : strlen(m_Tag)) + 2];
-		strcpy(buf, m_Prefix);
-		if (m_Tag != nullptr) {
-			strcat(buf, ":");
-			strcat(buf, m_Tag);
-		}
-
-		Serial.printf("[%-5s] [%s] %s", levelToString(level), buf, str);
-
-		for (size_t i = 0; i < size; i++) {
-			Serial.print(array[i]);
-		}
-
-		Serial.println();
-	}
-
 	const char* const m_Prefix;
 	char* m_Tag;
 };

src/logging/SerialBuffer.cpp

@@ -0,0 +1,66 @@
+#include "SerialBuffer.h"
+#include <cstdarg>
+#include <cstdio>
+#include <cstring>
+
+namespace SlimeVR::Logging {
+
+SerialBuffer::SerialBuffer() {
+	buffer.resize(BufferSize);
+}
+
+void SerialBuffer::printf(const char *fmt, ...) {
+	va_list lst;
+	va_start(lst, fmt);
+	auto result = vsnprintf(printfBuffer, sizeof(printfBuffer), fmt, lst);
+	va_end(lst);
+	if (result < 0) {
+		 return;
+	}
+
+	auto written = static_cast<size_t>(result);
+
+	if (written > sizeof(printfBuffer)) {
+		written = sizeof(printfBuffer) - 1;
+	}
+
+	size_t beforeEnd = BufferSize - tail;
+	if (beforeEnd >= written) {
+		memcpy(buffer.data() + tail, printfBuffer, written);
+	} else {
+		memcpy(buffer.data() + tail, printfBuffer, beforeEnd);
+		memcpy(buffer.data(), printfBuffer + beforeEnd, written - beforeEnd);
+	}
+
+	tail = (tail + written) % BufferSize;
+	if (count + written > BufferSize) {
+		head = tail;
+		count = BufferSize;
+	} else {
+		count += written;
+	}
+}
+
+void SerialBuffer::tick() {
+	if (count == 0) {
+		return;
+	}
+
+	size_t maxWrite = std::min(PerTickWriteSize, static_cast<size_t>(Serial.availableForWrite()));
+	size_t toWrite = std::min(maxWrite, count);
+	size_t beforeEnd = BufferSize - head;
+	if (beforeEnd >= toWrite) {
+		Serial.printf("%.*s", static_cast<int>(toWrite), buffer.data() + head);
+		head = (head + toWrite) % BufferSize;
+	} else {
+		Serial.printf("%.*s%.*s",
+			static_cast<int>(beforeEnd),
+			buffer.data() + head,
+			static_cast<int>(toWrite - beforeEnd),
+			buffer.data());
+		head = toWrite - beforeEnd;
+	}
+	count -= toWrite;
+}
+
+}