improved use of MovingMinMaxAvg<> for better performance, added execution timing stats

tests/jitter/src/main.cpp

@@ -16,12 +16,14 @@
 #include <cerrno>
 #include <stdio.h>
 
-#include <MovingMinMaxAvg.h> // for MovingMinMaxAvg
+#include <MovingMinMaxAvg.h>
 #include <SequenceNumberStats.h>
-#include <StdDev.h>
 #include <SharedUtil.h> // for usecTimestampNow
+#include <SimpleMovingAverage.h>
+#include <StdDev.h>
 
 const quint64 MSEC_TO_USEC = 1000;
+const quint64 LARGE_STATS_TIME = 500; // we don't expect stats calculation to take more than this many usecs
 
 void runSend(const char* addressOption, int port, int gap, int size, int report);
 void runReceive(const char* addressOption, int port, int gap, int size, int report);
@@ -77,25 +79,37 @@ void runSend(const char* addressOption, int port, int gap, int size, int report)
     servaddr.sin_addr.s_addr = inet_addr(addressOption);
     servaddr.sin_port = htons(port);
 
-
+    const int SAMPLES_FOR_SECOND = 1000000 / gap;
-    const int SAMPLES_FOR_30_SECONDS = 30 * 1000000 / gap;
+    std::cout << "SAMPLES_FOR_SECOND:" << SAMPLES_FOR_SECOND << "\n";
+    const int INTERVALS_PER_30_SECONDS = 30;
+    std::cout << "INTERVALS_PER_30_SECONDS:" << INTERVALS_PER_30_SECONDS << "\n";
+    const int SAMPLES_FOR_30_SECONDS = 30 * SAMPLES_FOR_SECOND;
     std::cout << "SAMPLES_FOR_30_SECONDS:" << SAMPLES_FOR_30_SECONDS << "\n";
+    const int REPORTS_FOR_30_SECONDS = 30 * MSECS_PER_SECOND / report;
+    std::cout << "REPORTS_FOR_30_SECONDS:" << REPORTS_FOR_30_SECONDS << "\n";
 
-    const int SAMPLES_PER_REPORT = report * MSEC_TO_USEC / gap;
+    int intervalsPerReport = report / MSEC_TO_USEC;
-    std::cout << "SAMPLES_PER_REPORT:" << SAMPLES_PER_REPORT << "\n";
+    if (intervalsPerReport < 1) {
-
+        intervalsPerReport = 1;
+    }
+    std::cout << "intervalsPerReport:" << intervalsPerReport << "\n";
+    MovingMinMaxAvg<int> timeGaps(SAMPLES_FOR_SECOND, INTERVALS_PER_30_SECONDS);
+    MovingMinMaxAvg<int> timeGapsPerReport(SAMPLES_FOR_SECOND, intervalsPerReport);
 
     char* outputBuffer = new char[size];
     memset(outputBuffer, 0, size);
 
     quint16 outgoingSequenceNumber = 0;
 
-    MovingMinMaxAvg<int> timeGaps(1, SAMPLES_FOR_30_SECONDS);
-    MovingMinMaxAvg<int> timeGapsPerReport(1, SAMPLES_PER_REPORT);
 
     StDev stDevReportInterval;
     StDev stDev30s;
     StDev stDev;
+    
+    SimpleMovingAverage averageNetworkTime(SAMPLES_FOR_30_SECONDS);
+    SimpleMovingAverage averageStatsCalcultionTime(SAMPLES_FOR_30_SECONDS);
+    float lastStatsCalculationTime = 0.0f; // we add out stats calculation time in the next calculation window
+    bool hasStatsCalculationTime = false;
 
     quint64 last = usecTimestampNow();
     quint64 lastReport = 0;
@@ -111,19 +125,37 @@ void runSend(const char* addressOption, int port, int gap, int size, int report)
             // pack seq num
             memcpy(outputBuffer, &outgoingSequenceNumber, sizeof(quint16));
 
+            quint64 networkStart = usecTimestampNow();
             int n = sendto(sockfd, outputBuffer, size, 0, (struct sockaddr *)&servaddr, sizeof(servaddr));
