Merge pull request #9342 from jherico/trace_detail

More tracing support

interface/src/Application.cpp

@@ -193,8 +193,9 @@ static QTimer pingTimer;
 
 static const int MAX_CONCURRENT_RESOURCE_DOWNLOADS = 16;
 
-// For processing on QThreadPool, target 2 less than the ideal number of threads, leaving
+// For processing on QThreadPool, we target a number of threads after reserving some 
-// 2 logical cores available for time sensitive tasks.
+// based on how many are being consumed by the application and the display plugin.  However,
+// we will never drop below the 'min' value
 static const int MIN_PROCESSING_THREAD_POOL_SIZE = 2;
 
 static const QString SNAPSHOT_EXTENSION  = ".jpg";
@@ -3313,15 +3314,15 @@ void Application::idle(float nsecsElapsed) {
         connect(offscreenUi.data(), &OffscreenUi::showDesktop, this, &Application::showDesktop);
     }
 
-    PROFILE_COUNTER(app, "fps", { { "fps", _frameCounter.rate() } });
+    auto displayPlugin = getActiveDisplayPlugin();
-    PROFILE_COUNTER(app, "downloads", {
+    if (displayPlugin) {
-        { "current", ResourceCache::getLoadingRequests().length() },
+        PROFILE_COUNTER_IF_CHANGED(app, "present", float, displayPlugin->presentRate());
-        { "pending", ResourceCache::getPendingRequestCount() }
+    }
-    });
+    PROFILE_COUNTER_IF_CHANGED(app, "fps", float, _frameCounter.rate());
-    PROFILE_COUNTER(app, "processing", {
+    PROFILE_COUNTER_IF_CHANGED(app, "currentDownloads", int, ResourceCache::getLoadingRequests().length());
-        { "current", DependencyManager::get<StatTracker>()->getStat("Processing") },
+    PROFILE_COUNTER_IF_CHANGED(app, "pendingDownloads", int, ResourceCache::getPendingRequestCount());
-        { "pending", DependencyManager::get<StatTracker>()->getStat("PendingProcessing") }
+    PROFILE_COUNTER_IF_CHANGED(app, "currentProcessing", int, DependencyManager::get<StatTracker>()->getStat("Processing").toInt());
-    });
+    PROFILE_COUNTER_IF_CHANGED(app, "pendingProcessing", int, DependencyManager::get<StatTracker>()->getStat("PendingProcessing").toInt());
 
     PROFILE_RANGE(app, __FUNCTION__);
 

interface/src/scripting/TestScriptingInterface.cpp

@@ -18,6 +18,8 @@
 
 #include "Application.h"
 
+Q_LOGGING_CATEGORY(trace_test, "trace.test")
+
 TestScriptingInterface* TestScriptingInterface::getInstance() {
     static TestScriptingInterface sharedInstance;
     return &sharedInstance;
@@ -125,3 +127,10 @@ bool TestScriptingInterface::waitForCondition(qint64 maxWaitMs, std::function<bo
     return condition();
 }
 
+void TestScriptingInterface::startTraceEvent(QString name) {
+    tracing::traceEvent(trace_test(), name, tracing::DurationBegin, "");
+}
+
+void TestScriptingInterface::endTraceEvent(QString name) {
+    tracing::traceEvent(trace_test(), name, tracing::DurationEnd);
+}

interface/src/scripting/TestScriptingInterface.h

@@ -65,6 +65,11 @@ public slots:
     */
     bool stopTracing(QString filename);
 
+    void startTraceEvent(QString name);
+
+    void endTraceEvent(QString name);
+
+
 private:
     bool waitForCondition(qint64 maxWaitMs, std::function<bool()> condition);
 };

libraries/animation/src/Rig.cpp

