fix formating try 1

platformio.ini

@@ -11,8 +11,8 @@
 ; https://docs.slimevr.dev/firmware/configuring-project.html#1-configuring-platformioini
 ; ================================================
 
-[platformio]
-build_cache_dir = cache
+;[platformio]
+;build_cache_dir = cache
 
 [env]
 lib_deps=

src/debug.h

@@ -58,7 +58,7 @@
 #define samplingRateInMillis 10
 
 // Sleeping options
-#define POWERSAVING_MODE POWER_SAVING_LEGACY  // Minimum causes sporadic data pauses
+#define POWERSAVING_MODE POWER_SAVING_MINIMUM  // Minimum causes sporadic data pauses
 #if POWERSAVING_MODE >= POWER_SAVING_MINIMUM
 #define TARGET_LOOPTIME_MICROS (samplingRateInMillis * 1000)
 #endif
@@ -80,7 +80,7 @@
 // If "false" updates are sent at the sensor update rate (usually 100 TPS)
 // If "true" updates will be less frequent in the time of little motion
 // Experimental
-#define OPTIMIZE_UPDATES true
+#define OPTIMIZE_UPDATES false
 
 #define I2C_SPEED 400000
 
@@ -104,10 +104,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 true
 #endif
 
 #ifndef USE_OTA_TIMEOUT

src/debugging/TimeTaken.cpp

