From cac4e5ba6c5d59dc243ac99c53d6b97dd5b4e7fd Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Sun, 17 Aug 2014 14:08:07 -0700 Subject: [PATCH 1/2] improved use of MovingMinMaxAvg<> for better performance, added execution timing stats --- tests/jitter/src/main.cpp | 119 ++++++++++++++++++++++++++++++++------ 1 file changed, 102 insertions(+), 17 deletions(-) diff --git a/tests/jitter/src/main.cpp b/tests/jitter/src/main.cpp index c27a791d5b..e70435b543 100644 --- a/tests/jitter/src/main.cpp +++ b/tests/jitter/src/main.cpp @@ -16,12 +16,14 @@ #include #include -#include // for MovingMinMaxAvg +#include #include -#include #include // for usecTimestampNow +#include +#include 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_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 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; - std::cout << "SAMPLES_PER_REPORT:" << SAMPLES_PER_REPORT << "\n"; - + int intervalsPerReport = report / MSEC_TO_USEC; + if (intervalsPerReport < 1) { + intervalsPerReport = 1; + } + std::cout << "intervalsPerReport:" << intervalsPerReport << "\n"; + MovingMinMaxAvg timeGaps(SAMPLES_FOR_SECOND, INTERVALS_PER_30_SECONDS); + MovingMinMaxAvg timeGapsPerReport(SAMPLES_FOR_SECOND, intervalsPerReport); char* outputBuffer = new char[size]; memset(outputBuffer, 0, size); quint16 outgoingSequenceNumber = 0; - MovingMinMaxAvg timeGaps(1, SAMPLES_FOR_30_SECONDS); - MovingMinMaxAvg 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 timeGaps(SAMPLES_FOR_SECOND, INTERVALS_PER_30_SECONDS); + MovingMinMaxAvg timeGapsPerReport(SAMPLES_FOR_SECOND, intervalsPerReport); char* inputBuffer = new char[size]; memset(inputBuffer, 0, size); - MovingMinMaxAvg timeGaps(1, SAMPLES_FOR_30_SECONDS); - MovingMinMaxAvg 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; From be94f98a9169eb778b71785d94b321f83fb1a1bd Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Sun, 17 Aug 2014 14:10:42 -0700 Subject: [PATCH 2/2] fix warning --- tests/jitter/src/main.cpp | 2 -- 1 file changed, 2 deletions(-) diff --git a/tests/jitter/src/main.cpp b/tests/jitter/src/main.cpp index e70435b543..8c93b7dbec 100644 --- a/tests/jitter/src/main.cpp +++ b/tests/jitter/src/main.cpp @@ -267,8 +267,6 @@ 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();