@@ -902,7 +902,7 @@ void Rig::updateAnimationStateHandlers() { // called on avatar update thread (wh
 
 void Rig::updateAnimations(float deltaTime, glm::mat4 rootTransform) {
 
-    PROFILE_RANGE_EX(simulation_animation, __FUNCTION__, 0xffff00ff, 0);
+    PROFILE_RANGE_EX(simulation_animation_detail, __FUNCTION__, 0xffff00ff, 0);
     PerformanceTimer perfTimer("updateAnimations");
 
     setModelOffset(rootTransform);

libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp

@@ -561,22 +561,22 @@ void OpenGLDisplayPlugin::compositeLayers() {
     updateCompositeFramebuffer();
 
     {
-        PROFILE_RANGE_EX(render, "compositeScene", 0xff0077ff, (uint64_t)presentCount())
+        PROFILE_RANGE_EX(render_detail, "compositeScene", 0xff0077ff, (uint64_t)presentCount())
         compositeScene();
     }
 
     {
-        PROFILE_RANGE_EX(render, "compositeOverlay", 0xff0077ff, (uint64_t)presentCount())
+        PROFILE_RANGE_EX(render_detail, "compositeOverlay", 0xff0077ff, (uint64_t)presentCount())
         compositeOverlay();
     }
     auto compositorHelper = DependencyManager::get<CompositorHelper>();
     if (compositorHelper->getReticleVisible()) {
-        PROFILE_RANGE_EX(render, "compositePointer", 0xff0077ff, (uint64_t)presentCount())
+        PROFILE_RANGE_EX(render_detail, "compositePointer", 0xff0077ff, (uint64_t)presentCount())
         compositePointer();
     }
 
     {
-        PROFILE_RANGE_EX(render, "compositeExtra", 0xff0077ff, (uint64_t)presentCount())
+        PROFILE_RANGE_EX(render_detail, "compositeExtra", 0xff0077ff, (uint64_t)presentCount())
         compositeExtra();
     }
 }

libraries/entities-renderer/src/RenderableModelEntityItem.cpp

@@ -211,7 +211,7 @@ namespace render {
     template <> void payloadRender(const RenderableModelEntityItemMeta::Pointer& payload, RenderArgs* args) {
         if (args) {
             if (payload && payload->entity) {
-                PROFILE_RANGE(render, "MetaModelRender");
+                PROFILE_RANGE(render_detail, "MetaModelRender");
                 payload->entity->render(args);
             }
         }

libraries/gpu-gl/src/gpu/gl/GLBackend.cpp

@@ -200,7 +200,7 @@ void GLBackend::renderPassTransfer(const Batch& batch) {
 
     _inRenderTransferPass = true;
     { // Sync all the buffers
-        PROFILE_RANGE(render_gpu_gl, "syncGPUBuffer");
+        PROFILE_RANGE(render_gpu_gl_detail, "syncGPUBuffer");
 
         for (auto& cached : batch._buffers._items) {
             if (cached._data) {
@@ -210,7 +210,7 @@ void GLBackend::renderPassTransfer(const Batch& batch) {
     }
 
     { // Sync all the buffers
-        PROFILE_RANGE(render_gpu_gl, "syncCPUTransform");
+        PROFILE_RANGE(render_gpu_gl_detail, "syncCPUTransform");
         _transform._cameras.clear();
         _transform._cameraOffsets.clear();
 
@@ -242,7 +242,7 @@ void GLBackend::renderPassTransfer(const Batch& batch) {
     }
 
     { // Sync the transform buffers
-        PROFILE_RANGE(render_gpu_gl, "syncGPUTransform");
+        PROFILE_RANGE(render_gpu_gl_detail, "syncGPUTransform");
         transferTransformState(batch);
     }
 
@@ -304,7 +304,7 @@ void GLBackend::render(const Batch& batch) {
     }
     
     {
-        PROFILE_RANGE(render_gpu_gl, "Transfer");
+        PROFILE_RANGE(render_gpu_gl_detail, "Transfer");
         renderPassTransfer(batch);
     }
 
@@ -314,7 +314,7 @@ void GLBackend::render(const Batch& batch) {
     }
 #endif
     {
-        PROFILE_RANGE(render_gpu_gl, _stereo._enable ? "Render Stereo" : "Render");
+        PROFILE_RANGE(render_gpu_gl_detail, _stereo._enable ? "Render Stereo" : "Render");
         renderPassDraw(batch);
     }
 #ifdef GPU_STEREO_DRAWCALL_INSTANCED
@@ -387,18 +387,22 @@ void GLBackend::resetStages() {
 
 
 void GLBackend::do_pushProfileRange(const Batch& batch, size_t paramOffset) {
-    auto name = batch._profileRanges.get(batch._params[paramOffset]._uint);
+    if (trace_render_gpu_gl_detail().isDebugEnabled()) {
-    profileRanges.push_back(name);
+        auto name = batch._profileRanges.get(batch._params[paramOffset]._uint);
+        profileRanges.push_back(name);
 #if defined(NSIGHT_FOUND)
-    nvtxRangePush(name.c_str());
+        nvtxRangePush(name.c_str());
 #endif
+    }
 }
 
 void GLBackend::do_popProfileRange(const Batch& batch, size_t paramOffset) {
-    profileRanges.pop_back();
+    if (trace_render_gpu_gl_detail().isDebugEnabled()) {
+        profileRanges.pop_back();
 #if defined(NSIGHT_FOUND)
-    nvtxRangePop();
+        nvtxRangePop();
 #endif
+    }
 }
 
 // TODO: As long as we have gl calls explicitely issued from interface

libraries/gpu-gl/src/gpu/gl/GLBackendQuery.cpp

@@ -28,7 +28,7 @@ void GLBackend::do_beginQuery(const Batch& batch, size_t paramOffset) {
     auto query = batch._queries.get(batch._params[paramOffset]._uint);
     GLQuery* glquery = syncGPUObject(*query);
     if (glquery) {
-        PROFILE_RANGE_BEGIN(render_gpu_gl, glquery->_profileRangeId, query->getName().c_str(), 0xFFFF7F00);
+        PROFILE_RANGE_BEGIN(render_gpu_gl_detail, glquery->_profileRangeId, query->getName().c_str(), 0xFFFF7F00);
 
         ++_queryStage._rangeQueryDepth;
         glGetInteger64v(GL_TIMESTAMP, (GLint64*)&glquery->_batchElapsedTime);
@@ -62,7 +62,7 @@ void GLBackend::do_endQuery(const Batch& batch, size_t paramOffset) {
         glGetInteger64v(GL_TIMESTAMP, &now);
         glquery->_batchElapsedTime = now - glquery->_batchElapsedTime;
 
-        PROFILE_RANGE_END(render_gpu_gl, glquery->_profileRangeId);
+        PROFILE_RANGE_END(render_gpu_gl_detail, glquery->_profileRangeId);
 
         (void)CHECK_GL_ERROR();
     }

libraries/gpu-gl/src/gpu/gl/GLShared.cpp

@@ -17,6 +17,7 @@
 
 Q_LOGGING_CATEGORY(gpugllogging, "hifi.gpu.gl")
 Q_LOGGING_CATEGORY(trace_render_gpu_gl, "trace.render.gpu.gl")
+Q_LOGGING_CATEGORY(trace_render_gpu_gl_detail, "trace.render.gpu.gl.detail")
 
 namespace gpu { namespace gl {
 

libraries/gpu-gl/src/gpu/gl/GLShared.h

@@ -16,6 +16,7 @@
 
 Q_DECLARE_LOGGING_CATEGORY(gpugllogging)
 Q_DECLARE_LOGGING_CATEGORY(trace_render_gpu_gl)
+Q_DECLARE_LOGGING_CATEGORY(trace_render_gpu_gl_detail)
 
 namespace gpu { namespace gl { 
 

libraries/render-utils/src/Model.cpp

@@ -283,7 +283,7 @@ void Model::reset() {
 }
 
 bool Model::updateGeometry() {
-    PROFILE_RANGE(render, __FUNCTION__);
+    PROFILE_RANGE(render_detail, __FUNCTION__);
     PerformanceTimer perfTimer("Model::updateGeometry");
     bool needFullUpdate = false;
 
@@ -1114,7 +1114,7 @@ void Model::snapToRegistrationPoint() {
 }
 
 void Model::simulate(float deltaTime, bool fullUpdate) {
-    PROFILE_RANGE(simulation, __FUNCTION__);
+    PROFILE_RANGE(simulation_detail, __FUNCTION__);
     PerformanceTimer perfTimer("Model::simulate");
     fullUpdate = updateGeometry() || fullUpdate || (_scaleToFit && !_scaledToFit)
                     || (_snapModelToRegistrationPoint && !_snappedToRegistrationPoint);

libraries/shared/src/Profile.cpp

@@ -9,16 +9,21 @@
 #include "Profile.h"
 
 Q_LOGGING_CATEGORY(trace_app, "trace.app")
+Q_LOGGING_CATEGORY(trace_app_detail, "trace.app.detail")
 Q_LOGGING_CATEGORY(trace_network, "trace.network")
 Q_LOGGING_CATEGORY(trace_parse, "trace.parse")
 Q_LOGGING_CATEGORY(trace_render, "trace.render")
+Q_LOGGING_CATEGORY(trace_render_detail, "trace.render.detail")
 Q_LOGGING_CATEGORY(trace_render_gpu, "trace.render.gpu")
 Q_LOGGING_CATEGORY(trace_resource, "trace.resource")
 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_detail, "trace.simulation.detail")
 Q_LOGGING_CATEGORY(trace_simulation_animation, "trace.simulation.animation")
+Q_LOGGING_CATEGORY(trace_simulation_animation_detail, "trace.simulation.animation.detail")
 Q_LOGGING_CATEGORY(trace_simulation_physics, "trace.simulation.physics")
+Q_LOGGING_CATEGORY(trace_simulation_physics_detail, "trace.simulation.physics.detail")
 
 #if defined(NSIGHT_FOUND)
 #include "nvToolsExt.h"

libraries/shared/src/Profile.h

@@ -13,16 +13,22 @@
 #include "Trace.h"
 #include "SharedUtil.h"
 
+// When profiling something that may happen many times per frame, use a xxx_detail category so that they may easily be filtered out of trace results
 Q_DECLARE_LOGGING_CATEGORY(trace_app)
+Q_DECLARE_LOGGING_CATEGORY(trace_app_detail)
 Q_DECLARE_LOGGING_CATEGORY(trace_network)
 Q_DECLARE_LOGGING_CATEGORY(trace_render)
+Q_DECLARE_LOGGING_CATEGORY(trace_render_detail)
 Q_DECLARE_LOGGING_CATEGORY(trace_render_gpu)
 Q_DECLARE_LOGGING_CATEGORY(trace_resource)
 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_detail)
 Q_DECLARE_LOGGING_CATEGORY(trace_simulation_animation)
+Q_DECLARE_LOGGING_CATEGORY(trace_simulation_animation_detail)
 Q_DECLARE_LOGGING_CATEGORY(trace_simulation_physics)
+Q_DECLARE_LOGGING_CATEGORY(trace_simulation_physics_detail)
 
 class Duration {
 public:
@@ -69,6 +75,7 @@ inline void counter(const QLoggingCategory& category, const QString& name, const
 #define PROFILE_RANGE_END(category, rangeId) Duration::endRange(trace_##category(), rangeId)
 #define PROFILE_ASYNC_BEGIN(category, name, id, ...) asyncBegin(trace_##category(), name, id, ##__VA_ARGS__);
 #define PROFILE_ASYNC_END(category, name, id, ...) asyncEnd(trace_##category(), name, id, ##__VA_ARGS__);
+#define PROFILE_COUNTER_IF_CHANGED(category, name, type, value) { static type lastValue = 0; type newValue = value;  if (newValue != lastValue) { counter(trace_##category(), name, { { name, newValue }}); lastValue = newValue; } }
 #define PROFILE_COUNTER(category, name, ...) counter(trace_##category(), name, ##__VA_ARGS__);
 #define PROFILE_INSTANT(category, name, ...) instant(trace_##category(), name, ##__VA_ARGS__);