diff --git a/assignment-client/src/audio/AudioMixer.cpp b/assignment-client/src/audio/AudioMixer.cpp index 5900e1f151..914d5ae63b 100644 --- a/assignment-client/src/audio/AudioMixer.cpp +++ b/assignment-client/src/audio/AudioMixer.cpp @@ -71,6 +71,8 @@ bool AudioMixer::_useDynamicJitterBuffers = false; int AudioMixer::_staticDesiredJitterBufferFrames = 0; int AudioMixer::_maxFramesOverDesired = 0; +bool AudioMixer::_printStreamStats = false; + AudioMixer::AudioMixer(const QByteArray& packet) : ThreadedAssignment(packet), _trailingSleepRatio(1.0f), @@ -448,7 +450,11 @@ void AudioMixer::run() { } qDebug() << "Max frames over desired:" << _maxFramesOverDesired; - + const QString PRINT_STREAM_STATS_JSON_KEY = "H-print-stream-stats"; + _printStreamStats = audioGroupObject[PRINT_STREAM_STATS_JSON_KEY].toBool(); + if (_printStreamStats) { + qDebug() << "Stream stats will be printed to stdout"; + } const QString UNATTENUATED_ZONE_KEY = "D-unattenuated-zone"; @@ -547,6 +553,7 @@ void AudioMixer::run() { sendAudioStreamStats = true; } + bool streamStatsPrinted = false; foreach (const SharedNodePointer& node, nodeList->getNodeHash()) { if (node->getLinkedData()) { AudioMixerClientData* nodeData = (AudioMixerClientData*)node->getLinkedData(); @@ -581,12 +588,21 @@ void AudioMixer::run() { // send an audio stream stats packet if it's time if (sendAudioStreamStats) { nodeData->sendAudioStreamStatsPackets(node); + + if (_printStreamStats) { + printf("\nStats for agent %s:\n", node->getUUID().toString().toLatin1().data()); + nodeData->printUpstreamDownstreamStats(); + streamStatsPrinted = true; + } } ++_sumListeners; } } } + if (streamStatsPrinted) { + printf("\n----------------------------------------------------------------\n"); + } ++_numStatFrames; diff --git a/assignment-client/src/audio/AudioMixer.h b/assignment-client/src/audio/AudioMixer.h index 83769a4209..d11539e22e 100644 --- a/assignment-client/src/audio/AudioMixer.h +++ b/assignment-client/src/audio/AudioMixer.h @@ -66,6 +66,8 @@ private: static int _staticDesiredJitterBufferFrames; static int _maxFramesOverDesired; + static bool _printStreamStats; + quint64 _lastSendAudioStreamStatsTime; }; diff --git a/assignment-client/src/audio/AudioMixerClientData.cpp b/assignment-client/src/audio/AudioMixerClientData.cpp index fb805e11d8..9a8a85c3d1 100644 --- a/assignment-client/src/audio/AudioMixerClientData.cpp +++ b/assignment-client/src/audio/AudioMixerClientData.cpp @@ -22,7 +22,8 @@ AudioMixerClientData::AudioMixerClientData() : _audioStreams(), - _outgoingMixedAudioSequenceNumber(0) + _outgoingMixedAudioSequenceNumber(0), + _downstreamAudioStreamStats() { } @@ -263,3 +264,45 @@ QString AudioMixerClientData::getAudioStreamStatsString() const { } return result; } + +void AudioMixerClientData::printUpstreamDownstreamStats() const { + // print the upstream (mic stream) stats if the mic stream exists + if (_audioStreams.contains(QUuid())) { + printf("Upstream:\n"); + printAudioStreamStats(_audioStreams.value(QUuid())->getAudioStreamStats()); + } + // print the downstream stats if they contain valid info + if (_downstreamAudioStreamStats._packetStreamStats._received > 0) { + printf("Downstream:\n"); + printAudioStreamStats(_downstreamAudioStreamStats); + } +} + +void AudioMixerClientData::printAudioStreamStats(const AudioStreamStats& streamStats) const { + printf(" Packet loss | overall: %5.2f%% (%d lost), last_30s: %5.2f%% (%d lost)\n", + streamStats._packetStreamStats.getLostRate() * 100.0f, + streamStats._packetStreamStats._lost, + streamStats._packetStreamWindowStats.getLostRate() * 100.0f, + streamStats._packetStreamWindowStats._lost); + + printf(" Ringbuffer frames | desired: %u, avg_available(10s): %u, available: %u\n", + streamStats._desiredJitterBufferFrames, + streamStats._framesAvailableAverage, + streamStats._framesAvailable); + + printf(" Ringbuffer stats | starves: %u, prev_starve_lasted: %u, frames_dropped: %u, overflows: %u\n", + streamStats._starveCount, + streamStats._consecutiveNotMixedCount, + streamStats._framesDropped, + streamStats._overflowCount); + + printf(" Inter-packet timegaps (overall) | min: %9s, max: %9s, avg: %9s\n", + formatUsecTime(streamStats._timeGapMin).toLatin1().data(), + formatUsecTime(streamStats._timeGapMax).toLatin1().data(), + formatUsecTime(streamStats._timeGapAverage).toLatin1().data()); + + printf(" Inter-packet timegaps (last 30s) | min: %9s, max: %9s, avg: %9s\n", + formatUsecTime(streamStats._timeGapWindowMin).toLatin1().data(), + formatUsecTime(streamStats._timeGapWindowMax).toLatin1().data(), + formatUsecTime(streamStats._timeGapWindowAverage).toLatin1().data()); +} diff --git a/assignment-client/src/audio/AudioMixerClientData.h b/assignment-client/src/audio/AudioMixerClientData.h index 80f3f9e3ca..0ce4ecc36a 100644 --- a/assignment-client/src/audio/AudioMixerClientData.h +++ b/assignment-client/src/audio/AudioMixerClientData.h @@ -38,6 +38,11 @@ public: void incrementOutgoingMixedAudioSequenceNumber() { _outgoingMixedAudioSequenceNumber++; } quint16 getOutgoingSequenceNumber() const { return _outgoingMixedAudioSequenceNumber; } + void printUpstreamDownstreamStats() const; + +private: + void printAudioStreamStats(const AudioStreamStats& streamStats) const; + private: QHash _audioStreams; // mic stream stored under key of null UUID diff --git a/domain-server/resources/web/settings/describe.json b/domain-server/resources/web/settings/describe.json index f4920a7b50..788a3ad551 100644 --- a/domain-server/resources/web/settings/describe.json +++ b/domain-server/resources/web/settings/describe.json @@ -21,6 +21,12 @@ "placeholder": "10", "default": "10" }, + "H-print-stream-stats": { + "type": "checkbox", + "label": "Print Stream Stats:", + "help": "If enabled, audio upstream and downstream stats of each agent will be printed each second to stdout", + "default": false + }, "D-unattenuated-zone": { "label": "Unattenuated Zone", "help": "Boxes for source and listener (corner x, corner y, corner z, size x, size y, size z, corner x, corner y, corner z, size x, size y, size z)", diff --git a/libraries/networking/src/SequenceNumberStats.cpp b/libraries/networking/src/SequenceNumberStats.cpp index 6a7f5e1964..f472159164 100644 --- a/libraries/networking/src/SequenceNumberStats.cpp +++ b/libraries/networking/src/SequenceNumberStats.cpp @@ -253,14 +253,19 @@ PacketStreamStats SequenceNumberStats::getStatsForHistoryWindow() const { } // calculate difference between newest stats and oldest stats to get window stats - PacketStreamStats windowStats; - windowStats._received = newestStats->_received - oldestStats->_received; - windowStats._unreasonable = newestStats->_unreasonable - oldestStats->_unreasonable; - windowStats._early = newestStats->_early - oldestStats->_early; - windowStats._late = newestStats->_late - oldestStats->_late; - windowStats._lost = newestStats->_lost - oldestStats->_lost; - windowStats._recovered = newestStats->_recovered - oldestStats->_recovered; - windowStats._expectedReceived = newestStats->_expectedReceived - oldestStats->_expectedReceived; - - return windowStats; + return *newestStats - *oldestStats; } + +PacketStreamStats SequenceNumberStats::getStatsForLastHistoryInterval() const { + + const PacketStreamStats* newestStats = _statsHistory.getNewestEntry(); + const PacketStreamStats* secondNewestStats = _statsHistory.get(1); + + // this catches cases where history is length 1 or 0 (both are NULL in case of 0) + if (newestStats == NULL || secondNewestStats == NULL) { + return PacketStreamStats(); + } + + return *newestStats - *secondNewestStats; +} + diff --git a/libraries/networking/src/SequenceNumberStats.h b/libraries/networking/src/SequenceNumberStats.h index 5e02dbc850..434d5a18db 100644 --- a/libraries/networking/src/SequenceNumberStats.h +++ b/libraries/networking/src/SequenceNumberStats.h @@ -31,6 +31,18 @@ public: _expectedReceived(0) {} + PacketStreamStats operator-(const PacketStreamStats& rhs) const { + PacketStreamStats diff; + diff._received = _received - rhs._received; + diff._unreasonable = _unreasonable - rhs._unreasonable; + diff._early = _early - rhs._early; + diff._late = _late - rhs._late; + diff._lost = _lost - rhs._lost; + diff._recovered = _recovered - rhs._recovered; + diff._expectedReceived = _expectedReceived - rhs._expectedReceived; + return diff; + } + float getLostRate() const { return (float)_lost / _expectedReceived; } quint32 _received; @@ -76,6 +88,7 @@ public: const PacketStreamStats& getStats() const { return _stats; } PacketStreamStats getStatsForHistoryWindow() const; + PacketStreamStats getStatsForLastHistoryInterval() const; const QSet& getMissingSet() const { return _missingSet; } private: diff --git a/tests/jitter/src/main.cpp b/tests/jitter/src/main.cpp index aefed73ccf..a33347f9ef 100644 --- a/tests/jitter/src/main.cpp +++ b/tests/jitter/src/main.cpp @@ -16,6 +16,8 @@ #include #include // for MovingMinMaxAvg +#include +#include #include // for usecTimestampNow const quint64 MSEC_TO_USEC = 1000; @@ -61,6 +63,8 @@ void runSend(const char* addressOption, int port, int gap, int size, int report) char* outputBuffer = new char[size]; memset(outputBuffer, 0, size); + + quint16 outgoingSequenceNumber = 0; sockfd=socket(AF_INET,SOCK_DGRAM,0); @@ -74,6 +78,16 @@ void runSend(const char* addressOption, int port, int gap, int size, int report) std::cout << "SAMPLES_FOR_30_SECONDS:" << SAMPLES_FOR_30_SECONDS << "\n"; MovingMinMaxAvg timeGaps(1, SAMPLES_FOR_30_SECONDS); // stats + + const int SAMPLES_PER_REPORT = report * MSEC_TO_USEC / gap; + + std::cout << "SAMPLES_PER_REPORT:" << SAMPLES_PER_REPORT << "\n"; + + MovingMinMaxAvg timeGapsPerReport(1, SAMPLES_PER_REPORT); + + StDev stDevReportInterval; + StDev stDev30s; + StDev stDev; quint64 last = usecTimestampNow(); quint64 lastReport = 0; @@ -85,21 +99,47 @@ void runSend(const char* addressOption, int port, int gap, int size, int report) if (actualGap >= gap) { + + // pack seq num + memcpy(outputBuffer, &outgoingSequenceNumber, sizeof(quint16)); + sendto(sockfd, outputBuffer, size, 0, (struct sockaddr *)&servaddr, sizeof(servaddr)); + outgoingSequenceNumber++; int gapDifferece = actualGap - gap; timeGaps.update(gapDifferece); + timeGapsPerReport.update(gapDifferece); + stDev.addValue(gapDifferece); + stDev30s.addValue(gapDifferece); + stDevReportInterval.addValue(gapDifferece); last = now; if (now - lastReport >= (report * MSEC_TO_USEC)) { - std::cout << "SEND gap Difference From Expected " + + std::cout << "\n" + << "SEND gap Difference From Expected\n" + << "Overall:\n" << "min: " << timeGaps.getMin() << " usecs, " << "max: " << timeGaps.getMax() << " usecs, " << "avg: " << timeGaps.getAverage() << " usecs, " - << "min last 30: " << timeGaps.getWindowMin() << " usecs, " - << "max last 30: " << timeGaps.getWindowMax() << " usecs, " - << "avg last 30: " << timeGaps.getWindowAverage() << " usecs " + << "stdev: " << stDev.getStDev() << " usecs\n" + << "Last 30s:\n" + << "min: " << timeGaps.getWindowMin() << " usecs, " + << "max: " << timeGaps.getWindowMax() << " usecs, " + << "avg: " << timeGaps.getWindowAverage() << " usecs, " + << "stdev: " << stDev30s.getStDev() << " usecs\n" + << "Last report interval:\n" + << "min: " << timeGapsPerReport.getWindowMin() << " usecs, " + << "max: " << timeGapsPerReport.getWindowMax() << " usecs, " + << "avg: " << timeGapsPerReport.getWindowAverage() << " usecs, " + << "stdev: " << stDevReportInterval.getStDev() << " usecs\n" << "\n"; + + stDevReportInterval.reset(); + if (stDev30s.getSamples() > SAMPLES_FOR_30_SECONDS) { + stDev30s.reset(); + } + lastReport = now; } } @@ -129,6 +169,22 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo MovingMinMaxAvg timeGaps(1, SAMPLES_FOR_30_SECONDS); // stats + const int SAMPLES_PER_REPORT = report * MSEC_TO_USEC / gap; + + std::cout << "SAMPLES_PER_REPORT:" << SAMPLES_PER_REPORT << "\n"; + + MovingMinMaxAvg timeGapsPerReport(1, SAMPLES_PER_REPORT); + + const int REPORTS_FOR_30_SECONDS = 30 * MSECS_PER_SECOND / report; + + std::cout << "REPORTS_FOR_30_SECONDS:" << REPORTS_FOR_30_SECONDS << "\n"; + + SequenceNumberStats seqStats(REPORTS_FOR_30_SECONDS); + + StDev stDevReportInterval; + StDev stDev30s; + StDev stDev; + if (bind(sockfd, (struct sockaddr *)&myaddr, sizeof(myaddr)) < 0) { std::cout << "bind failed\n"; return; @@ -139,6 +195,10 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo while (true) { n = recvfrom(sockfd, inputBuffer, size, 0, NULL, NULL); // we don't care about where it came from + + // parse seq num + quint16 incomingSequenceNumber = *(reinterpret_cast(inputBuffer)); + seqStats.sequenceNumberReceived(incomingSequenceNumber); if (last == 0) { last = usecTimestampNow(); @@ -148,17 +208,54 @@ void runReceive(const char* addressOption, int port, int gap, int size, int repo int actualGap = now - last; int gapDifferece = actualGap - gap; timeGaps.update(gapDifferece); + timeGapsPerReport.update(gapDifferece); + stDev.addValue(gapDifferece); + stDev30s.addValue(gapDifferece); + stDevReportInterval.addValue(gapDifferece); last = now; if (now - lastReport >= (report * MSEC_TO_USEC)) { - std::cout << "RECEIVE gap Difference From Expected " + + seqStats.pushStatsToHistory(); + + std::cout << "RECEIVE gap Difference From Expected\n" + << "Overall:\n" << "min: " << timeGaps.getMin() << " usecs, " << "max: " << timeGaps.getMax() << " usecs, " << "avg: " << timeGaps.getAverage() << " usecs, " - << "min last 30: " << timeGaps.getWindowMin() << " usecs, " - << "max last 30: " << timeGaps.getWindowMax() << " usecs, " - << "avg last 30: " << timeGaps.getWindowAverage() << " usecs " + << "stdev: " << stDev.getStDev() << " usecs\n" + << "Last 30s:\n" + << "min: " << timeGaps.getWindowMin() << " usecs, " + << "max: " << timeGaps.getWindowMax() << " usecs, " + << "avg: " << timeGaps.getWindowAverage() << " usecs, " + << "stdev: " << stDev30s.getStDev() << " usecs\n" + << "Last report interval:\n" + << "min: " << timeGapsPerReport.getWindowMin() << " usecs, " + << "max: " << timeGapsPerReport.getWindowMax() << " usecs, " + << "avg: " << timeGapsPerReport.getWindowAverage() << " usecs, " + << "stdev: " << stDevReportInterval.getStDev() << " usecs\n" << "\n"; + + stDevReportInterval.reset(); + if (stDev30s.getSamples() > SAMPLES_FOR_30_SECONDS) { + stDev30s.reset(); + } + + PacketStreamStats packetStatsLast30s = seqStats.getStatsForHistoryWindow(); + PacketStreamStats packetStatsLastReportInterval = seqStats.getStatsForLastHistoryInterval(); + + std::cout << "RECEIVE Packet Stats\n" + << "Overall:\n" + << "lost: " << seqStats.getLost() << ", " + << "lost %: " << seqStats.getStats().getLostRate() * 100.0f << "%\n" + << "Last 30s:\n" + << "lost: " << packetStatsLast30s._lost << ", " + << "lost %: " << packetStatsLast30s.getLostRate() * 100.0f << "%\n" + << "Last report interval:\n" + << "lost: " << packetStatsLastReportInterval._lost << ", " + << "lost %: " << packetStatsLastReportInterval.getLostRate() * 100.0f << "%\n" + << "\n\n"; + lastReport = now; } }