added some stats to the mixer fixed debug logging, improved timer precision

assignment-client/src/avatars/AvatarMixer.cpp

@@ -72,6 +72,8 @@ const float IDENTITY_SEND_PROBABILITY = 1.0f / 187.0f;
 //    1) use the view frustum to cull those avatars that are out of view. Since avatar data doesn't need to be present
 //       if the avatar is not in view or in the keyhole.
 void AvatarMixer::broadcastAvatarData() {
+    _broadcastRate.increment();
+
     int idleTime = AVATAR_DATA_SEND_INTERVAL_MSECS;
 
     if (_lastFrameTimestamp.time_since_epoch().count() > 0) {
@@ -160,6 +162,7 @@ void AvatarMixer::broadcastAvatarData() {
                 return;
             }
             ++_sumListeners;
+            nodeData->resetInViewStats();
 
             AvatarData& avatar = nodeData->getAvatar();
             glm::vec3 myPosition = avatar.getClientGlobalPosition();
@@ -360,6 +363,12 @@ void AvatarMixer::broadcastAvatarData() {
                     AABox otherNodeBox(otherNodeData->getGlobalBoundingBoxCorner(), otherNodeBoxScale);
                     bool sendMinimumForOutOfView = !nodeData->otherAvatarInView(otherNodeBox);
 
+                    if (sendMinimumForOutOfView) {
+                        nodeData->incrementAvatarOutOfView();
+                    } else {
+                        nodeData->incrementAvatarInView();
+                    }
+
                     numAvatarDataBytes += avatarPacketList->write(otherNode->getUUID().toRfc4122());
                     numAvatarDataBytes +=
                         avatarPacketList->write(otherAvatar.toByteArray(false, distribution(generator) < AVATAR_SEND_FULL_UPDATE_RATIO, sendMinimumForOutOfView));
@@ -391,6 +400,9 @@ void AvatarMixer::broadcastAvatarData() {
 
     // We're done encoding this version of the otherAvatars.  Update their "lastSent" joint-states so
     // that we can notice differences, next time around.
+    //
+    // FIXME - this seems suspicious, the code seems to consider all avatars, but not all avatars will
+    // have had their joints sent, so actually we should consider the time since they actually were sent????
     nodeList->eachMatchingNode(
         [&](const SharedNodePointer& otherNode)->bool {
             if (!otherNode->getLinkedData()) {
@@ -415,6 +427,18 @@ void AvatarMixer::broadcastAvatarData() {
         });
 
     _lastFrameTimestamp = p_high_resolution_clock::now();
+
+#ifdef WANT_DEBUG
+    auto sinceLastDebug = p_high_resolution_clock::now() - _lastDebugMessage;
+    auto sinceLastDebugUsecs = std::chrono::duration_cast<std::chrono::microseconds>(sinceLastDebug).count();
+    quint64 DEBUG_INTERVAL = USECS_PER_SECOND * 5;
+
+    if (sinceLastDebugUsecs > DEBUG_INTERVAL) {
+        qDebug() << "broadcast rate:" << _broadcastRate.rate() << "hz";
+        _lastDebugMessage = p_high_resolution_clock::now();
+    }
+#endif
+
 }
 
 void AvatarMixer::nodeKilled(SharedNodePointer killedNode) {
@@ -511,6 +535,7 @@ void AvatarMixer::sendStatsPacket() {
 
     statsObject["trailing_sleep_percentage"] = _trailingSleepRatio * 100;
     statsObject["performance_throttling_ratio"] = _performanceThrottlingRatio;
+    statsObject["broadcast_loop_rate"] = _broadcastRate.rate();
 
     QJsonObject avatarsObject;
 
@@ -563,6 +588,7 @@ void AvatarMixer::run() {
 
     // setup the timer that will be fired on the broadcast thread
     _broadcastTimer = new QTimer;
+    _broadcastTimer->setTimerType(Qt::PreciseTimer);
     _broadcastTimer->setInterval(AVATAR_DATA_SEND_INTERVAL_MSECS);
     _broadcastTimer->moveToThread(&_broadcastThread);
 

assignment-client/src/avatars/AvatarMixer.h

@@ -15,6 +15,7 @@
 #ifndef hifi_AvatarMixer_h
 #define hifi_AvatarMixer_h
 
+#include <shared/RateCounter.h>
 #include <PortableHighResolutionClock.h>
 
 #include <ThreadedAssignment.h>
@@ -65,6 +66,11 @@ private:
     float _domainMaximumScale { MAX_AVATAR_SCALE };
 
     QTimer* _broadcastTimer = nullptr;
+
+    RateCounter<> _broadcastRate;
+    p_high_resolution_clock::time_point _lastDebugMessage;
+
+
 };
 
 #endif // hifi_AvatarMixer_h

assignment-client/src/avatars/AvatarMixerClientData.cpp

@@ -84,4 +84,6 @@ void AvatarMixerClientData::loadJSONStats(QJsonObject& jsonObject) const {
     jsonObject[INBOUND_AVATAR_DATA_STATS_KEY] = _avatar->getAverageBytesReceivedPerSecond() / (float) BYTES_PER_KILOBIT;
 
     jsonObject["av_data_receive_rate"] = _avatar->getReceiveRate();
+    jsonObject["recent_other_av_in_view"] = _recentOtherAvatarsInView;
+    jsonObject["recent_other_av_out_of_view"] = _recentOtherAvatarsOutOfView;
 }

assignment-client/src/avatars/AvatarMixerClientData.h

@@ -93,6 +93,10 @@ public:
     bool otherAvatarInView(const AABox& otherAvatarBox);
     bool otherAvatarInView(const glm::vec3& otherAvatar);
 
+    void resetInViewStats() { _recentOtherAvatarsInView = _recentOtherAvatarsOutOfView = 0; }
+    void incrementAvatarInView() { _recentOtherAvatarsInView++; }
+    void incrementAvatarOutOfView() { _recentOtherAvatarsOutOfView++; }
+
 private:
     AvatarSharedPointer _avatar { new AvatarData() };
 
@@ -116,6 +120,9 @@ private:
     std::unordered_set<QUuid> _radiusIgnoredOthers;
     ViewFrustum _currentViewFrustum;
     bool _currentViewFrustumIsValid { false };
+
+    int _recentOtherAvatarsInView { 0 };
+    int _recentOtherAvatarsOutOfView { 0 };
 };
 
 #endif // hifi_AvatarMixerClientData_h

libraries/avatars/src/AvatarData.cpp

@@ -211,10 +211,7 @@ QByteArray AvatarData::toByteArray(bool cullSmallChanges, bool sendAll, bool sen
     if (sendMinimum) {
         memcpy(destinationBuffer, &_globalPosition, sizeof(_globalPosition));
         destinationBuffer += sizeof(_globalPosition);
-        qDebug() << __FUNCTION__ << "minimum... included global position!!";
     } else {
-        //qDebug() << __FUNCTION__ << "not minimum... sending actual content!!";
-
         auto header = reinterpret_cast<AvatarDataPacket::Header*>(destinationBuffer);
         header->position[0] = getLocalPosition().x;
         header->position[1] = getLocalPosition().y;