From 03114fa6106e807a8e4732e9c0b07b3fcb4d3cdc Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Tue, 20 Dec 2016 11:42:37 -0800 Subject: [PATCH 1/6] add AvatarsPerSec trace stats --- interface/src/Application.cpp | 20 +++++++++++++++----- interface/src/avatar/Avatar.cpp | 20 +++++++++++++++++++- interface/src/avatar/Avatar.h | 2 ++ interface/src/avatar/AvatarManager.cpp | 8 +++++++- libraries/shared/src/Profile.cpp | 1 + libraries/shared/src/Profile.h | 1 + 6 files changed, 45 insertions(+), 7 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 691c5051b1..5ca2e1bc7f 100644 --- a/interface/src/Application.cpp +++ b/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()->startTracing(); } - } else if (args.at(i) == TRACE_FILE) { - QString traceFilePath = args.at(i + 1); - setProperty(hifi::properties::TRACING, traceFilePath); - DependencyManager::get()->startTracing(); } } } diff --git a/interface/src/avatar/Avatar.cpp b/interface/src/avatar/Avatar.cpp index e83df85ff0..37840436fb 100644 --- a/interface/src/avatar/Avatar.cpp +++ b/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()->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 { diff --git a/interface/src/avatar/Avatar.h b/interface/src/avatar/Avatar.h index dd0a9b2ab1..784f380028 100644 --- a/interface/src/avatar/Avatar.h +++ b/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(); diff --git a/interface/src/avatar/AvatarManager.cpp b/interface/src/avatar/AvatarManager.cpp index e2058ae1cf..fa695d9287 100644 --- a/interface/src/avatar/AvatarManager.cpp +++ b/interface/src/avatar/AvatarManager.cpp @@ -25,13 +25,13 @@ #endif +#include #include #include #include #include #include #include -#include #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(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) { diff --git a/libraries/shared/src/Profile.cpp b/libraries/shared/src/Profile.cpp index 4c5882348e..33c5c15862 100644 --- a/libraries/shared/src/Profile.cpp +++ b/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) diff --git a/libraries/shared/src/Profile.h b/libraries/shared/src/Profile.h index 6d02a0939f..57a98deb73 100644 --- a/libraries/shared/src/Profile.h +++ b/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 { From 1788d19260c88e29b8336fb9f4519395e0c384ea Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Tue, 20 Dec 2016 14:00:25 -0800 Subject: [PATCH 2/6] remove some debug code --- interface/src/Application.cpp | 20 +++++--------------- interface/src/avatar/Avatar.cpp | 2 -- 2 files changed, 5 insertions(+), 17 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 5ca2e1bc7f..691c5051b1 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -570,26 +570,16 @@ Application::Application(int& argc, char** argv, QElapsedTimer& startupTimer, bo const QString TEST_SCRIPT = "--testScript"; const QString TRACE_FILE = "--traceFile"; const QStringList args = arguments(); - 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 + for (int i = 0; i < args.size() - 1; ++i) { 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()->startTracing(); } + } else if (args.at(i) == TRACE_FILE) { + QString traceFilePath = args.at(i + 1); + setProperty(hifi::properties::TRACING, traceFilePath); + DependencyManager::get()->startTracing(); } } } diff --git a/interface/src/avatar/Avatar.cpp b/interface/src/avatar/Avatar.cpp index 37840436fb..43ba8060f5 100644 --- a/interface/src/avatar/Avatar.cpp +++ b/interface/src/avatar/Avatar.cpp @@ -643,7 +643,6 @@ 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 @@ -667,7 +666,6 @@ 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 { From 991a61b7222b9977314d68ec0a06e6b6cb0947e6 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Tue, 20 Dec 2016 14:01:03 -0800 Subject: [PATCH 3/6] fix data collection for AvatarsPerSec --- interface/src/avatar/AvatarManager.cpp | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/interface/src/avatar/AvatarManager.cpp b/interface/src/avatar/AvatarManager.cpp index fa695d9287..88eda5f13a 100644 --- a/interface/src/avatar/AvatarManager.cpp +++ b/interface/src/avatar/AvatarManager.cpp @@ -129,8 +129,6 @@ 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; } @@ -168,9 +166,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() } }); + + PROFILE_COUNTER(app, "AvatarsPerSec", { { "aps", (float)(size() * USECS_PER_SECOND) / (float)(usecTimestampNow() - start) } }); + PROFILE_COUNTER(app, "JointsPerSec", { { "jps", Avatar::getNumJointsProcessedPerSecond() } }); } void AvatarManager::postUpdate(float deltaTime) { From 4d711d869c35ec7c49d1154382cc7210a7bc1b14 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Tue, 20 Dec 2016 14:45:11 -0800 Subject: [PATCH 4/6] cleanup --- interface/src/avatar/Avatar.cpp | 2 +- interface/src/avatar/AvatarManager.cpp | 5 +++-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/interface/src/avatar/Avatar.cpp b/interface/src/avatar/Avatar.cpp index 43ba8060f5..2f99ccfdc8 100644 --- a/interface/src/avatar/Avatar.cpp +++ b/interface/src/avatar/Avatar.cpp @@ -294,7 +294,7 @@ void Avatar::updateAvatarEntities() { void Avatar::simulate(float deltaTime) { PerformanceTimer perfTimer("simulate"); - if (!_motionState && !isDead()) { + if (!isDead() && !_motionState) { DependencyManager::get()->addAvatarToSimulation(this); } animateScaleChanges(deltaTime); diff --git a/interface/src/avatar/AvatarManager.cpp b/interface/src/avatar/AvatarManager.cpp index 88eda5f13a..b25968433d 100644 --- a/interface/src/avatar/AvatarManager.cpp +++ b/interface/src/avatar/AvatarManager.cpp @@ -167,8 +167,9 @@ void AvatarManager::updateOtherAvatars(float deltaTime) { // simulate avatar fades simulateAvatarFades(deltaTime); - PROFILE_COUNTER(app, "AvatarsPerSec", { { "aps", (float)(size() * USECS_PER_SECOND) / (float)(usecTimestampNow() - start) } }); - PROFILE_COUNTER(app, "JointsPerSec", { { "jps", Avatar::getNumJointsProcessedPerSecond() } }); + PROFILE_COUNTER(app, "NumAvatarsPerSec", + { { "NumAvatarsPerSec", (float)(size() * USECS_PER_SECOND) / (float)(usecTimestampNow() - start) } }); + PROFILE_COUNTER(app, "NumJointsPerSec", { { "NumJointsPerSec", Avatar::getNumJointsProcessedPerSecond() } }); } void AvatarManager::postUpdate(float deltaTime) { From fa18d548f7273cf0e94fd89dec587d08a6c155a2 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Tue, 20 Dec 2016 15:28:25 -0800 Subject: [PATCH 5/6] use proper category for NumAvatarsPerSec trace --- interface/src/avatar/AvatarManager.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/interface/src/avatar/AvatarManager.cpp b/interface/src/avatar/AvatarManager.cpp index b25968433d..ee92bc9210 100644 --- a/interface/src/avatar/AvatarManager.cpp +++ b/interface/src/avatar/AvatarManager.cpp @@ -167,9 +167,9 @@ void AvatarManager::updateOtherAvatars(float deltaTime) { // simulate avatar fades simulateAvatarFades(deltaTime); - PROFILE_COUNTER(app, "NumAvatarsPerSec", + PROFILE_COUNTER(simulation_avatar, "NumAvatarsPerSec", { { "NumAvatarsPerSec", (float)(size() * USECS_PER_SECOND) / (float)(usecTimestampNow() - start) } }); - PROFILE_COUNTER(app, "NumJointsPerSec", { { "NumJointsPerSec", Avatar::getNumJointsProcessedPerSecond() } }); + PROFILE_COUNTER(simulation_avatar, "NumJointsPerSec", { { "NumJointsPerSec", Avatar::getNumJointsProcessedPerSecond() } }); } void AvatarManager::postUpdate(float deltaTime) { From e43efa74de0708dffbbaf49e0548e87013029a82 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Tue, 20 Dec 2016 16:16:31 -0800 Subject: [PATCH 6/6] use sampled counter --- interface/src/avatar/AvatarManager.cpp | 7 +++++-- libraries/shared/src/Profile.cpp | 1 - libraries/shared/src/Profile.h | 1 - 3 files changed, 5 insertions(+), 4 deletions(-) diff --git a/interface/src/avatar/AvatarManager.cpp b/interface/src/avatar/AvatarManager.cpp index ee92bc9210..53f17e9635 100644 --- a/interface/src/avatar/AvatarManager.cpp +++ b/interface/src/avatar/AvatarManager.cpp @@ -124,6 +124,9 @@ void AvatarManager::updateMyAvatar(float deltaTime) { } } + +Q_LOGGING_CATEGORY(trace_simulation_avatar, "trace.simulation.avatar"); + void AvatarManager::updateOtherAvatars(float deltaTime) { // lock the hash for read to check the size QReadLocker lock(&_hashLock); @@ -167,9 +170,9 @@ void AvatarManager::updateOtherAvatars(float deltaTime) { // simulate avatar fades simulateAvatarFades(deltaTime); - PROFILE_COUNTER(simulation_avatar, "NumAvatarsPerSec", + SAMPLE_PROFILE_COUNTER(0.1f, simulation_avatar, "NumAvatarsPerSec", { { "NumAvatarsPerSec", (float)(size() * USECS_PER_SECOND) / (float)(usecTimestampNow() - start) } }); - PROFILE_COUNTER(simulation_avatar, "NumJointsPerSec", { { "NumJointsPerSec", Avatar::getNumJointsProcessedPerSecond() } }); + SAMPLE_PROFILE_COUNTER(0.1f, simulation_avatar, "NumJointsPerSec", { { "NumJointsPerSec", Avatar::getNumJointsProcessedPerSecond() } }); } void AvatarManager::postUpdate(float deltaTime) { diff --git a/libraries/shared/src/Profile.cpp b/libraries/shared/src/Profile.cpp index 33c5c15862..4c5882348e 100644 --- a/libraries/shared/src/Profile.cpp +++ b/libraries/shared/src/Profile.cpp @@ -18,7 +18,6 @@ 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) diff --git a/libraries/shared/src/Profile.h b/libraries/shared/src/Profile.h index 57a98deb73..6d02a0939f 100644 --- a/libraries/shared/src/Profile.h +++ b/libraries/shared/src/Profile.h @@ -22,7 +22,6 @@ 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 {