+            quint64 networkEnd = usecTimestampNow();
+            float networkElapsed = (float)(networkEnd - networkStart);
+
             if (n < 0) {
                 std::cout << "Send error: " << strerror(errno) << "\n";
             }
             outgoingSequenceNumber++;
 
+            quint64 statsCalcultionStart = usecTimestampNow();
+
             int gapDifferece = actualGap - gap;
+
             timeGaps.update(gapDifferece);
             timeGapsPerReport.update(gapDifferece);
             stDev.addValue(gapDifferece);
             stDev30s.addValue(gapDifferece);
             stDevReportInterval.addValue(gapDifferece);
             last = now;
+            
+            // track out network time and stats calculation times
+            averageNetworkTime.updateAverage(networkElapsed);
+            
+            // for our stats calculation time, we actually delay the updating by one sample.
+            // we do this so that the calculation of the average timing for the stats calculation
+            // happen inside of the calculation processing. This ensures that tracking stats on
+            // stats calculation doesn't side effect the remaining running time.
+            if (hasStatsCalculationTime) {
+                averageStatsCalcultionTime.updateAverage(lastStatsCalculationTime);
+            }
 
             if (now - lastReport >= (report * MSEC_TO_USEC)) {
 
@@ -144,6 +176,9 @@ void runSend(const char* addressOption, int port, int gap, int size, int report)
                     << "max: " << timeGapsPerReport.getWindowMax() << " usecs, "
                     << "avg: " << timeGapsPerReport.getWindowAverage() << " usecs, "
                     << "stdev: " << stDevReportInterval.getStDev() << " usecs\n"
+                    << "Average Execution Times Last 30s:\n"
+                    << "    network: " << averageNetworkTime.getAverage() << " usecs average\n"
+                    << "      stats: " << averageStatsCalcultionTime.getAverage() << " usecs average"
                     << "\n";
 
                 stDevReportInterval.reset();
@@ -153,6 +188,14 @@ void runSend(const char* addressOption, int port, int gap, int size, int report)
 
                 lastReport = now;
             }
+
+            quint64 statsCalcultionEnd = usecTimestampNow();
+            lastStatsCalculationTime = (float)(statsCalcultionEnd - statsCalcultionStart);
+            if (lastStatsCalculationTime > LARGE_STATS_TIME) {
+                qDebug() << "WARNING -- unexpectedly large lastStatsCalculationTime=" << lastStatsCalculationTime;
+            }
+            hasStatsCalculationTime = true;
+
         }
     }
     delete[] outputBuffer;
@@ -184,21 +227,26 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo
     myaddr.sin_port = htons(port);
 
 
-    const int SAMPLES_FOR_30_SECONDS = 30 * 1000000 / gap;
+    const int SAMPLES_FOR_SECOND = 1000000 / gap;
+    std::cout << "SAMPLES_FOR_SECOND:" << SAMPLES_FOR_SECOND << "\n";
+    const int INTERVALS_PER_30_SECONDS = 30;
+    std::cout << "INTERVALS_PER_30_SECONDS:" << INTERVALS_PER_30_SECONDS << "\n";
+    const int SAMPLES_FOR_30_SECONDS = 30 * SAMPLES_FOR_SECOND;
     std::cout << "SAMPLES_FOR_30_SECONDS:" << SAMPLES_FOR_30_SECONDS << "\n";
-
-    const int SAMPLES_PER_REPORT = report * MSEC_TO_USEC / gap;
-    std::cout << "SAMPLES_PER_REPORT:" << SAMPLES_PER_REPORT << "\n";
-
     const int REPORTS_FOR_30_SECONDS = 30 * MSECS_PER_SECOND / report;
     std::cout << "REPORTS_FOR_30_SECONDS:" << REPORTS_FOR_30_SECONDS << "\n";
 
+    int intervalsPerReport = report / MSEC_TO_USEC;
+    if (intervalsPerReport < 1) {
+        intervalsPerReport = 1;
+    }
+    std::cout << "intervalsPerReport:" << intervalsPerReport << "\n";
+    MovingMinMaxAvg<int> timeGaps(SAMPLES_FOR_SECOND, INTERVALS_PER_30_SECONDS);
+    MovingMinMaxAvg<int> timeGapsPerReport(SAMPLES_FOR_SECOND, intervalsPerReport);
 
     char* inputBuffer = new char[size];
     memset(inputBuffer, 0, size);
 
