Added function to measure code performance

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\""

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     

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

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 );

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() )
+    if( myConfig.isBrewfatherActive() ) {
+        LOG_PERF_START("push-brewfather");
         sendBrewfather( angle,  gravity, temp );
+        LOG_PERF_STOP("push-brewfather");
+    }
 
-    if( myConfig.isHttpActive() )
+    if( myConfig.isHttpActive() ) {
+        LOG_PERF_START("push-http");
         sendHttp( myConfig.getHttpPushTarget(), angle, gravity, temp, runTime );
+        LOG_PERF_STOP("push-http");
+    }
 
-    if( myConfig.isHttpActive2() )
+    if( myConfig.isHttpActive2() ) {
+        LOG_PERF_START("push-http2");
         sendHttp( myConfig.getHttpPushTarget2(), angle, gravity, temp, runTime );
+        LOG_PERF_STOP("push-http2");
+    }
 }
 
 //

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() ) {
+    if( mySensors.getDS18Count() ) {
-        Log.notice(F("TSEN: Found %d sensors." CR), mySensors.getDeviceCount());
+        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);