From db842d6b4c2a6600c63fc9a143fc70c4db108968 Mon Sep 17 00:00:00 2001 From: Magnus Date: Sun, 4 Apr 2021 22:47:24 +0200 Subject: [PATCH] Added function to measure code performance --- platformio.ini | 1 + src/helper.cpp | 4 ++ src/helper.h | 126 +++++++++++++++++++++++++++++++++++++++++++++ src/main.cpp | 52 +++++++++++++++++-- src/pushtarget.cpp | 21 +++++--- src/tempsensor.cpp | 12 +++-- 6 files changed, 202 insertions(+), 14 deletions(-) diff --git a/platformio.ini b/platformio.ini index efbcde0..4bf1b64 100644 --- a/platformio.ini +++ b/platformio.ini @@ -23,6 +23,7 @@ build_flags = #-O0 -Wl,-Map,output.map -D BAUD=${common_env_data.monitor_speed} -D ACTIVATE_OTA #-D SKIP_SLEEPMODE + -D COLLECT_PERFDATA -D USE_LITTLEFS=true -D EMBED_HTML -D USER_SSID=\""\"" # =\""myssid\"" diff --git a/src/helper.cpp b/src/helper.cpp index caa7bf3..08c1e2b 100644 --- a/src/helper.cpp +++ b/src/helper.cpp @@ -25,6 +25,7 @@ SOFTWARE. #include "config.h" SerialDebug mySerial; +PerfLogging myPerfLogging; BatteryVoltage myBatteryVoltage; // @@ -49,6 +50,9 @@ void printBuildOptions() { #ifdef EMBED_HTML "EMBED_HTML " #endif +#ifdef COLLECT_PERFDATA + "PERFDATA " +#endif #ifdef ACTIVATE_OTA "OTA " #endif diff --git a/src/helper.h b/src/helper.h index 85a908d..4b70982 100644 --- a/src/helper.h +++ b/src/helper.h @@ -57,8 +57,134 @@ class BatteryVoltage { float getVoltage() { return batteryLevel; }; }; +#if defined( COLLECT_PERFDATA ) +// Use these to collect performance data from various parts of the code +#define LOG_PERF_START(s) myPerfLogging.start(s) +#define LOG_PERF_STOP(s) myPerfLogging.stop(s) +#define LOG_PERF_PRINT() myPerfLogging.print() +#define LOG_PERF_CLEAR() myPerfLogging.clear() +#else +// These will disable the performance collection +#define LOG_PERF_START(s) +#define LOG_PERF_STOP(s) +#define LOG_PERF_PRINT() +#define LOG_PERF_CLEAR() +#endif + +class PerfLogging { + private: + struct PerfEntry { + unsigned long start; // millis() + unsigned long end; // millis() + unsigned long max; // max time in ms + const char* key; // measurement + PerfEntry* next; // + }; + + PerfEntry* first = 0; + + PerfEntry* find( const char* k ) { + if( first == 0 ) + return 0; + + PerfEntry* pe = first; + + while( strcmp( k, pe->key ) != 0 ) { + if( pe->next == 0 ) + return 0; + + pe = pe->next; + } + return pe; + }; + + PerfEntry* add( const char* k ) { + if( first == 0 ) { + first = new PerfEntry(); + first->key = k; + first->next = 0; + first->max = 0; + return first; + } + + PerfEntry* pe = first; + + while( strcmp( k, pe->key ) != 0 ) { + if( pe->next == 0 ) { + pe->next = new PerfEntry(); + pe->next->key = k; + pe->next->max = 0; + pe->next->next = 0; + return pe->next; + } + + pe = pe->next; + } + + return pe; + }; + + + public: + // + // Clear the current cache + // + void clear() { + if( first == 0 ) + return; + + PerfEntry* pe = first; + + do { + PerfEntry* p = pe; + pe = pe->next; + delete p; + } while( pe != 0 ); + + first = 0; + } + + // + // Start measuring this performance point + // + void start( const char* key ) { + PerfEntry* pe = add( key ); + pe->start = millis(); + } + + // + // Finalize measuring of this performance point + // + void stop( const char* key ) { + PerfEntry* pe = find( key ); + + if( pe != 0 ) { + pe->end = millis(); + + unsigned long t = pe->end - pe->start; + + if( t > pe->max ) + pe->max = t; + } + } + + // + // Print the collected performance data + // + void print() { + PerfEntry* pe = first; + + while( pe != 0 ) { + //Log.notice( F("PERF: %s=%l ms (%l, %l)" CR), pe->key, (pe->end - pe->start), pe->start, pe->end ); + Log.notice( F("PERF: %s %lms" CR), pe->key, pe->max ); + pe = pe->next; + } + } +}; + // Global instance created extern SerialDebug mySerial; +extern PerfLogging myPerfLogging; extern BatteryVoltage myBatteryVoltage; #endif // _HELPER_H diff --git a/src/main.cpp b/src/main.cpp index c4bad85..10b2c1a 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -91,6 +91,7 @@ void checkSleepMode( float angle, float volt ) { // Setup // void setup() { + LOG_PERF_START("main-setup"); startMillis = millis(); drd = new DoubleResetDetector(DRD_TIMEOUT, DRD_ADDRESS); @@ -104,40 +105,63 @@ void setup() { printBuildOptions(); Log.notice(F("Main: Loading configuration." CR)); + LOG_PERF_START("main-config-load"); myConfig.checkFileSystem(); myConfig.loadFile(); + LOG_PERF_STOP("main-config-load"); // Setup watchdog ESP.wdtDisable(); ESP.wdtEnable( interval*2 ); + LOG_PERF_START("main-temp-setup"); myTempSensor.setup(); + LOG_PERF_STOP("main-temp-setup"); // Setup Gyro + LOG_PERF_START("main-gyro-setup"); if( !myGyro.setup() ) Log.error(F("Main: Failed to initialize the gyro." CR)); + LOG_PERF_STOP("main-gyro-setup"); if( dt ) Log.notice(F("Main: Detected doubletap on reset." CR)); Log.notice(F("Main: Connecting to wifi." CR)); + LOG_PERF_START("main-wifi-connect"); myWifi.connect( dt ); + LOG_PERF_STOP("main-wifi-connect"); + + LOG_PERF_START("main-gyro-read"); myGyro.read(); + LOG_PERF_STOP("main-gyro-read"); + + LOG_PERF_START("main-batt-read"); myBatteryVoltage.read(); + LOG_PERF_STOP("main-batt-read"); checkSleepMode( myGyro.getAngle(), myBatteryVoltage.getVoltage() ); if( myWifi.isConnected() ) { Log.notice(F("Main: Connected to wifi ip=%s." CR), myWifi.getIPAddress().c_str() ); #if defined( ACTIVATE_OTA ) + LOG_PERF_START("main-wifi-ota"); if( !sleepModeActive && myWifi.checkFirmwareVersion() ) { myWifi.updateFirmware(); } + LOG_PERF_STOP("main-wifi-ota"); #endif - if( !sleepModeActive ) + if( !sleepModeActive ) { + LOG_PERF_START("main-webserver-setup"); if( myWebServer.setupWebServer() ) Log.notice(F("Main: Webserver is running." CR) ); + LOG_PERF_STOP("main-webserver-setup"); + } } + + LOG_PERF_STOP("main-setup"); + LOG_PERF_PRINT(); + LOG_PERF_CLEAR(); } // @@ -158,27 +182,39 @@ void loop() { if( myGyro.hasValue() ) { angle = myGyro.getAngle(); // Gyro angle sensorTemp = myGyro.getSensorTempC(); // Temp in the Gyro + + LOG_PERF_START("loop-temp-read"); float temp = myTempSensor.getValueCelcius(); // The code is build around using C for temp. + LOG_PERF_STOP("loop-temp-read"); + + LOG_PERF_START("loop-gravity-calc"); float gravity = calculateGravity( angle, temp ); + LOG_PERF_STOP("loop-gravity-calc"); + #if LOG_LEVEL==6 Log.verbose(F("Main: Sensor values gyro angle=%F gyro temp=%F, temp=%F, gravity=%F." CR), angle, sensorTemp, temp, gravity ); #endif if( myConfig.isGravityTempAdj() ) { + LOG_PERF_START("loop-gravity-corr"); gravity = gravityTemperatureCorrection( gravity, temp); // Use default correction temperature of 20C + LOG_PERF_STOP("loop-gravity-corr"); #if LOG_LEVEL==6 Log.verbose(F("Main: Temp adjusted gravity=%F." CR), gravity ); #endif } // Limit the printout when sleep mode is not active. - if( loopCounter%10 == 0 || sleepModeActive ) + if( loopCounter%10 == 0 || sleepModeActive ) { Log.notice(F("Main: gyro angle=%F, gyro temp=%F, DS18B20 temp=%F, gravity=%F, batt=%F." CR), angle, sensorTemp, temp, gravity, volt ); + LOG_PERF_PRINT(); + } -#if defined( ACTIVATE_PUSH ) unsigned long runTime = millis() - startMillis; + LOG_PERF_START("loop-push"); myPushTarget.send( angle, gravity, temp, runTime/1000, sleepModeActive ); // Force the transmission if we are going to sleep -#endif + LOG_PERF_STOP("loop-push"); + } else { Log.error(F("Main: No gyro value." CR) ); } @@ -191,6 +227,7 @@ void loop() { LittleFS.end(); myGyro.enterSleep(); drd->stop(); + LOG_PERF_PRINT(); delay(100); deepSleep( myConfig.getSleepInterval() ); } @@ -200,8 +237,15 @@ void loop() { #endif // Do these checks if we are running in normal mode (not sleep mode) checkSleepMode( angle, volt ); + + LOG_PERF_START("loop-gyro-read"); myGyro.read(); + LOG_PERF_STOP("loop-gyro-read"); + + LOG_PERF_START("loop-batt-read"); myBatteryVoltage.read(); + LOG_PERF_STOP("loop-batt-read"); + lastMillis = millis(); #if LOG_LEVEL==6 Log.verbose(F("Main: Heap %d kb FreeSketch %d kb." CR), ESP.getFreeHeap()/1024, ESP.getFreeSketchSpace()/1024 ); diff --git a/src/pushtarget.cpp b/src/pushtarget.cpp index c7c3553..8dd7222 100644 --- a/src/pushtarget.cpp +++ b/src/pushtarget.cpp @@ -45,14 +45,23 @@ void PushTarget::send(float angle, float gravity, float temp, float runTime, boo #endif ms = millis(); - if( myConfig.isBrewfatherActive() ) - sendBrewfather( angle, gravity, temp ); + if( myConfig.isBrewfatherActive() ) { + LOG_PERF_START("push-brewfather"); + sendBrewfather( angle, gravity, temp ); + LOG_PERF_STOP("push-brewfather"); + } - if( myConfig.isHttpActive() ) - sendHttp( myConfig.getHttpPushTarget(), angle, gravity, temp, runTime ); + if( myConfig.isHttpActive() ) { + LOG_PERF_START("push-http"); + sendHttp( myConfig.getHttpPushTarget(), angle, gravity, temp, runTime ); + LOG_PERF_STOP("push-http"); + } - if( myConfig.isHttpActive2() ) - sendHttp( myConfig.getHttpPushTarget2(), angle, gravity, temp, runTime ); + if( myConfig.isHttpActive2() ) { + LOG_PERF_START("push-http2"); + sendHttp( myConfig.getHttpPushTarget2(), angle, gravity, temp, runTime ); + LOG_PERF_STOP("push-http2"); + } } // diff --git a/src/tempsensor.cpp b/src/tempsensor.cpp index 1ca2b7c..6194699 100644 --- a/src/tempsensor.cpp +++ b/src/tempsensor.cpp @@ -51,7 +51,7 @@ void TempSensor::setup() { return; #endif - if( mySensors.getDeviceCount() ) + if( mySensors.getDS18Count() ) return; #if LOG_LEVEL==6 @@ -59,8 +59,8 @@ void TempSensor::setup() { #endif mySensors.begin(); - if( mySensors.getDeviceCount() ) { - Log.notice(F("TSEN: Found %d sensors." CR), mySensors.getDeviceCount()); + if( mySensors.getDS18Count() ) { + Log.notice(F("TSEN: Found %d sensors." CR), mySensors.getDS18Count()); mySensors.setResolution(TEMPERATURE_PRECISION); } @@ -91,10 +91,14 @@ float TempSensor::getValue() { #endif // Read the sensors + //LOG_PERF_START("temp-request"); mySensors.requestTemperatures(); + //LOG_PERF_STOP("temp-request"); - if( mySensors.getDeviceCount() >= 1) { + if( mySensors.getDS18Count() >= 1) { + //LOG_PERF_START("temp-get"); c = mySensors.getTempCByIndex(0); + //LOG_PERF_STOP("temp-get"); #if LOG_LEVEL==6 Log.verbose(F("TSEN: Reciving temp value for sensor %F C." CR), c);