From 30a9961362bf2fd2d9b30e571e1ff5027df29ba9 Mon Sep 17 00:00:00 2001 From: Brad Davis Date: Fri, 16 Dec 2016 13:41:33 -0800 Subject: [PATCH] tracing polish --- interface/src/Application.cpp | 63 ++++++++++--------- interface/src/ui/ApplicationOverlay.cpp | 10 +-- interface/src/ui/overlays/Overlays.cpp | 3 +- .../animation/src/AnimInverseKinematics.cpp | 10 +-- libraries/animation/src/AnimationCache.cpp | 2 +- libraries/animation/src/Rig.cpp | 2 +- .../display-plugins/OpenGLDisplayPlugin.cpp | 22 +++---- .../display-plugins/hmd/HmdDisplayPlugin.cpp | 2 +- .../src/RenderableModelEntityItem.cpp | 2 +- libraries/fbx/src/FBXReader_Node.cpp | 2 +- libraries/fbx/src/OBJReader.cpp | 2 +- libraries/gl/src/gl/OffscreenQmlSurface.cpp | 7 ++- libraries/gpu-gl/src/gpu/gl/GLBackend.cpp | 10 +-- .../gpu-gl/src/gpu/gl/GLBackendQuery.cpp | 4 +- libraries/gpu-gl/src/gpu/gl/GLShared.cpp | 1 + libraries/gpu-gl/src/gpu/gl/GLShared.h | 1 + .../src/gpu/gl41/GL41BackendTexture.cpp | 2 +- libraries/gpu/src/gpu/Texture.cpp | 4 +- .../src/model-networking/ModelCache.cpp | 8 ++- .../src/model-networking/TextureCache.cpp | 6 +- libraries/model/src/model/TextureMap.cpp | 6 +- libraries/networking/src/ResourceCache.cpp | 8 +-- libraries/networking/src/udt/SendQueue.cpp | 8 +-- libraries/octree/src/OctreeElement.cpp | 1 - .../src/DeferredLightingEffect.cpp | 2 +- libraries/render-utils/src/Model.cpp | 8 +-- libraries/render/src/render/Scene.cpp | 17 ++--- libraries/render/src/render/Task.h | 2 +- libraries/shared/src/Profile.cpp | 15 +++++ libraries/shared/src/Profile.h | 33 +++++++--- libraries/shared/src/Trace.cpp | 22 ++++++- libraries/shared/src/Trace.h | 2 - plugins/oculus/src/OculusDisplayPlugin.cpp | 2 +- plugins/openvr/src/OpenVrDisplayPlugin.cpp | 6 +- tests/render-perf/src/main.cpp | 2 +- tests/shared/src/TraceTests.cpp | 16 ++--- 36 files changed, 191 insertions(+), 122 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index c49575a5f1..e75b295207 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -179,6 +179,8 @@ extern "C" { } #endif +Q_LOGGING_CATEGORY(trace_app_input_mouse, "trace.app.input.mouse") + using namespace std; static QTimer locationUpdateTimer; @@ -1945,16 +1947,6 @@ void Application::initializeUi() { } void Application::paintGL() { - PROFILE_COUNTER(interfaceapp, "fps", { { "fps", _frameCounter.rate() } }); - PROFILE_COUNTER(interfaceapp, "downloads", { - { "current", ResourceCache::getLoadingRequests().length() }, - { "pending", ResourceCache::getPendingRequestCount() } - }); - PROFILE_COUNTER(interfaceapp, "processing", { - { "current", DependencyManager::get()->getStat("Processing") }, - { "pending", DependencyManager::get()->getStat("PendingProcessing") } - }); - // Some plugins process message events, allowing paintGL to be called reentrantly. if (_inPaint || _aboutToQuit) { return; @@ -1966,7 +1958,7 @@ void Application::paintGL() { _frameCount++; auto lastPaintBegin = usecTimestampNow(); - PROFILE_RANGE_EX(interfaceapp, __FUNCTION__, 0xff0000ff, (uint64_t)_frameCount); + PROFILE_RANGE_EX(render, __FUNCTION__, 0xff0000ff, (uint64_t)_frameCount); PerformanceTimer perfTimer("paintGL"); if (nullptr == _displayPlugin) { @@ -2143,7 +2135,7 @@ void Application::paintGL() { auto finalFramebuffer = framebufferCache->getFramebuffer(); { - PROFILE_RANGE(interfaceapp, "/mainRender"); + PROFILE_RANGE(render, "/mainRender"); PerformanceTimer perfTimer("mainRender"); renderArgs._boomOffset = boomOffset; // Viewport is assigned to the size of the framebuffer @@ -2198,7 +2190,7 @@ void Application::paintGL() { frame->overlay = _applicationOverlay.getOverlayTexture(); // deliver final scene rendering commands to the display plugin { - PROFILE_RANGE(interfaceapp, "/pluginOutput"); + PROFILE_RANGE(render, "/pluginOutput"); PerformanceTimer perfTimer("pluginOutput"); _frameCounter.increment(); displayPlugin->submitFrame(frame); @@ -2286,7 +2278,7 @@ void Application::resizeEvent(QResizeEvent* event) { } void Application::resizeGL() { - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(render, __FUNCTION__); if (nullptr == _displayPlugin) { return; } @@ -2931,7 +2923,7 @@ void Application::maybeToggleMenuVisible(QMouseEvent* event) const { } void Application::mouseMoveEvent(QMouseEvent* event) { - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(app_input_mouse, __FUNCTION__); if (_aboutToQuit) { return; @@ -3241,6 +3233,18 @@ void Application::idle(float nsecsElapsed) { connect(offscreenUi.data(), &OffscreenUi::showDesktop, this, &Application::showDesktop); } + PROFILE_COUNTER(app, "fps", { { "fps", _frameCounter.rate() } }); + PROFILE_COUNTER(app, "downloads", { + { "current", ResourceCache::getLoadingRequests().length() }, + { "pending", ResourceCache::getPendingRequestCount() } + }); + PROFILE_COUNTER(app, "processing", { + { "current", DependencyManager::get()->getStat("Processing") }, + { "pending", DependencyManager::get()->getStat("PendingProcessing") } + }); + + PROFILE_RANGE(app, __FUNCTION__); + if (auto steamClient = PluginManager::getInstance()->getSteamClientPlugin()) { steamClient->runCallbacks(); } @@ -3958,7 +3962,7 @@ static bool domainLoadingInProgress = false; void Application::update(float deltaTime) { - PROFILE_RANGE_EX(interfaceapp, __FUNCTION__, 0xffff0000, (uint64_t)_frameCount + 1); + PROFILE_RANGE_EX(app, __FUNCTION__, 0xffff0000, (uint64_t)_frameCount + 1); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::update()"); @@ -3967,7 +3971,7 @@ void Application::update(float deltaTime) { if (!_physicsEnabled) { if (!domainLoadingInProgress) { - PROFILE_ASYNC_BEGIN(interfaceapp, "Scene Loading", ""); + PROFILE_ASYNC_BEGIN(app, "Scene Loading", ""); domainLoadingInProgress = true; } @@ -4002,7 +4006,7 @@ void Application::update(float deltaTime) { } } else if (domainLoadingInProgress) { domainLoadingInProgress = false; - PROFILE_ASYNC_END(interfaceapp, "Scene Loading", ""); + PROFILE_ASYNC_END(app, "Scene Loading", ""); } { @@ -4096,12 +4100,12 @@ void Application::update(float deltaTime) { QSharedPointer avatarManager = DependencyManager::get(); if (_physicsEnabled) { - PROFILE_RANGE_EX(interfaceapp, "Physics", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(simulation_physics, "Physics", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("physics"); { - PROFILE_RANGE_EX(interfaceapp, "UpdateStats", 0xffffff00, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(simulation_physics, "UpdateStats", 0xffffff00, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("updateStates)"); static VectorOfMotionStates motionStates; @@ -4135,14 +4139,14 @@ void Application::update(float deltaTime) { }); } { - PROFILE_RANGE_EX(interfaceapp, "StepSimulation", 0xffff8000, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(simulation_physics, "StepSimulation", 0xffff8000, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("stepSimulation"); getEntities()->getTree()->withWriteLock([&] { _physicsEngine->stepSimulation(); }); } { - PROFILE_RANGE_EX(interfaceapp, "HarvestChanges", 0xffffff00, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(simulation_physics, "HarvestChanges", 0xffffff00, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("harvestChanges"); if (_physicsEngine->hasOutgoingChanges()) { getEntities()->getTree()->withWriteLock([&] { @@ -4184,20 +4188,20 @@ void Application::update(float deltaTime) { _avatarSimCounter.increment(); { - PROFILE_RANGE_EX(interfaceapp, "OtherAvatars", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(simulation, "OtherAvatars", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount()); avatarManager->updateOtherAvatars(deltaTime); } qApp->updateMyAvatarLookAtPosition(); { - PROFILE_RANGE_EX(interfaceapp, "MyAvatar", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(simulation, "MyAvatar", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount()); avatarManager->updateMyAvatar(deltaTime); } } { - PROFILE_RANGE_EX(interfaceapp, "Overlays", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(app, "Overlays", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("overlays"); _overlays.update(deltaTime); } @@ -4217,7 +4221,7 @@ void Application::update(float deltaTime) { // Update my voxel servers with my current voxel query... { - PROFILE_RANGE_EX(interfaceapp, "QueryOctree", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(app, "QueryOctree", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); QMutexLocker viewLocker(&_viewMutex); PerformanceTimer perfTimer("queryOctree"); quint64 sinceLastQuery = now - _lastQueriedTime; @@ -4257,7 +4261,7 @@ void Application::update(float deltaTime) { avatarManager->postUpdate(deltaTime); { - PROFILE_RANGE_EX(interfaceapp, "PreRenderLambdas", 0xffff0000, (uint64_t)0); + PROFILE_RANGE_EX(app, "PreRenderLambdas", 0xffff0000, (uint64_t)0); std::unique_lock guard(_postUpdateLambdasLock); for (auto& iter : _postUpdateLambdas) { @@ -4534,8 +4538,11 @@ QRect Application::getDesirableApplicationGeometry() const { // or the "myCamera". // void Application::loadViewFrustum(Camera& camera, ViewFrustum& viewFrustum) { +<<<<<<< HEAD PROFILE_RANGE(interfaceapp, __FUNCTION__); PerformanceTimer perfTimer("loadViewFrustum"); +======= +>>>>>>> tracing polish // We will use these below, from either the camera or head vectors calculated above viewFrustum.setProjection(camera.getProjection()); @@ -4711,7 +4718,7 @@ void Application::displaySide(RenderArgs* renderArgs, Camera& theCamera, bool se myAvatar->preDisplaySide(renderArgs); activeRenderingThread = QThread::currentThread(); - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(render, __FUNCTION__); PerformanceTimer perfTimer("display"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide()"); diff --git a/interface/src/ui/ApplicationOverlay.cpp b/interface/src/ui/ApplicationOverlay.cpp index f7bbc1aa96..364dff52a3 100644 --- a/interface/src/ui/ApplicationOverlay.cpp +++ b/interface/src/ui/ApplicationOverlay.cpp @@ -57,7 +57,7 @@ ApplicationOverlay::~ApplicationOverlay() { // Renders the overlays either to a texture or to the screen void ApplicationOverlay::renderOverlay(RenderArgs* renderArgs) { - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(render, __FUNCTION__); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "ApplicationOverlay::displayOverlay()"); buildFramebufferObject(); @@ -96,7 +96,7 @@ void ApplicationOverlay::renderOverlay(RenderArgs* renderArgs) { } void ApplicationOverlay::renderQmlUi(RenderArgs* renderArgs) { - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(app, __FUNCTION__); if (!_uiTexture) { _uiTexture = gpu::TexturePointer(gpu::Texture::createExternal2D(OffscreenQmlSurface::getDiscardLambda())); @@ -124,7 +124,7 @@ void ApplicationOverlay::renderQmlUi(RenderArgs* renderArgs) { } void ApplicationOverlay::renderAudioScope(RenderArgs* renderArgs) { - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(app, __FUNCTION__); gpu::Batch& batch = *renderArgs->_batch; auto geometryCache = DependencyManager::get(); @@ -143,7 +143,7 @@ void ApplicationOverlay::renderAudioScope(RenderArgs* renderArgs) { } void ApplicationOverlay::renderOverlays(RenderArgs* renderArgs) { - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(app, __FUNCTION__); gpu::Batch& batch = *renderArgs->_batch; auto geometryCache = DependencyManager::get(); @@ -262,7 +262,7 @@ static const auto DEFAULT_SAMPLER = gpu::Sampler(gpu::Sampler::FILTER_MIN_MAG_LI static const auto DEPTH_FORMAT = gpu::Element(gpu::SCALAR, gpu::FLOAT, gpu::DEPTH); void ApplicationOverlay::buildFramebufferObject() { - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(app, __FUNCTION__); auto uiSize = qApp->getUiSize(); if (!_overlayFramebuffer || uiSize != _overlayFramebuffer->getSize()) { diff --git a/interface/src/ui/overlays/Overlays.cpp b/interface/src/ui/overlays/Overlays.cpp index b1f2f60adc..889eec3b9c 100644 --- a/interface/src/ui/overlays/Overlays.cpp +++ b/interface/src/ui/overlays/Overlays.cpp @@ -37,6 +37,7 @@ #include "Web3DOverlay.h" #include +Q_LOGGING_CATEGORY(trace_render_overlays, "trace.render.overlays") Overlays::Overlays() : _nextOverlayID(1) {} @@ -102,7 +103,7 @@ void Overlays::cleanupOverlaysToDelete() { } void Overlays::renderHUD(RenderArgs* renderArgs) { - PROFILE_RANGE(interfaceapp, __FUNCTION__); + PROFILE_RANGE(render_overlays, __FUNCTION__); QReadLocker lock(&_lock); gpu::Batch& batch = *renderArgs->_batch; diff --git a/libraries/animation/src/AnimInverseKinematics.cpp b/libraries/animation/src/AnimInverseKinematics.cpp index c067157e98..c97808dce5 100644 --- a/libraries/animation/src/AnimInverseKinematics.cpp +++ b/libraries/animation/src/AnimInverseKinematics.cpp @@ -394,7 +394,7 @@ const AnimPoseVec& AnimInverseKinematics::overlay(const AnimVariantMap& animVars loadPoses(underPoses); } else { - PROFILE_RANGE_EX(animation, "ik/relax", 0xffff00ff, 0); + PROFILE_RANGE_EX(simulation_animation, "ik/relax", 0xffff00ff, 0); // relax toward underPoses // HACK: this relaxation needs to be constant per-frame rather than per-realtime @@ -433,7 +433,7 @@ const AnimPoseVec& AnimInverseKinematics::overlay(const AnimVariantMap& animVars // build a list of targets from _targetVarVec std::vector targets; { - PROFILE_RANGE_EX(animation, "ik/computeTargets", 0xffff00ff, 0); + PROFILE_RANGE_EX(simulation_animation, "ik/computeTargets", 0xffff00ff, 0); computeTargets(animVars, targets, underPoses); } @@ -450,7 +450,7 @@ const AnimPoseVec& AnimInverseKinematics::overlay(const AnimVariantMap& animVars } else { { - PROFILE_RANGE_EX(animation, "ik/shiftHips", 0xffff00ff, 0); + PROFILE_RANGE_EX(simulation_animation, "ik/shiftHips", 0xffff00ff, 0); // shift hips according to the _hipsOffset from the previous frame float offsetLength = glm::length(_hipsOffset); @@ -476,12 +476,12 @@ const AnimPoseVec& AnimInverseKinematics::overlay(const AnimVariantMap& animVars } { - PROFILE_RANGE_EX(animation, "ik/ccd", 0xffff00ff, 0); + PROFILE_RANGE_EX(simulation_animation, "ik/ccd", 0xffff00ff, 0); solveWithCyclicCoordinateDescent(targets); } { - PROFILE_RANGE_EX(animation, "ik/measureHipsOffset", 0xffff00ff, 0); + PROFILE_RANGE_EX(simulation_animation, "ik/measureHipsOffset", 0xffff00ff, 0); // measure new _hipsOffset for next frame // by looking for discrepancies between where a targeted endEffector is diff --git a/libraries/animation/src/AnimationCache.cpp b/libraries/animation/src/AnimationCache.cpp index 09dda3671f..6594482085 100644 --- a/libraries/animation/src/AnimationCache.cpp +++ b/libraries/animation/src/AnimationCache.cpp @@ -55,7 +55,7 @@ void AnimationReader::run() { DependencyManager::get()->decrementStat("PendingProcessing"); CounterStat counter("Processing"); - PROFILE_RANGE_EX(animation, __FUNCTION__, 0xFF00FF00, 0, { { "url", _url.toString() } }); + PROFILE_RANGE_EX(resource_parse, __FUNCTION__, 0xFF00FF00, 0, { { "url", _url.toString() } }); auto originalPriority = QThread::currentThread()->priority(); if (originalPriority == QThread::InheritPriority) { originalPriority = QThread::NormalPriority; diff --git a/libraries/animation/src/Rig.cpp b/libraries/animation/src/Rig.cpp index a8027d42ad..886eafffcf 100644 --- a/libraries/animation/src/Rig.cpp +++ b/libraries/animation/src/Rig.cpp @@ -883,7 +883,7 @@ void Rig::updateAnimationStateHandlers() { // called on avatar update thread (wh void Rig::updateAnimations(float deltaTime, glm::mat4 rootTransform) { - PROFILE_RANGE_EX(animation, __FUNCTION__, 0xffff00ff, 0); + PROFILE_RANGE_EX(simulation_animation, __FUNCTION__, 0xffff00ff, 0); setModelOffset(rootTransform); diff --git a/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp b/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp index 1c73e4dda2..68c05062fd 100644 --- a/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp +++ b/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp @@ -129,7 +129,7 @@ public: _context->makeCurrent(); while (!_shutdown) { if (_pendingMainThreadOperation) { - PROFILE_RANGE(displayPlugins, "MainThreadOp") + PROFILE_RANGE(render, "MainThreadOp") { Lock lock(_mutex); _context->doneCurrent(); @@ -203,7 +203,7 @@ public: // Execute the frame and present it to the display device. _context->makeCurrent(); { - PROFILE_RANGE(displayPlugins, "PluginPresent") + PROFILE_RANGE(render, "PluginPresent") currentPlugin->present(); CHECK_GL_ERROR(); } @@ -560,22 +560,22 @@ void OpenGLDisplayPlugin::compositeLayers() { updateCompositeFramebuffer(); { - PROFILE_RANGE_EX(displayPlugins, "compositeScene", 0xff0077ff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, "compositeScene", 0xff0077ff, (uint64_t)presentCount()) compositeScene(); } { - PROFILE_RANGE_EX(displayPlugins, "compositeOverlay", 0xff0077ff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, "compositeOverlay", 0xff0077ff, (uint64_t)presentCount()) compositeOverlay(); } auto compositorHelper = DependencyManager::get(); if (compositorHelper->getReticleVisible()) { - PROFILE_RANGE_EX(displayPlugins, "compositePointer", 0xff0077ff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, "compositePointer", 0xff0077ff, (uint64_t)presentCount()) compositePointer(); } { - PROFILE_RANGE_EX(displayPlugins, "compositeExtra", 0xff0077ff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, "compositeExtra", 0xff0077ff, (uint64_t)presentCount()) compositeExtra(); } } @@ -595,12 +595,12 @@ void OpenGLDisplayPlugin::internalPresent() { } void OpenGLDisplayPlugin::present() { - PROFILE_RANGE_EX(displayPlugins, __FUNCTION__, 0xffffff00, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, __FUNCTION__, 0xffffff00, (uint64_t)presentCount()) updateFrameData(); incrementPresentCount(); { - PROFILE_RANGE_EX(displayPlugins, "recycle", 0xff00ff00, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, "recycle", 0xff00ff00, (uint64_t)presentCount()) _gpuContext->recycle(); } @@ -614,19 +614,19 @@ void OpenGLDisplayPlugin::present() { _lastFrame = _currentFrame.get(); }); // Execute the frame rendering commands - PROFILE_RANGE_EX(displayPlugins, "execute", 0xff00ff00, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, "execute", 0xff00ff00, (uint64_t)presentCount()) _gpuContext->executeFrame(_currentFrame); } // Write all layers to a local framebuffer { - PROFILE_RANGE_EX(displayPlugins, "composite", 0xff00ffff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, "composite", 0xff00ffff, (uint64_t)presentCount()) compositeLayers(); } // Take the composite framebuffer and send it to the output device { - PROFILE_RANGE_EX(displayPlugins, "internalPresent", 0xff00ffff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, "internalPresent", 0xff00ffff, (uint64_t)presentCount()) internalPresent(); } diff --git a/libraries/display-plugins/src/display-plugins/hmd/HmdDisplayPlugin.cpp b/libraries/display-plugins/src/display-plugins/hmd/HmdDisplayPlugin.cpp index 1bfe73b687..e0c3dab1ed 100644 --- a/libraries/display-plugins/src/display-plugins/hmd/HmdDisplayPlugin.cpp +++ b/libraries/display-plugins/src/display-plugins/hmd/HmdDisplayPlugin.cpp @@ -206,7 +206,7 @@ float HmdDisplayPlugin::getLeftCenterPixel() const { } void HmdDisplayPlugin::internalPresent() { - PROFILE_RANGE_EX(displayPlugins, __FUNCTION__, 0xff00ff00, (uint64_t)presentCount()) + PROFILE_RANGE_EX(render, __FUNCTION__, 0xff00ff00, (uint64_t)presentCount()) // Composite together the scene, overlay and mouse cursor hmdPresent(); diff --git a/libraries/entities-renderer/src/RenderableModelEntityItem.cpp b/libraries/entities-renderer/src/RenderableModelEntityItem.cpp index 73b6141193..0008d0fbcc 100644 --- a/libraries/entities-renderer/src/RenderableModelEntityItem.cpp +++ b/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(renderlogging, "MetaModelRender"); + PROFILE_RANGE(render, "MetaModelRender"); payload->entity->render(args); } } diff --git a/libraries/fbx/src/FBXReader_Node.cpp b/libraries/fbx/src/FBXReader_Node.cpp index 034070c9d7..85850a748e 100644 --- a/libraries/fbx/src/FBXReader_Node.cpp +++ b/libraries/fbx/src/FBXReader_Node.cpp @@ -321,7 +321,7 @@ FBXNode parseTextFBXNode(Tokenizer& tokenizer) { } FBXNode FBXReader::parseFBX(QIODevice* device) { - PROFILE_RANGE_EX(modelformat, __FUNCTION__, 0xff0000ff, device); + PROFILE_RANGE_EX(resource_parse, __FUNCTION__, 0xff0000ff, device); // verify the prolog const QByteArray BINARY_PROLOG = "Kaydara FBX Binary "; if (device->peek(BINARY_PROLOG.size()) != BINARY_PROLOG) { diff --git a/libraries/fbx/src/OBJReader.cpp b/libraries/fbx/src/OBJReader.cpp index 8ea2c5fd38..73cf7a520e 100644 --- a/libraries/fbx/src/OBJReader.cpp +++ b/libraries/fbx/src/OBJReader.cpp @@ -420,7 +420,7 @@ done: FBXGeometry* OBJReader::readOBJ(QByteArray& model, const QVariantHash& mapping, const QUrl& url) { - PROFILE_RANGE_EX(modelformat, __FUNCTION__, 0xffff0000, nullptr); + PROFILE_RANGE_EX(resource_parse, __FUNCTION__, 0xffff0000, nullptr); QBuffer buffer { &model }; buffer.open(QIODevice::ReadOnly); diff --git a/libraries/gl/src/gl/OffscreenQmlSurface.cpp b/libraries/gl/src/gl/OffscreenQmlSurface.cpp index e1e7d46570..4ab19744d4 100644 --- a/libraries/gl/src/gl/OffscreenQmlSurface.cpp +++ b/libraries/gl/src/gl/OffscreenQmlSurface.cpp @@ -38,6 +38,9 @@ #include "GLLogging.h" #include "Context.h" +Q_LOGGING_CATEGORY(trace_render_qml, "trace.render.qml") +Q_LOGGING_CATEGORY(trace_render_qml_gl, "trace.render.qml.gl") + struct TextureSet { // The number of surfaces with this size size_t count { 0 }; @@ -276,6 +279,7 @@ void OffscreenQmlSurface::render() { return; } + PROFILE_RANGE(render_qml_gl, __FUNCTION__) _canvas->makeCurrent(); _renderControl->sync(); @@ -284,7 +288,6 @@ void OffscreenQmlSurface::render() { GLuint texture = offscreenTextures.getNextTexture(_size); glBindFramebuffer(GL_DRAW_FRAMEBUFFER, _fbo); glFramebufferTexture(GL_DRAW_FRAMEBUFFER, GL_COLOR_ATTACHMENT0, texture, 0); - PROFILE_RANGE(glLogging, "qml_render->rendercontrol") _renderControl->render(); glBindFramebuffer(GL_DRAW_FRAMEBUFFER, 0); glBindTexture(GL_TEXTURE_2D, texture); @@ -617,12 +620,12 @@ void OffscreenQmlSurface::updateQuick() { } if (_polish) { + PROFILE_RANGE(render_qml, "OffscreenQML polish") _renderControl->polishItems(); _polish = false; } if (_render) { - PROFILE_RANGE(glLogging, __FUNCTION__); render(); _render = false; } diff --git a/libraries/gpu-gl/src/gpu/gl/GLBackend.cpp b/libraries/gpu-gl/src/gpu/gl/GLBackend.cpp index ea9d421cba..071bfef766 100644 --- a/libraries/gpu-gl/src/gpu/gl/GLBackend.cpp +++ b/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(gpugllogging, "syncGPUBuffer"); + PROFILE_RANGE(render_gpu_gl, "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(gpugllogging, "syncCPUTransform"); + PROFILE_RANGE(render_gpu_gl, "syncCPUTransform"); _transform._cameras.clear(); _transform._cameraOffsets.clear(); @@ -242,7 +242,7 @@ void GLBackend::renderPassTransfer(const Batch& batch) { } { // Sync the transform buffers - PROFILE_RANGE(gpugllogging, "syncGPUTransform"); + PROFILE_RANGE(render_gpu_gl, "syncGPUTransform"); transferTransformState(batch); } @@ -304,7 +304,7 @@ void GLBackend::render(const Batch& batch) { } { - PROFILE_RANGE(gpugllogging, "Transfer"); + PROFILE_RANGE(render_gpu_gl, "Transfer"); renderPassTransfer(batch); } @@ -314,7 +314,7 @@ void GLBackend::render(const Batch& batch) { } #endif { - PROFILE_RANGE(gpugllogging, _stereo._enable ? "Render Stereo" : "Render"); + PROFILE_RANGE(render_gpu_gl, _stereo._enable ? "Render Stereo" : "Render"); renderPassDraw(batch); } #ifdef GPU_STEREO_DRAWCALL_INSTANCED diff --git a/libraries/gpu-gl/src/gpu/gl/GLBackendQuery.cpp b/libraries/gpu-gl/src/gpu/gl/GLBackendQuery.cpp index f0e87184c1..b4afd86abb 100644 --- a/libraries/gpu-gl/src/gpu/gl/GLBackendQuery.cpp +++ b/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(gpugllogging, glquery->_profileRangeId, query->getName().c_str(), 0xFFFF7F00); + PROFILE_RANGE_BEGIN(render_gpu_gl, 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(gpugllogging, glquery->_profileRangeId); + PROFILE_RANGE_END(render_gpu_gl, glquery->_profileRangeId); (void)CHECK_GL_ERROR(); } diff --git a/libraries/gpu-gl/src/gpu/gl/GLShared.cpp b/libraries/gpu-gl/src/gpu/gl/GLShared.cpp index 76457206e2..59ffc52e85 100644 --- a/libraries/gpu-gl/src/gpu/gl/GLShared.cpp +++ b/libraries/gpu-gl/src/gpu/gl/GLShared.cpp @@ -16,6 +16,7 @@ #include Q_LOGGING_CATEGORY(gpugllogging, "hifi.gpu.gl") +Q_LOGGING_CATEGORY(trace_render_gpu_gl, "trace.render.gpu.gl") namespace gpu { namespace gl { diff --git a/libraries/gpu-gl/src/gpu/gl/GLShared.h b/libraries/gpu-gl/src/gpu/gl/GLShared.h index 1b2724fe38..7c4d8106f9 100644 --- a/libraries/gpu-gl/src/gpu/gl/GLShared.h +++ b/libraries/gpu-gl/src/gpu/gl/GLShared.h @@ -15,6 +15,7 @@ #include Q_DECLARE_LOGGING_CATEGORY(gpugllogging) +Q_DECLARE_LOGGING_CATEGORY(trace_render_gpu_gl) namespace gpu { namespace gl { diff --git a/libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp b/libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp index d7f1cc7fab..65c45111db 100644 --- a/libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp +++ b/libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp @@ -122,7 +122,7 @@ void GL41Texture::transferMip(uint16_t mipLevel, uint8_t face) const { } void GL41Texture::startTransfer() { - PROFILE_RANGE(gpugllogging, __FUNCTION__); + PROFILE_RANGE(render_gpu_gl, __FUNCTION__); Parent::startTransfer(); glBindTexture(_target, _id); diff --git a/libraries/gpu/src/gpu/Texture.cpp b/libraries/gpu/src/gpu/Texture.cpp index 6098d816fb..19147ca98d 100755 --- a/libraries/gpu/src/gpu/Texture.cpp +++ b/libraries/gpu/src/gpu/Texture.cpp @@ -759,7 +759,7 @@ bool sphericalHarmonicsFromTexture(const gpu::Texture& cubeTexture, std::vector< return false; } - PROFILE_RANGE(gpulogging, "sphericalHarmonicsFromTexture"); + PROFILE_RANGE(render_gpu, "sphericalHarmonicsFromTexture"); const uint sqOrder = order*order; @@ -792,7 +792,7 @@ bool sphericalHarmonicsFromTexture(const gpu::Texture& cubeTexture, std::vector< // for each face of cube texture for(int face=0; face < gpu::Texture::NUM_CUBE_FACES; face++) { - PROFILE_RANGE(gpulogging, "ProcessFace"); + PROFILE_RANGE(render_gpu, "ProcessFace"); auto numComponents = cubeTexture.accessStoredMipFace(0,face)->getFormat().getScalarCount(); auto data = cubeTexture.accessStoredMipFace(0,face)->readData(); diff --git a/libraries/model-networking/src/model-networking/ModelCache.cpp b/libraries/model-networking/src/model-networking/ModelCache.cpp index 427f307dc3..2a02540821 100644 --- a/libraries/model-networking/src/model-networking/ModelCache.cpp +++ b/libraries/model-networking/src/model-networking/ModelCache.cpp @@ -24,6 +24,8 @@ #include #include +Q_LOGGING_CATEGORY(trace_resource_parse_geometry, "trace.resource.parse.geometry") + class GeometryReader; class GeometryExtra { @@ -54,7 +56,7 @@ private: }; void GeometryMappingResource::downloadFinished(const QByteArray& data) { - PROFILE_ASYNC_BEGIN(modelnetworking, "GeometryMappingResource::downloadFinished", _url.toString(), + PROFILE_ASYNC_BEGIN(resource_parse_geometry, "GeometryMappingResource::downloadFinished", _url.toString(), { { "url", _url.toString() } }); auto mapping = FSTReader::readMapping(data); @@ -120,7 +122,7 @@ void GeometryMappingResource::onGeometryMappingLoaded(bool success) { disconnect(_connection); // FIXME Should not have to do this } - PROFILE_ASYNC_END(modelnetworking, "GeometryMappingResource::downloadFinished", _url.toString()); + PROFILE_ASYNC_END(resource_parse_geometry, "GeometryMappingResource::downloadFinished", _url.toString()); finishedLoading(success); } @@ -145,7 +147,7 @@ private: void GeometryReader::run() { DependencyManager::get()->decrementStat("PendingProcessing"); CounterStat counter("Processing"); - PROFILE_RANGE_EX(modelnetworking, "GeometryReader::run", 0xFF00FF00, 0, { { "url", _url.toString() } }); + PROFILE_RANGE_EX(resource_parse_geometry, "GeometryReader::run", 0xFF00FF00, 0, { { "url", _url.toString() } }); auto originalPriority = QThread::currentThread()->priority(); if (originalPriority == QThread::InheritPriority) { originalPriority = QThread::NormalPriority; diff --git a/libraries/model-networking/src/model-networking/TextureCache.cpp b/libraries/model-networking/src/model-networking/TextureCache.cpp index 20c1be77c5..6a4edd60ed 100644 --- a/libraries/model-networking/src/model-networking/TextureCache.cpp +++ b/libraries/model-networking/src/model-networking/TextureCache.cpp @@ -36,6 +36,8 @@ #include #include +Q_LOGGING_CATEGORY(trace_resource_parse_image, "trace.resource.parse.image") + TextureCache::TextureCache() { setUnusedResourceCacheSize(0); setObjectName("TextureCache"); @@ -349,7 +351,7 @@ void ImageReader::run() { CounterStat counter("Processing"); - PROFILE_RANGE_EX(modelnetworking, __FUNCTION__, 0xffff0000, 0, { { "url", _url.toString() } }); + PROFILE_RANGE_EX(resource_parse_image, __FUNCTION__, 0xffff0000, 0, { { "url", _url.toString() } }); auto originalPriority = QThread::currentThread()->priority(); if (originalPriority == QThread::InheritPriority) { originalPriority = QThread::NormalPriority; @@ -395,7 +397,7 @@ void ImageReader::run() { auto url = _url.toString().toStdString(); - PROFILE_RANGE_EX(modelnetworking, __FUNCTION__, 0xffffff00, 0); + PROFILE_RANGE_EX(resource_parse_image, __FUNCTION__, 0xffffff00, 0); texture.reset(resource.dynamicCast()->getTextureLoader()(image, url)); } diff --git a/libraries/model/src/model/TextureMap.cpp b/libraries/model/src/model/TextureMap.cpp index 83914ae950..3957d6c708 100755 --- a/libraries/model/src/model/TextureMap.cpp +++ b/libraries/model/src/model/TextureMap.cpp @@ -746,7 +746,7 @@ const CubeLayout CubeLayout::CUBEMAP_LAYOUTS[] = { const int CubeLayout::NUM_CUBEMAP_LAYOUTS = sizeof(CubeLayout::CUBEMAP_LAYOUTS) / sizeof(CubeLayout); gpu::Texture* TextureUsage::processCubeTextureColorFromImage(const QImage& srcImage, const std::string& srcImageName, bool isLinear, bool doCompress, bool generateMips, bool generateIrradiance) { - PROFILE_RANGE(modelLog, "processCubeTextureColorFromImage"); + PROFILE_RANGE(resource_parse, "processCubeTextureColorFromImage"); gpu::Texture* theTexture = nullptr; if ((srcImage.width() > 0) && (srcImage.height() > 0)) { @@ -805,13 +805,13 @@ gpu::Texture* TextureUsage::processCubeTextureColorFromImage(const QImage& srcIm } if (generateMips) { - PROFILE_RANGE(modelLog, "generateMips"); + PROFILE_RANGE(resource_parse, "generateMips"); theTexture->autoGenerateMips(-1); } // Generate irradiance while we are at it if (generateIrradiance) { - PROFILE_RANGE(modelLog, "generateIrradiance"); + PROFILE_RANGE(resource_parse, "generateIrradiance"); theTexture->generateIrradiance(); } } diff --git a/libraries/networking/src/ResourceCache.cpp b/libraries/networking/src/ResourceCache.cpp index db4bc35cd4..677be8ecf5 100644 --- a/libraries/networking/src/ResourceCache.cpp +++ b/libraries/networking/src/ResourceCache.cpp @@ -650,12 +650,12 @@ void Resource::reinsert() { void Resource::makeRequest() { if (_request) { - PROFILE_ASYNC_END(resourceLog, "Resource:" + getType(), QString::number(_requestID)); + PROFILE_ASYNC_END(resource, "Resource:" + getType(), QString::number(_requestID)); _request->disconnect(); _request->deleteLater(); } - PROFILE_ASYNC_BEGIN(resourceLog, "Resource:" + getType(), QString::number(_requestID), { { "url", _url.toString() }, { "activeURL", _activeUrl.toString() } }); + PROFILE_ASYNC_BEGIN(resource, "Resource:" + getType(), QString::number(_requestID), { { "url", _url.toString() }, { "activeURL", _activeUrl.toString() } }); _request = ResourceManager::createResourceRequest(this, _activeUrl); @@ -663,7 +663,7 @@ void Resource::makeRequest() { qCDebug(networking).noquote() << "Failed to get request for" << _url.toDisplayString(); ResourceCache::requestCompleted(_self); finishedLoading(false); - PROFILE_ASYNC_END(resourceLog, "Resource:" + getType(), QString::number(_requestID)); + PROFILE_ASYNC_END(resource, "Resource:" + getType(), QString::number(_requestID)); return; } @@ -688,7 +688,7 @@ void Resource::handleDownloadProgress(uint64_t bytesReceived, uint64_t bytesTota void Resource::handleReplyFinished() { Q_ASSERT_X(_request, "Resource::handleReplyFinished", "Request should not be null while in handleReplyFinished"); - PROFILE_ASYNC_END(resourceLog, "Resource:" + getType(), QString::number(_requestID), { + PROFILE_ASYNC_END(resource, "Resource:" + getType(), QString::number(_requestID), { { "from_cache", _request->loadedFromCache() }, { "size_mb", _bytesTotal / 1000000.0 } }); diff --git a/libraries/networking/src/udt/SendQueue.cpp b/libraries/networking/src/udt/SendQueue.cpp index 8e32befe14..c330f5516e 100644 --- a/libraries/networking/src/udt/SendQueue.cpp +++ b/libraries/networking/src/udt/SendQueue.cpp @@ -86,7 +86,7 @@ SendQueue::SendQueue(Socket* socket, HifiSockAddr dest) : _socket(socket), _destination(dest) { - PROFILE_ASYNC_BEGIN(networking, "SendQueue", _destination.toString()); + PROFILE_ASYNC_BEGIN(network, "SendQueue", _destination.toString()); // setup psuedo-random number generation for all instances of SendQueue static std::random_device rd; @@ -106,7 +106,7 @@ SendQueue::SendQueue(Socket* socket, HifiSockAddr dest) : } SendQueue::~SendQueue() { - PROFILE_ASYNC_END(networking, "SendQueue", _destination.toString()); + PROFILE_ASYNC_END(network, "SendQueue", _destination.toString()); } void SendQueue::queuePacket(std::unique_ptr packet) { @@ -227,7 +227,7 @@ void SendQueue::sendHandshake() { if (!_hasReceivedHandshakeACK) { // we haven't received a handshake ACK from the client, send another now auto handshakePacket = ControlPacket::create(ControlPacket::Handshake, sizeof(SequenceNumber)); - PROFILE_ASYNC_BEGIN(networking, "SendQueue:Handshake", _destination.toString()); + PROFILE_ASYNC_BEGIN(network, "SendQueue:Handshake", _destination.toString()); handshakePacket->writePrimitive(_initialSequenceNumber); _socket->writeBasePacket(*handshakePacket, _destination); @@ -244,7 +244,7 @@ void SendQueue::handshakeACK(SequenceNumber initialSequenceNumber) { std::lock_guard locker { _handshakeMutex }; _hasReceivedHandshakeACK = true; } - PROFILE_ASYNC_END(networking, "SendQueue:Handshake", _destination.toString()); + PROFILE_ASYNC_END(network, "SendQueue:Handshake", _destination.toString()); // Notify on the handshake ACK condition _handshakeACKCondition.notify_one(); diff --git a/libraries/octree/src/OctreeElement.cpp b/libraries/octree/src/OctreeElement.cpp index 4eb59d0494..abcfd8fbaa 100644 --- a/libraries/octree/src/OctreeElement.cpp +++ b/libraries/octree/src/OctreeElement.cpp @@ -392,7 +392,6 @@ OctreeElementPointer OctreeElement::addChildAtIndex(int childIndex) { _isDirty = true; markWithChangedTime(); - PROFILE_INSTANT(octree, "EntityAdd", "g"); } return childAt; } diff --git a/libraries/render-utils/src/DeferredLightingEffect.cpp b/libraries/render-utils/src/DeferredLightingEffect.cpp index 908fccaaf6..6f1152ac16 100644 --- a/libraries/render-utils/src/DeferredLightingEffect.cpp +++ b/libraries/render-utils/src/DeferredLightingEffect.cpp @@ -793,7 +793,7 @@ void RenderDeferred::configure(const Config& config) { } void RenderDeferred::run(const SceneContextPointer& sceneContext, const RenderContextPointer& renderContext, const Inputs& inputs) { - PROFILE_RANGE(renderlogging, "DeferredLighting"); + PROFILE_RANGE(render, "DeferredLighting"); auto deferredTransform = inputs.get0(); auto deferredFramebuffer = inputs.get1(); diff --git a/libraries/render-utils/src/Model.cpp b/libraries/render-utils/src/Model.cpp index 9dc0ad8a08..bb0ffa63b6 100644 --- a/libraries/render-utils/src/Model.cpp +++ b/libraries/render-utils/src/Model.cpp @@ -281,7 +281,7 @@ void Model::reset() { } bool Model::updateGeometry() { - PROFILE_RANGE(renderutils, __FUNCTION__); + PROFILE_RANGE(render, __FUNCTION__); PerformanceTimer perfTimer("Model::updateGeometry"); bool needFullUpdate = false; @@ -476,7 +476,7 @@ bool Model::convexHullContains(glm::vec3 point) { // entity-scripts to call. I think it would be best to do the picking once-per-frame (in cpu, or gpu if possible) // and then the calls use the most recent such result. void Model::recalculateMeshBoxes(bool pickAgainstTriangles) { - PROFILE_RANGE(renderutils, __FUNCTION__); + PROFILE_RANGE(render, __FUNCTION__); bool calculatedMeshTrianglesNeeded = pickAgainstTriangles && !_calculatedMeshTrianglesValid; if (!_calculatedMeshBoxesValid || calculatedMeshTrianglesNeeded || (!_calculatedMeshPartBoxesValid && pickAgainstTriangles) ) { @@ -969,7 +969,7 @@ Blender::Blender(ModelPointer model, int blendNumber, const Geometry::WeakPointe } void Blender::run() { - PROFILE_RANGE_EX(renderutils, __FUNCTION__, 0xFFFF0000, 0, { { "url", _model->getURL().toString() } }); + PROFILE_RANGE_EX(simulation_animation, __FUNCTION__, 0xFFFF0000, 0, { { "url", _model->getURL().toString() } }); QVector vertices, normals; if (_model) { int offset = 0; @@ -1090,7 +1090,7 @@ void Model::snapToRegistrationPoint() { } void Model::simulate(float deltaTime, bool fullUpdate) { - PROFILE_RANGE(renderutils, __FUNCTION__); + PROFILE_RANGE(simulation, __FUNCTION__); PerformanceTimer perfTimer("Model::simulate"); fullUpdate = updateGeometry() || fullUpdate || (_scaleToFit && !_scaledToFit) || (_snapModelToRegistrationPoint && !_snappedToRegistrationPoint); diff --git a/libraries/render/src/render/Scene.cpp b/libraries/render/src/render/Scene.cpp index 3cb9de7b77..9ff7120508 100644 --- a/libraries/render/src/render/Scene.cpp +++ b/libraries/render/src/render/Scene.cpp @@ -78,13 +78,16 @@ void consolidateChangeQueue(PendingChangesQueue& queue, PendingChanges& singleBa } void Scene::processPendingChangesQueue() { - PROFILE_RANGE(renderlogging, __FUNCTION__); - _changeQueueMutex.lock(); + PROFILE_RANGE(render, __FUNCTION__); PendingChanges consolidatedPendingChanges; - consolidateChangeQueue(_changeQueue, consolidatedPendingChanges); - _changeQueueMutex.unlock(); + + { + std::unique_lock lock(_changeQueueMutex); + consolidateChangeQueue(_changeQueue, consolidatedPendingChanges); + } - _itemsMutex.lock(); + { + std::unique_lock lock(_itemsMutex); // Here we should be able to check the value of last ItemID allocated // and allocate new items accordingly ItemID maxID = _IDAllocator.load(); @@ -108,9 +111,7 @@ void Scene::processPendingChangesQueue() { // Update the numItemsAtomic counter AFTER the pending changes went through _numAllocatedItems.exchange(maxID); - - // ready to go back to rendering activities - _itemsMutex.unlock(); + } } void Scene::resetItems(const ItemIDs& ids, Payloads& payloads) { diff --git a/libraries/render/src/render/Task.h b/libraries/render/src/render/Task.h index 067dc290d4..68643110b8 100644 --- a/libraries/render/src/render/Task.h +++ b/libraries/render/src/render/Task.h @@ -572,7 +572,7 @@ public: void run(const SceneContextPointer& sceneContext, const RenderContextPointer& renderContext) { PerformanceTimer perfTimer(_name.c_str()); - PROFILE_RANGE(renderlogging, _name.c_str()); + PROFILE_RANGE(render, _name.c_str()); auto start = usecTimestampNow(); _concept->run(sceneContext, renderContext); diff --git a/libraries/shared/src/Profile.cpp b/libraries/shared/src/Profile.cpp index 18e273a6bb..007063f241 100644 --- a/libraries/shared/src/Profile.cpp +++ b/libraries/shared/src/Profile.cpp @@ -8,6 +8,21 @@ #include "Profile.h" +Q_LOGGING_CATEGORY(trace_app, "trace.app") +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_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_animation, "trace.simulation.animation") +Q_LOGGING_CATEGORY(trace_simulation_physics, "trace.simulation.physics") + +void foo() { + randFloat(); +} #if defined(NSIGHT_FOUND) #include "nvToolsExt.h" diff --git a/libraries/shared/src/Profile.h b/libraries/shared/src/Profile.h index a89b19e7c6..6d02a0939f 100644 --- a/libraries/shared/src/Profile.h +++ b/libraries/shared/src/Profile.h @@ -11,6 +11,18 @@ #define HIFI_PROFILE_ #include "Trace.h" +#include "SharedUtil.h" + +Q_DECLARE_LOGGING_CATEGORY(trace_app) +Q_DECLARE_LOGGING_CATEGORY(trace_network) +Q_DECLARE_LOGGING_CATEGORY(trace_render) +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_animation) +Q_DECLARE_LOGGING_CATEGORY(trace_simulation_physics) class Duration { public: @@ -51,13 +63,18 @@ inline void counter(const QLoggingCategory& category, const QString& name, const } } -#define PROFILE_RANGE(category, name) Duration profileRangeThis(category(), name); -#define PROFILE_RANGE_EX(category, name, argbColor, payload, ...) Duration profileRangeThis(category(), name, argbColor, (uint64_t)payload, ##__VA_ARGS__); -#define PROFILE_RANGE_BEGIN(category, rangeId, name, argbColor) rangeId = Duration::beginRange(category(), name, argbColor) -#define PROFILE_RANGE_END(category, rangeId) Duration::endRange(category(), rangeId) -#define PROFILE_ASYNC_BEGIN(category, name, id, ...) asyncBegin(category(), name, id, ##__VA_ARGS__); -#define PROFILE_ASYNC_END(category, name, id, ...) asyncEnd(category(), name, id, ##__VA_ARGS__); -#define PROFILE_COUNTER(category, name, ...) counter(category(), name, ##__VA_ARGS__); -#define PROFILE_INSTANT(category, name, ...) instant(category(), name, ##__VA_ARGS__); +#define PROFILE_RANGE(category, name) Duration profileRangeThis(trace_##category(), name); +#define PROFILE_RANGE_EX(category, name, argbColor, payload, ...) Duration profileRangeThis(trace_##category(), name, argbColor, (uint64_t)payload, ##__VA_ARGS__); +#define PROFILE_RANGE_BEGIN(category, rangeId, name, argbColor) rangeId = Duration::beginRange(trace_##category(), name, argbColor) +#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(category, name, ...) counter(trace_##category(), name, ##__VA_ARGS__); +#define PROFILE_INSTANT(category, name, ...) instant(trace_##category(), name, ##__VA_ARGS__); + +#define SAMPLE_PROFILE_RANGE(chance, category, name, ...) if (randFloat() <= chance) { PROFILE_RANGE(category, name); } +#define SAMPLE_PROFILE_RANGE_EX(chance, category, name, ...) if (randFloat() <= chance) { PROFILE_RANGE_EX(category, name, argbColor, payload, ##__VA_ARGS__); } +#define SAMPLE_PROFILE_COUNTER(chance, category, name, ...) if (randFloat() <= chance) { PROFILE_COUNTER(category, name, ##__VA_ARGS__); } +#define SAMPLE_PROFILE_INSTANT(chance, category, name, ...) if (randFloat() <= chance) { PROFILE_INSTANT(category, name, ##__VA_ARGS__); } #endif diff --git a/libraries/shared/src/Trace.cpp b/libraries/shared/src/Trace.cpp index 0e2b2f213c..8422f7f8a9 100644 --- a/libraries/shared/src/Trace.cpp +++ b/libraries/shared/src/Trace.cpp @@ -13,6 +13,9 @@ #include #include #include +#include +#include +#include #include #include @@ -100,7 +103,24 @@ void TraceEvent::writeJson(QTextStream& out) const { #endif } -void Tracer::serialize(const QString& path) { +void Tracer::serialize(const QString& originalPath) { + + QString path = originalPath; + + // If the filename is relative, turn it into an absolute path relative to the document directory. + QFileInfo originalFileInfo(path); + if (originalFileInfo.isRelative()) { + QString docsLocation = QStandardPaths::writableLocation(QStandardPaths::DocumentsLocation); + path = docsLocation + "/" + path; + QFileInfo info(path); + if (!info.absoluteDir().exists()) { + QString originalRelativePath = originalFileInfo.path(); + QDir(docsLocation).mkpath(originalRelativePath); + } + } + + + std::list currentEvents; { std::lock_guard guard(_eventsMutex); diff --git a/libraries/shared/src/Trace.h b/libraries/shared/src/Trace.h index e075dc24c4..f719969758 100644 --- a/libraries/shared/src/Trace.h +++ b/libraries/shared/src/Trace.h @@ -21,8 +21,6 @@ #include "DependencyManager.h" -#define TRACE_ENABLED - namespace tracing { bool enabled(); diff --git a/plugins/oculus/src/OculusDisplayPlugin.cpp b/plugins/oculus/src/OculusDisplayPlugin.cpp index 5ab9d2f058..2e9f74a0e5 100644 --- a/plugins/oculus/src/OculusDisplayPlugin.cpp +++ b/plugins/oculus/src/OculusDisplayPlugin.cpp @@ -110,7 +110,7 @@ void OculusDisplayPlugin::hmdPresent() { return; } - PROFILE_RANGE_EX(displayplugins, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) + PROFILE_RANGE_EX(render, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) int curIndex; ovr_GetTextureSwapChainCurrentIndex(_session, _textureSwapChain, &curIndex); diff --git a/plugins/openvr/src/OpenVrDisplayPlugin.cpp b/plugins/openvr/src/OpenVrDisplayPlugin.cpp index 5a963db254..42f3ece9cd 100644 --- a/plugins/openvr/src/OpenVrDisplayPlugin.cpp +++ b/plugins/openvr/src/OpenVrDisplayPlugin.cpp @@ -529,7 +529,7 @@ static bool isBadPose(vr::HmdMatrix34_t* mat) { } bool OpenVrDisplayPlugin::beginFrameRender(uint32_t frameIndex) { - PROFILE_RANGE_EX(displayplugins, __FUNCTION__, 0xff7fff00, frameIndex) + PROFILE_RANGE_EX(render, __FUNCTION__, 0xff7fff00, frameIndex) handleOpenVrEvents(); if (openVrQuitRequested()) { QMetaObject::invokeMethod(qApp, "quit"); @@ -633,7 +633,7 @@ void OpenVrDisplayPlugin::compositeLayers() { } void OpenVrDisplayPlugin::hmdPresent() { - PROFILE_RANGE_EX(displayplugins, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) + PROFILE_RANGE_EX(render, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) if (_threadedSubmit) { _submitThread->waitForPresent(); @@ -654,7 +654,7 @@ void OpenVrDisplayPlugin::hmdPresent() { } void OpenVrDisplayPlugin::postPreview() { - PROFILE_RANGE_EX(displayplugins, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) + PROFILE_RANGE_EX(render, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) PoseData nextRender, nextSim; nextRender.frameIndex = presentCount(); diff --git a/tests/render-perf/src/main.cpp b/tests/render-perf/src/main.cpp index 0185b1b3cd..bd731564e7 100644 --- a/tests/render-perf/src/main.cpp +++ b/tests/render-perf/src/main.cpp @@ -900,7 +900,7 @@ private: gpu::doInBatch(gpuContext, [&](gpu::Batch& batch) { batch.resetStages(); }); - PROFILE_RANGE(renderperflogging, __FUNCTION__); + PROFILE_RANGE(render, __FUNCTION__); PerformanceTimer perfTimer("draw"); // The pending changes collecting the changes here render::PendingChanges pendingChanges; diff --git a/tests/shared/src/TraceTests.cpp b/tests/shared/src/TraceTests.cpp index 175cf2cc01..5536d17ca6 100644 --- a/tests/shared/src/TraceTests.cpp +++ b/tests/shared/src/TraceTests.cpp @@ -9,33 +9,35 @@ #include "TraceTests.h" #include -#include +#include + +#include -#include #include #include <../QTestExtensions.h> QTEST_MAIN(TraceTests) -Q_LOGGING_CATEGORY(tracertestlogging, "hifi.tracer.test") +Q_LOGGING_CATEGORY(trace_test, "trace.test") + +const QString OUTPUT_FILE = "traces/testTrace.json.gz"; void TraceTests::testTraceSerialization() { auto tracer = DependencyManager::set(); tracer->startTracing(); - tracer->traceEvent(tracertestlogging(), "TestEvent", tracing::DurationBegin); { auto start = usecTimestampNow(); + PROFILE_RANGE(test, "TestEvent") for (size_t i = 0; i < 10000; ++i) { - tracer->traceEvent(tracertestlogging(), "TestCounter", tracing::Counter, "", { { "i", i } }); + SAMPLE_PROFILE_COUNTER(0.1f, test, "TestCounter", { { "i", i } }) } auto duration = usecTimestampNow() - start; duration /= USECS_PER_MSEC; qDebug() << "Recording took " << duration << "ms"; } - tracer->traceEvent(tracertestlogging(), "TestEvent", tracing::DurationEnd); tracer->stopTracing(); { auto start = usecTimestampNow(); - tracer->serialize("testTrace.json.gz"); + tracer->serialize(OUTPUT_FILE); auto duration = usecTimestampNow() - start; duration /= USECS_PER_MSEC; qDebug() << "Serialization took " << duration << "ms";