-    MovingMinMaxAvg<int> timeGaps(1, SAMPLES_FOR_30_SECONDS);
-    MovingMinMaxAvg<int> timeGapsPerReport(1, SAMPLES_PER_REPORT);
 
     SequenceNumberStats seqStats(REPORTS_FOR_30_SECONDS);
 
@@ -206,6 +254,11 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo
     StDev stDev30s;
     StDev stDev;
 
+    SimpleMovingAverage averageNetworkTime(SAMPLES_FOR_30_SECONDS);
+    SimpleMovingAverage averageStatsCalcultionTime(SAMPLES_FOR_30_SECONDS);
+    float lastStatsCalculationTime = 0.0f; // we add out stats calculation time in the next calculation window
+    bool hasStatsCalculationTime = false;
+
     if (bind(sockfd, (struct sockaddr *)&myaddr, sizeof(myaddr)) < 0) {
         std::cout << "bind failed\n";
         return;
@@ -213,9 +266,16 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo
 
     quint64 last = 0; // first case
     quint64 lastReport = 0;
+    
+    quint64 a,b;
 
     while (true) {
+    
+        quint64 networkStart = usecTimestampNow();
         n = recvfrom(sockfd, inputBuffer, size, 0, NULL, NULL); // we don't care about where it came from
+        quint64 networkEnd = usecTimestampNow();
+        float networkElapsed = (float)(networkEnd - networkStart);
+    
         if (n < 0) {
             std::cout << "Receive error: " << strerror(errno) << "\n";
         }
@@ -228,8 +288,11 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo
             last = usecTimestampNow();
             std::cout << "first packet received\n";
         } else {
+
+            quint64 statsCalcultionStart = usecTimestampNow();
             quint64 now = usecTimestampNow();
             int actualGap = now - last;
+
             int gapDifferece = actualGap - gap;
             timeGaps.update(gapDifferece);
             timeGapsPerReport.update(gapDifferece);
@@ -237,6 +300,17 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo
             stDev30s.addValue(gapDifferece);
             stDevReportInterval.addValue(gapDifferece);
             last = now;
+            
+            // track out network time and stats calculation times
+            averageNetworkTime.updateAverage(networkElapsed);
+            
+            // for our stats calculation time, we actually delay the updating by one sample.
+            // we do this so that the calculation of the average timing for the stats calculation
+            // happen inside of the calculation processing. This ensures that tracking stats on
+            // stats calculation doesn't side effect the remaining running time.
+            if (hasStatsCalculationTime) {
+                averageStatsCalcultionTime.updateAverage(lastStatsCalculationTime);
+            }
 
             if (now - lastReport >= (report * MSEC_TO_USEC)) {
 
@@ -258,9 +332,12 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo
                     << "max: " << timeGapsPerReport.getWindowMax() << " usecs, "
                     << "avg: " << timeGapsPerReport.getWindowAverage() << " usecs, "
                     << "stdev: " << stDevReportInterval.getStDev() << " usecs\n"
+                    << "Average Execution Times Last 30s:\n"
+                    << "    network: " << averageNetworkTime.getAverage() << " usecs average\n"
+                    << "      stats: " << averageStatsCalcultionTime.getAverage() << " usecs average"
                     << "\n";
-
                 stDevReportInterval.reset();
+
                 if (stDev30s.getSamples() > SAMPLES_FOR_30_SECONDS) {
                     stDev30s.reset();
                 }
@@ -282,6 +359,14 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo
 
                 lastReport = now;
             }
+
+            quint64 statsCalcultionEnd = usecTimestampNow();
+
+            lastStatsCalculationTime = (float)(statsCalcultionEnd - statsCalcultionStart);
+            if (lastStatsCalculationTime > LARGE_STATS_TIME) {
+                qDebug() << "WARNING -- unexpectedly large lastStatsCalculationTime=" << lastStatsCalculationTime;
+            }
+            hasStatsCalculationTime = true;
         }
     }
     delete[] inputBuffer;