@@ -22,34 +22,85 @@
 
 namespace SlimeVR::Debugging {
 
-TimeTakenMeasurer::TimeTakenMeasurer(const char* name)
-	: name{name} {}
+void TimeTakenMeasurer::before(int measurement) {
+	timings[measurement].start = micros();
+}
+void TimeTakenMeasurer::after(int measurement) { timings[measurement].end = micros(); }
 
-void TimeTakenMeasurer::before() { startMicros = micros(); }
+void TimeTakenMeasurer::calculate() {
+	for (auto& timing : timings) {
+		if (timing.start == 0 && timing.end == 0) {
+			continue;  // Skip if not measured
+		}
+		unsigned long d = timing.end - timing.start;
+		timing.min = min(timing.min, d);
+		timing.max = max(timing.max, d);
+		timing.timeTaken += d;
+		timing.count++;
+		timing.start = 0;
+		timing.end = 0;
+	}
+	if (lastTimingsPrint < millis() - SecondsBetweenReports * 1000) {
+		nextPeriod();
+		report();
+	}
+}
 
-void TimeTakenMeasurer::after() {
-	uint64_t elapsedMicros = micros() - startMicros;
-	timeTakenMicros += elapsedMicros;
-
-	uint64_t sinceLastReportMillis = millis() - lastTimeTakenReportMillis;
-
-	if (sinceLastReportMillis < static_cast<uint64_t>(SecondsBetweenReports * 1e3)) {
-		return;
+void TimeTakenMeasurer::nextPeriod() {
+	// Calculate the time since the last report
+	unsigned long sinceLastReportMillis = millis() - lastTimingsPrint;
+	lastTimingsPrint = millis();
+	for (auto& timing : timings) {
+		timing.timeTakenPercent = static_cast<float>(timing.timeTaken) / 1e3f
+								/ static_cast<float>(sinceLastReportMillis) * 100;
+		timing.timeTotal = sinceLastReportMillis;
+		timing.avg = timing.timeTaken / max(timing.count, 1ul);
 	}
 
-	float usedPercentage = static_cast<float>(timeTakenMicros) / 1e3f
-						 / static_cast<float>(sinceLastReportMillis) * 100;
+	// Copy the values to the past measurement
+	pasttimings = timings;
 
+	// Reset the current measurement
+	for (auto& timing : timings) {
+		timing.avg = 0;
+		timing.min = -1;
+		timing.max = 0;
+		timing.timeTaken = 0;
+		timing.count = 0;
+		timing.start = 0;
+		timing.end = 0;
+		timing.timeTakenPercent = 0;
+		timing.timeTotal = 0;
+	}
+}
+
+void TimeTakenMeasurer::report() {
+	unsigned long totalTime = 0;
+	unsigned long count = 0;
+	for (size_t i = 0; i < pasttimings.size(); ++i) {
+		const auto& timing = pasttimings[i];
+		const auto& name = names[i];
+		m_Logger.info(
+			"%-24s | avg: %5lu us | min: %5lu us | max: %5lu us | time taken: %5lu ms "
+			"or %5.2f%% of %lu ms count: %lu",
+			name.c_str(),
+			timing.avg,
+			timing.min,
+			timing.max,
+			static_cast<unsigned long>(timing.timeTaken / 1000),
+			timing.timeTakenPercent,
+			timing.timeTotal,
+			timing.count
+		);
+		totalTime = max(timing.timeTotal, totalTime);
+		count = max(timing.count, count);
+	}
 	m_Logger.info(
-		"%s: %.2f%% of the last period taken (%.2f/%lld millis)",
-		name,
-		usedPercentage,
-		timeTakenMicros / 1e3f,
-		sinceLastReportMillis
+		"Time Total: %lu ms Loops: %lu PrintReport Time: %lu ms",
+		totalTime,
+		count,
+		millis() - lastTimingsPrint
 	);
-
-	timeTakenMicros = 0;
-	lastTimeTakenReportMillis = millis();
 }
 
 }  // namespace SlimeVR::Debugging

src/debugging/TimeTaken.h

@@ -26,33 +26,58 @@
 
 namespace SlimeVR::Debugging {
 
+struct TimingMeasurement {
+	unsigned long avg = 0;
+	unsigned long min = -1;
+	unsigned long max = 0;
+	unsigned long timeTaken = 0;
+	float timeTakenPercent = 0;
+	unsigned long timeTotal = 0;
+	unsigned long count = 0;
+	unsigned long start = 0;
+	unsigned long end = 0;
+};
+
 /*
  * Usage:
  *
- * TimeTakenMeasurer measurer{"Some event"};
+ * std::vector<const char*> timingNames = {
+ *    "tpsCounter.update()",  <- 0
+ *    "globalTimer.tick()"    <- 1
+ * }
+ * TimeTakenMeasurer measurer{timingNames};
  *
  * ...
  *
- * measurer.before();
+ * measurer.before(0);
  * thing to measure
- * measurer.after();
+ * measurer.after(0);
  */
 class TimeTakenMeasurer {
 public:
-	explicit TimeTakenMeasurer(const char* name);
-	void before();
-	void after();
+	explicit TimeTakenMeasurer(const std::vector<const char*>& names) {
+		for (const auto& name : names) {
+			this->names.push_back(name);
+			this->timings.push_back({0, 2 ^ 64, 0, 0, 0, 0, 0, 0});
+		}
+	}
+
+	void before(int measurement);
+	void after(int measurement);
+	void calculate();
 
 private:
-	static constexpr float SecondsBetweenReports = 1.0f;
+	void nextPeriod();
+	void report();
+	static constexpr float SecondsBetweenReports = 10.0f;
+	unsigned long lastTimingsPrint = 0;
 
-	const char* name;
+	std::vector<String> names;
+	std::vector<TimingMeasurement> timings;
+
+	std::vector<TimingMeasurement> pasttimings;
 	SlimeVR::Logging::Logger m_Logger = SlimeVR::Logging::Logger("TimeTaken");
-
-	uint64_t lastTimeTakenReportMillis = 0;
-	uint64_t timeTakenMicros = 0;
-
-	uint64_t startMicros = 0;
+	unsigned long lastTimeTakenReportMillis = 0;
 };
 
 }  // namespace SlimeVR::Debugging

src/main.cpp

@@ -43,8 +43,31 @@ SlimeVR::Configuration::Configuration configuration;
 SlimeVR::Network::Manager networkManager;
 SlimeVR::Network::Connection networkConnection;
 
-#if DEBUG_MEASURE_SENSOR_TIME_TAKEN
-SlimeVR::Debugging::TimeTakenMeasurer sensorMeasurer{"Sensors"};
+#if DEBUG_MEASURE_TIME_TAKEN
+// Define the names of the measurements
+// The order of the names should match the order of the measurements in the
+// timings array
+// The names are used to identify the measurements in the report
+std::vector<const char*> timingNames
+	= {"tpsCounter.update()",
+	   "globalTimer.tick()",
+	   "Serial update()",
+	   "OTA::otaUpdate()",
+	   "networkManager.update()",
+	   "sensorManager.update()",
+	   "battery.Loop()",
+	   "ledManager.update()",
+	   "I2CSCAN::update()",
+	   "TARGET_LOOPTIME_MICROS",
+	   "Serial printState()",
+	   "IMU1 Sensor loop",
+	   "IMU2 Sensor loop"};
+SlimeVR::Debugging::TimeTakenMeasurer timingsMeasurer(timingNames);
+#define BENCHMARK_START(number) timingsMeasurer.before(number);
+#define BENCHMARK_END(number) timingsMeasurer.after(number);
+#else
+#define BENCHMARK_START(number)
+#define BENCHMARK_END(number)
 #endif
 
 int sensorToCalibrate = -1;
@@ -119,24 +142,35 @@ void setup() {
 }
 
 void loop() {
+	BENCHMARK_START(0)
 	tpsCounter.update();
+	BENCHMARK_END(0)
+	BENCHMARK_START(1)
 	globalTimer.tick();
+	BENCHMARK_END(1)
+	BENCHMARK_START(2)
 	SerialCommands::update();
+	BENCHMARK_END(2)
+	BENCHMARK_START(3)
 	OTA::otaUpdate();
+	BENCHMARK_END(3)
+	BENCHMARK_START(4)
 	networkManager.update();
-
-#if DEBUG_MEASURE_SENSOR_TIME_TAKEN
-	sensorMeasurer.before();
-#endif
+	BENCHMARK_END(4)
+	BENCHMARK_START(5)
 	sensorManager.update();
-#if DEBUG_MEASURE_SENSOR_TIME_TAKEN
-	sensorMeasurer.after();
-#endif
-
+	BENCHMARK_END(5)
+	BENCHMARK_START(6)
 	battery.Loop();
+	BENCHMARK_END(6)
+	BENCHMARK_START(7)
 	ledManager.update();
+	BENCHMARK_END(7)
+	BENCHMARK_START(8)
 	I2CSCAN::update();
+	BENCHMARK_END(8)
 #ifdef TARGET_LOOPTIME_MICROS
+	BENCHMARK_START(9)
 	long elapsed = (micros() - loopTime);
 	if (elapsed < TARGET_LOOPTIME_MICROS) {
 		long sleepus = TARGET_LOOPTIME_MICROS - elapsed - 100;  // µs to sleep
@@ -151,12 +185,18 @@ void loop() {
 		}
 	}
 	loopTime = micros();
+	BENCHMARK_END(9)
 #endif
+	BENCHMARK_START(10)
 #if defined(PRINT_STATE_EVERY_MS) && PRINT_STATE_EVERY_MS > 0
 	unsigned long now = millis();
 	if (lastStatePrint + PRINT_STATE_EVERY_MS < now) {
 		lastStatePrint = now;
 		SerialCommands::printState();
 	}
+#endif
+	BENCHMARK_END(10)
+#if DEBUG_MEASURE_TIME_TAKEN
+	timingsMeasurer.calculate();
 #endif
 }

src/sensors/SensorManager.cpp

@@ -47,6 +47,11 @@
 #include "softfusion/i2cimpl.h"
 #include "softfusion/softfusionsensor.h"
 
+#if DEBUG_MEASURE_TIME_TAKEN
+#include "debugging/TimeTaken.h"
+extern SlimeVR::Debugging::TimeTakenMeasurer timingsMeasurer;
+#endif
+
 #if ESP32
 #include "driver/i2c.h"
 #endif
@@ -149,7 +154,13 @@ void SensorManager::postSetup() {
 void SensorManager::update() {
 	// Gather IMU data
 	bool allIMUGood = true;
+#if DEBUG_MEASURE_TIME_TAKEN
+	uint8_t sensorcount = 0;
+#endif
 	for (auto& sensor : m_Sensors) {
+#if DEBUG_MEASURE_TIME_TAKEN
+		timingsMeasurer.before(11 + sensorcount);
+#endif
 		if (sensor->isWorking()) {
 			if (sensor->m_hwInterface != nullptr) {
 				sensor->m_hwInterface->swapIn();
@@ -159,6 +170,10 @@ void SensorManager::update() {
 		if (sensor->getSensorState() == SensorStatus::SENSOR_ERROR) {
 			allIMUGood = false;
 		}
+#if DEBUG_MEASURE_TIME_TAKEN
+		timingsMeasurer.after(11 + sensorcount);
+		sensorcount++;
+#endif
 	}
 
 	statusManager.setStatus(SlimeVR::Status::IMU_ERROR, !allIMUGood);