add AvatarsPerSec trace stats

interface/src/Application.cpp

@@ -570,16 +570,26 @@ Application::Application(int& argc, char** argv, QElapsedTimer& startupTimer, bo
         const QString TEST_SCRIPT = "--testScript";
         const QString TRACE_FILE = "--traceFile";
         const QStringList args = arguments();
-        for (int i = 0; i < args.size() - 1; ++i) {
+        std::cout << "adebug args.size() = " << args.size() << std::endl;  // adebug
+        for (int i = 0; i < args.size(); ++i) {
+            std::cout << i << "  adebug  '" << args.at(i).toStdString() << std::endl;  // adebug
             if (args.at(i) == TEST_SCRIPT) {
                 QString testScriptPath = args.at(i + 1);
+                std::cout << "adebug given test script '" << testScriptPath.toStdString() << "'" << std::endl;  // adebug
                 if (QFileInfo(testScriptPath).exists()) {
                     setProperty(hifi::properties::TEST, QUrl::fromLocalFile(testScriptPath));
+                    std::cout << "adebug found test script '" << testScriptPath.toStdString() << "'" << std::endl;  // adebug
+                    ++i;
+                } else {
+                    std::cout << "adebug did NOT find test script '" << testScriptPath.toStdString() << "'" << std::endl;  // adebug
+                }
+            } else {
+                std::cout << "adebug test script not specified'" << std::endl;  // adebug
+                if (args.at(i) == TRACE_FILE) {
+                    QString traceFilePath = args.at(i + 1);
+                    setProperty(hifi::properties::TRACING, traceFilePath);
+                    DependencyManager::get<tracing::Tracer>()->startTracing();
                 }
-            } else if (args.at(i) == TRACE_FILE) {
-                QString traceFilePath = args.at(i + 1);
-                setProperty(hifi::properties::TRACING, traceFilePath);
-                DependencyManager::get<tracing::Tracer>()->startTracing();
             }
         }
     }

interface/src/avatar/Avatar.cpp

@@ -75,6 +75,19 @@ namespace render {
     }
 }
 
+static uint64_t timeProcessingJoints = 0;
+static int32_t numJointsProcessed = 0;
+
+float Avatar::getNumJointsProcessedPerSecond() {
+    float rate = 0.0f;
+    if (timeProcessingJoints > 0) {
+        rate = (float)(numJointsProcessed * USECS_PER_SECOND) / (float)timeProcessingJoints;
+    }
+    timeProcessingJoints = 0;
+    numJointsProcessed = 0;
+    return rate;
+}
+
 Avatar::Avatar(RigPointer rig) :
     AvatarData(),
     _skeletonOffset(0.0f),
