Performance measurement (#532)

* Benchmark implementation.

Co-authored-by: unlogisch04 <98281608+unlogisch04@users.noreply.github.com>

* Make benchmark printing non-default

* fix format

* remove hard define

* Add Guards to Benchmark

* Cleanup

---------

Co-authored-by: Gorbit99 <gorbitgames@gmail.com>

Author: unlogisch04

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,72 @@
+#include "Benchmark.h"
+
+#include <limits>
+
+namespace SlimeVR::Debugging {
+
+Benchmark::Benchmark(const char* name)
+	: name{name} {}
+
+void Benchmark::before() {
+#if DEBUG_MEASURE_TIME_TAKEN
+	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++;
+
+	auto timeSinceLastReport = millis() - lastReportMillis;
+	if (timeSinceLastReport >= static_cast<uint32_t>(ReportsIntervalSeconds * 1000)) {
+		printReport();
+		reset();
+	}
+#endif
+}
+
+void Benchmark::printReport() {
+#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;
+	m_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
+	);
+
+	lastReportMillis = millis();
+#endif
+}
+
+void Benchmark::reset() {
+#if DEBUG_MEASURE_TIME_TAKEN
+	totalTimeTakenMicros = 0;
+	minTimeTakenMicros = std::numeric_limits<uint64_t>::max();
+	maxTimeTakenMicros = 0;
+	measurementCount = 0;
+#endif
+}
+
+}  // namespace SlimeVR::Debugging

src/debugging/TimeTaken.h src/debugging/Benchmark.hsrc/debugging/TimeTaken.h renamed to 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
@@ -20,39 +23,45 @@
 
 #pragma once
 
+#include <Arduino.h>
+
+#include <cmath>
 #include <cstdint>
+#include <limits>
 
-#include "logging/Logger.h"
+#include "../logging/Logger.h"
 
 namespace SlimeVR::Debugging {
 
-/*
- * Usage:
- *
- * TimeTakenMeasurer measurer{"Some event"};
- *
- * ...
- *
- * measurer.before();
- * thing to measure
- * measurer.after();
- */
-class TimeTakenMeasurer {
+class Benchmark {
 public:
-	explicit TimeTakenMeasurer(const char* name);
+	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 before();
 	void after();
 
 private:
-	static constexpr float SecondsBetweenReports = 1.0f;
+	static constexpr float ReportsIntervalSeconds = 10.0f;
 
-	const char* name;
-	SlimeVR::Logging::Logger m_Logger = SlimeVR::Logging::Logger("TimeTaken");
+	void printReport();
+	void reset();
+
+	uint32_t lastReportMillis = millis();
+
+	uint64_t currentMeasurementStartMicros = 0;
 
-	uint64_t lastTimeTakenReportMillis = 0;
-	uint64_t timeTakenMicros = 0;
+	uint64_t totalTimeTakenMicros = 0;
+	uint64_t minTimeTakenMicros = std::numeric_limits<uint64_t>::max();
+	uint64_t maxTimeTakenMicros = 0;
+	uint32_t measurementCount = 0;
+
+	const char* name;
 
-	uint64_t startMicros = 0;
+	SlimeVR::Logging::Logger m_Logger = SlimeVR::Logging::Logger("Benchmark");
 };
 
 }  // namespace SlimeVR::Debugging

src/debugging/TimeTaken.cpp

@@ -27,7 +27,7 @@
 #include "Wire.h"
 #include "batterymonitor.h"
 #include "credentials.h"
-#include "debugging/TimeTaken.h"
+#include "debugging/Benchmark.h"
 #include "globals.h"
 #include "logging/Logger.h"
 #include "ota.h"
@@ -45,9 +45,17 @@ SlimeVR::Network::Connection networkConnection;
 SlimeVR::WiFiNetwork wifiNetwork;
 SlimeVR::WifiProvisioning wifiProvisioning;
 
-#if DEBUG_MEASURE_SENSOR_TIME_TAKEN
-SlimeVR::Debugging::TimeTakenMeasurer sensorMeasurer{"Sensors"};
-#endif
+SlimeVR::Debugging::Benchmark tpsCounterBM{"tpsCounter.update()"};
+SlimeVR::Debugging::Benchmark globalTimerBM{"globalTimer.tick()"};
+SlimeVR::Debugging::Benchmark serialCommandsBM{"SerialCommands::update()"};
+SlimeVR::Debugging::Benchmark otaBM{"OTA::otaUpdate()"};
+SlimeVR::Debugging::Benchmark networkManagerBM{"networkManager.update()"};
+SlimeVR::Debugging::Benchmark sensorManagerBM{"sensorManager.update()"};
+SlimeVR::Debugging::Benchmark batteryBM{"battery.Loop()"};
+SlimeVR::Debugging::Benchmark ledManagerBM{"ledManager.update()"};
+SlimeVR::Debugging::Benchmark i2cScanBM{"I2CSCAN::update()"};
+SlimeVR::Debugging::Benchmark targetLooptimeBM{"TARGET_LOOPTIME_MICROS"};
+SlimeVR::Debugging::Benchmark printStateBM{"Serial printState()"};
 
 int sensorToCalibrate = -1;
 bool blinking = false;
@@ -153,24 +161,44 @@ void setup() {
 }
 
 void loop() {
+	tpsCounterBM.before();
 	tpsCounter.update();
+	tpsCounterBM.after();
+
+	globalTimerBM.before();
 	globalTimer.tick();
+	globalTimerBM.after();
+
+	serialCommandsBM.before();
 	SerialCommands::update();
+	serialCommandsBM.after();
+
+	otaBM.before();
 	OTA::otaUpdate();
+	otaBM.after();
+
+	networkManagerBM.before();
 	networkManager.update();
+	networkManagerBM.after();
 
-#if DEBUG_MEASURE_SENSOR_TIME_TAKEN
-	sensorMeasurer.before();
-#endif
+	sensorManagerBM.before();
 	sensorManager.update();
-#if DEBUG_MEASURE_SENSOR_TIME_TAKEN
-	sensorMeasurer.after();
-#endif
+	sensorManagerBM.after();
 
+	batteryBM.before();
 	battery.Loop();
+	batteryBM.after();
+
+	ledManagerBM.before();
 	ledManager.update();
+	ledManagerBM.after();
+
+	i2cScanBM.before();
 	I2CSCAN::update();
+	i2cScanBM.after();
+
 #ifdef TARGET_LOOPTIME_MICROS
+	targetLooptimeBM.before();
 	long elapsed = (micros() - loopTime);
 	if (elapsed < TARGET_LOOPTIME_MICROS) {
 		long sleepus = TARGET_LOOPTIME_MICROS - elapsed - 100;  // µs to sleep
@@ -185,12 +213,15 @@ void loop() {
 		}
 	}
 	loopTime = micros();
+	targetLooptimeBM.after();
 #endif
 #if defined(PRINT_STATE_EVERY_MS) && PRINT_STATE_EVERY_MS > 0
+	printStateBM.before();
 	unsigned long now = millis();
 	if (lastStatePrint + PRINT_STATE_EVERY_MS < now) {
 		lastStatePrint = now;
 		SerialCommands::printState();
 	}
+	printStateBM.after();
 #endif
 }

src/main.cpp

@@ -23,10 +23,19 @@
 
 #include "SensorManager.h"
 
+#include <array>
+
+#include "../debugging/Benchmark.h"
 #include "SensorBuilder.h"
 
 namespace SlimeVR::Sensors {
 
+std::array<SlimeVR::Debugging::Benchmark, 2> sensorLoopBMs{
+	SlimeVR::Debugging::Benchmark{"IMU1 Sensor loop"},
+	SlimeVR::Debugging::Benchmark{"IMU2 Sensor loop"}
+};
+SlimeVR::Debugging::Benchmark sensorManagerNetworkingBM{"sensorManager Network"};
+
 void SensorManager::setup() {
 	if (m_MCP.begin_I2C()) {
 		m_Logger.info("MCP initialized");
@@ -60,7 +69,12 @@ void SensorManager::postSetup() {
 void SensorManager::update() {
 	// Gather IMU data
 	bool allIMUGood = true;
+	size_t sensorId = 0;
 	for (auto& sensor : m_Sensors) {
+		if (sensorId < sensorLoopBMs.size()) {
+			sensorLoopBMs[sensorId].before();
+		}
+
 		if (sensor->isWorking()) {
 			if (sensor->m_hwInterface != nullptr) {
 				sensor->m_hwInterface->swapIn();
@@ -70,6 +84,11 @@ void SensorManager::update() {
 		if (sensor->getSensorState() == SensorStatus::SENSOR_ERROR) {
 			allIMUGood = false;
 		}
+
+		if (sensorId < sensorLoopBMs.size()) {
+			sensorLoopBMs[sensorId].after();
+		}
+		sensorId++;
 	}
 
 	statusManager.setStatus(SlimeVR::Status::IMU_ERROR, !allIMUGood);
@@ -106,6 +125,7 @@ void SensorManager::update() {
 	m_LastBundleSentAtMicros = now;
 #endif
 
+	sensorManagerNetworkingBM.before();
 #if PACKET_BUNDLING != PACKET_BUNDLING_DISABLED
 	networkConnection.beginBundle();
 #endif
@@ -119,6 +139,7 @@ void SensorManager::update() {
 #if PACKET_BUNDLING != PACKET_BUNDLING_DISABLED
 	networkConnection.endBundle();
 #endif
+	sensorManagerNetworkingBM.after();
 }
 
 }  // namespace SlimeVR::Sensors