@@ -281,7 +294,7 @@ void Avatar::updateAvatarEntities() {
 void Avatar::simulate(float deltaTime) {
     PerformanceTimer perfTimer("simulate");
 
-    if (!isDead() && !_motionState) {
+    if (!_motionState && !isDead()) {
         DependencyManager::get<AvatarManager>()->addAvatarToSimulation(this);
     }
     animateScaleChanges(deltaTime);
@@ -319,6 +332,7 @@ void Avatar::simulate(float deltaTime) {
         }
     }
 
+    uint64_t start = usecTimestampNow();
     if (_shouldAnimate && !_shouldSkipRender && (avatarPositionInView || avatarMeshInView)) {
         {
             PerformanceTimer perfTimer("skeleton");
@@ -345,6 +359,8 @@ void Avatar::simulate(float deltaTime) {
         PerformanceTimer perfTimer("skeleton");
         _skeletonModel->simulate(deltaTime, false);
     }
+    timeProcessingJoints += usecTimestampNow() - start;
+    numJointsProcessed += _jointData.size();
 
     // update animation for display name fade in/out
     if ( _displayNameTargetAlpha != _displayNameAlpha) {
@@ -627,6 +643,7 @@ glm::quat Avatar::computeRotationFromBodyToWorldUp(float proportion) const {
 }
 
 void Avatar::fixupModelsInScene() {
+#ifdef FOO // adebug
     _attachmentsToDelete.clear();
 
     // check to see if when we added our models to the scene they were ready, if they were not ready, then
@@ -650,6 +667,7 @@ void Avatar::fixupModelsInScene() {
     _attachmentsToDelete.insert(_attachmentsToDelete.end(), _attachmentsToRemove.begin(), _attachmentsToRemove.end());
     _attachmentsToRemove.clear();
     scene->enqueuePendingChanges(pendingChanges);
+#endif // adebug
 }
 
 bool Avatar::shouldRenderHead(const RenderArgs* renderArgs) const {

interface/src/avatar/Avatar.h

@@ -57,6 +57,8 @@ class Avatar : public AvatarData {
     Q_PROPERTY(glm::vec3 skeletonOffset READ getSkeletonOffset WRITE setSkeletonOffset)
 
 public:
+    static float getNumJointsProcessedPerSecond();
+
     explicit Avatar(RigPointer rig = nullptr);
     ~Avatar();
 

interface/src/avatar/AvatarManager.cpp

@@ -25,13 +25,13 @@
 #endif
 
 
+#include <AvatarData.h>
 #include <PerfStat.h>
 #include <RegisteredMetaTypes.h>
 #include <Rig.h>
 #include <SettingHandle.h>
 #include <UsersScriptingInterface.h>
 #include <UUID.h>
-#include <AvatarData.h>
 
 #include "Application.h"
 #include "Avatar.h"
@@ -129,6 +129,8 @@ void AvatarManager::updateOtherAvatars(float deltaTime) {
     QReadLocker lock(&_hashLock);
 
     if (_avatarHash.size() < 2 && _avatarFades.isEmpty()) {
+        PROFILE_COUNTER(simulation_avatar, "AvatarsPerSec", { { "aps", 0.0f } });
+        PROFILE_COUNTER(simulation_avatar, "JointsPerSec", { { "jps", 0.0f } });
         return;
     }
 
@@ -143,6 +145,7 @@ void AvatarManager::updateOtherAvatars(float deltaTime) {
     // simulate avatars
     auto hashCopy = getHashCopy();
 
+    uint64_t start = usecTimestampNow();
     AvatarHash::iterator avatarIterator = hashCopy.begin();
     while (avatarIterator != hashCopy.end()) {
         auto avatar = std::static_pointer_cast<Avatar>(avatarIterator.value());
@@ -165,6 +168,9 @@ void AvatarManager::updateOtherAvatars(float deltaTime) {
 
     // simulate avatar fades
     simulateAvatarFades(deltaTime);
+    float avatarsPerSecond = (float)(size() * USECS_PER_SECOND) / (float)(usecTimestampNow() - start);
+    PROFILE_COUNTER(simulation_avatar, "AvatarsPerSec", { { "aps", avatarsPerSecond } });
+    PROFILE_COUNTER(simulation_avatar, "JointsPerSec", { { "jps", Avatar::getNumJointsProcessedPerSecond() } });
 }
 
 void AvatarManager::postUpdate(float deltaTime) {

libraries/shared/src/Profile.cpp

@@ -18,6 +18,7 @@ Q_LOGGING_CATEGORY(trace_resource_network, "trace.resource.network")
 Q_LOGGING_CATEGORY(trace_resource_parse, "trace.resource.parse")
 Q_LOGGING_CATEGORY(trace_simulation, "trace.simulation")
 Q_LOGGING_CATEGORY(trace_simulation_animation, "trace.simulation.animation")
+Q_LOGGING_CATEGORY(trace_simulation_avatar, "trace.simulation.avatar")
 Q_LOGGING_CATEGORY(trace_simulation_physics, "trace.simulation.physics")
 
 #if defined(NSIGHT_FOUND)

libraries/shared/src/Profile.h

@@ -22,6 +22,7 @@ Q_DECLARE_LOGGING_CATEGORY(trace_resource_parse)
 Q_DECLARE_LOGGING_CATEGORY(trace_resource_network)
 Q_DECLARE_LOGGING_CATEGORY(trace_simulation)
 Q_DECLARE_LOGGING_CATEGORY(trace_simulation_animation)
+Q_DECLARE_LOGGING_CATEGORY(trace_simulation_avatar)
 Q_DECLARE_LOGGING_CATEGORY(trace_simulation_physics)
 
 class Duration {