From 7bb27559139c02508aa2c69798e21c8109953082 Mon Sep 17 00:00:00 2001 From: Ryan Huffman Date: Tue, 22 Nov 2016 16:45:53 -0800 Subject: [PATCH] Add chrome tracing support --- assignment-client/src/AssignmentClient.cpp | 2 + domain-server/src/DomainServer.cpp | 3 + interface/src/Application.cpp | 74 +++++-- .../src/scripting/TestScriptingInterface.cpp | 28 +++ .../src/scripting/TestScriptingInterface.h | 11 + interface/src/ui/ApplicationOverlay.cpp | 13 +- interface/src/ui/overlays/Overlays.cpp | 3 +- .../animation/src/AnimInverseKinematics.cpp | 10 +- libraries/animation/src/AnimationCache.cpp | 8 + libraries/animation/src/AnimationCache.h | 2 + libraries/animation/src/Rig.cpp | 2 +- .../display-plugins/OpenGLDisplayPlugin.cpp | 24 +- .../display-plugins/hmd/HmdDisplayPlugin.cpp | 2 +- .../src/RenderableModelEntityItem.cpp | 2 +- libraries/entities/src/EntityTree.cpp | 1 + libraries/fbx/src/FBXReader_Node.cpp | 2 +- libraries/fbx/src/OBJReader.cpp | 2 +- libraries/gl/src/gl/GLLogging.cpp | 2 +- libraries/gl/src/gl/OffscreenQmlSurface.cpp | 4 +- libraries/gpu-gl/src/gpu/gl/GLBackend.cpp | 11 +- .../gpu-gl/src/gpu/gl/GLBackendQuery.cpp | 5 +- .../src/gpu/gl41/GL41BackendTexture.cpp | 3 +- libraries/gpu/src/gpu/Texture.cpp | 7 +- .../src/model-networking/ModelCache.cpp | 26 ++- .../src/model-networking/ShaderCache.h | 3 + .../src/model-networking/TextureCache.cpp | 14 +- .../src/model-networking/TextureCache.h | 3 + libraries/model/src/model/TextureMap.cpp | 6 + libraries/networking/src/AssetClient.cpp | 2 +- libraries/networking/src/AssetRequest.cpp | 20 ++ libraries/networking/src/AssetRequest.h | 1 + .../networking/src/AssetResourceRequest.cpp | 33 ++- libraries/networking/src/Assignment.cpp | 6 +- libraries/networking/src/Assignment.h | 4 +- libraries/networking/src/HifiSockAddr.cpp | 4 + libraries/networking/src/HifiSockAddr.h | 2 + libraries/networking/src/LimitedNodeList.cpp | 4 +- libraries/networking/src/LimitedNodeList.h | 3 +- libraries/networking/src/NetworkLogging.cpp | 1 + libraries/networking/src/NetworkLogging.h | 1 + libraries/networking/src/NetworkPeer.cpp | 3 + libraries/networking/src/NodeList.cpp | 1 + libraries/networking/src/ResourceCache.cpp | 18 +- libraries/networking/src/ResourceCache.h | 3 + libraries/networking/src/udt/Connection.cpp | 6 + libraries/networking/src/udt/Connection.h | 2 +- libraries/networking/src/udt/SendQueue.cpp | 9 + libraries/networking/src/udt/SendQueue.h | 2 + libraries/networking/src/udt/Socket.cpp | 1 + libraries/octree/src/OctreeElement.cpp | 4 + .../src/DeferredLightingEffect.cpp | 2 +- libraries/render-utils/src/Model.cpp | 9 +- libraries/render/src/render/Logging.cpp | 11 + libraries/render/src/render/Logging.h | 16 ++ libraries/render/src/render/Scene.cpp | 5 +- libraries/render/src/render/Task.h | 3 +- libraries/shared/CMakeLists.txt | 2 + libraries/shared/src/Profile.cpp | 72 ++++++ libraries/shared/src/Profile.h | 63 ++++++ libraries/shared/src/StatTracker.cpp | 34 +++ libraries/shared/src/StatTracker.h | 45 ++++ libraries/shared/src/Trace.cpp | 205 ++++++++++++++++++ libraries/shared/src/Trace.h | 115 ++++++++++ .../shared/src/shared/GlobalAppProperties.cpp | 1 + .../shared/src/shared/GlobalAppProperties.h | 1 + libraries/shared/src/shared/NsightHelpers.cpp | 43 ---- libraries/shared/src/shared/NsightHelpers.h | 31 +-- plugins/oculus/src/OculusDisplayPlugin.cpp | 2 +- plugins/oculus/src/OculusHelpers.cpp | 5 +- plugins/oculus/src/OculusHelpers.h | 6 + plugins/openvr/src/OpenVrDisplayPlugin.cpp | 6 +- scripts/developer/tests/testTestMode.js | 12 +- tests/render-perf/src/main.cpp | 5 +- tests/render-texture-load/src/main.cpp | 1 - tests/shared/src/TraceTests.cpp | 45 ++++ tests/shared/src/TraceTests.h | 20 ++ 76 files changed, 987 insertions(+), 176 deletions(-) create mode 100644 libraries/render/src/render/Logging.cpp create mode 100644 libraries/render/src/render/Logging.h create mode 100644 libraries/shared/src/Profile.cpp create mode 100644 libraries/shared/src/Profile.h create mode 100644 libraries/shared/src/StatTracker.cpp create mode 100644 libraries/shared/src/StatTracker.h create mode 100644 libraries/shared/src/Trace.cpp create mode 100644 libraries/shared/src/Trace.h create mode 100644 tests/shared/src/TraceTests.cpp create mode 100644 tests/shared/src/TraceTests.h diff --git a/assignment-client/src/AssignmentClient.cpp b/assignment-client/src/AssignmentClient.cpp index c5024055c0..56416809d1 100644 --- a/assignment-client/src/AssignmentClient.cpp +++ b/assignment-client/src/AssignmentClient.cpp @@ -37,6 +37,7 @@ #include "AssignmentClient.h" #include "AssignmentClientLogging.h" #include "avatars/ScriptableAvatar.h" +#include const QString ASSIGNMENT_CLIENT_TARGET_NAME = "assignment-client"; const long long ASSIGNMENT_REQUEST_INTERVAL_MSECS = 1 * 1000; @@ -48,6 +49,7 @@ AssignmentClient::AssignmentClient(Assignment::Type requestAssignmentType, QStri { LogUtils::init(); + DependencyManager::set(); DependencyManager::set(); auto scriptableAvatar = DependencyManager::set(); diff --git a/domain-server/src/DomainServer.cpp b/domain-server/src/DomainServer.cpp index 711a5b6fc2..e531812077 100644 --- a/domain-server/src/DomainServer.cpp +++ b/domain-server/src/DomainServer.cpp @@ -43,6 +43,7 @@ #include "DomainServerNodeData.h" #include "NodeConnectionData.h" +#include int const DomainServer::EXIT_CODE_REBOOT = 234923; @@ -73,6 +74,8 @@ DomainServer::DomainServer(int argc, char* argv[]) : { parseCommandLine(); + DependencyManager::set(); + LogUtils::init(); Setting::init(); diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index acd87d9cbf..90f187784f 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -46,6 +46,8 @@ #include #include +#include +#include #include #include #include @@ -423,6 +425,8 @@ bool setupEssentials(int& argc, char** argv) { steamClient->init(); } + DependencyManager::set(); + #if defined(Q_OS_WIN) // Select appropriate audio DLL QString audioDLLPath = QCoreApplication::applicationDirPath(); @@ -445,6 +449,7 @@ bool setupEssentials(int& argc, char** argv) { // Set dependencies DependencyManager::set(std::bind(&Application::getUserAgent, qApp)); + DependencyManager::set(); DependencyManager::set(); DependencyManager::set(); DependencyManager::set(); @@ -557,6 +562,7 @@ 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) { if (args.at(i) == TEST_SCRIPT) { @@ -564,6 +570,10 @@ Application::Application(int& argc, char** argv, QElapsedTimer& startupTimer, bo if (QFileInfo(testScriptPath).exists()) { setProperty(hifi::properties::TEST, QUrl::fromLocalFile(testScriptPath)); } + } else if (args.at(i) == TRACE_FILE) { + QString traceFilePath = args.at(i + 1); + setProperty(hifi::properties::TRACING, traceFilePath); + DependencyManager::get()->startTracing(); } } } @@ -1572,6 +1582,13 @@ void Application::cleanupBeforeQuit() { QString webengineRemoteDebugging = QProcessEnvironment::systemEnvironment().value("QTWEBENGINE_REMOTE_DEBUGGING", "false"); qCDebug(interfaceapp) << "QTWEBENGINE_REMOTE_DEBUGGING =" << webengineRemoteDebugging; + if (tracing::enabled()) { + auto tracer = DependencyManager::get(); + tracer->stopTracing(); + auto outputFile = property(hifi::properties::TRACING).toString(); + tracer->serialize(outputFile); + } + // Stop third party processes so that they're not left running in the event of a subsequent shutdown crash. #ifdef HAVE_DDE DependencyManager::get()->setEnabled(false); @@ -1928,6 +1945,16 @@ 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; @@ -1939,7 +1966,7 @@ void Application::paintGL() { _frameCount++; auto lastPaintBegin = usecTimestampNow(); - PROFILE_RANGE_EX(__FUNCTION__, 0xff0000ff, (uint64_t)_frameCount); + PROFILE_RANGE_EX(interfaceapp, __FUNCTION__, 0xff0000ff, (uint64_t)_frameCount); PerformanceTimer perfTimer("paintGL"); if (nullptr == _displayPlugin) { @@ -2116,7 +2143,7 @@ void Application::paintGL() { auto finalFramebuffer = framebufferCache->getFramebuffer(); { - PROFILE_RANGE(__FUNCTION__ "/mainRender"); + PROFILE_RANGE(interfaceapp, "/mainRender"); PerformanceTimer perfTimer("mainRender"); renderArgs._boomOffset = boomOffset; // Viewport is assigned to the size of the framebuffer @@ -2171,7 +2198,7 @@ void Application::paintGL() { frame->overlay = _applicationOverlay.getOverlayTexture(); // deliver final scene rendering commands to the display plugin { - PROFILE_RANGE(__FUNCTION__ "/pluginOutput"); + PROFILE_RANGE(interfaceapp, "/pluginOutput"); PerformanceTimer perfTimer("pluginOutput"); _frameCounter.increment(); displayPlugin->submitFrame(frame); @@ -2259,7 +2286,7 @@ void Application::resizeEvent(QResizeEvent* event) { } void Application::resizeGL() { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); if (nullptr == _displayPlugin) { return; } @@ -2314,7 +2341,6 @@ bool Application::importSVOFromURL(const QString& urlString) { } bool Application::event(QEvent* event) { - if (!Menu::getInstance()) { return false; } @@ -2905,7 +2931,7 @@ void Application::maybeToggleMenuVisible(QMouseEvent* event) const { } void Application::mouseMoveEvent(QMouseEvent* event) { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); if (_aboutToQuit) { return; @@ -3213,7 +3239,7 @@ void Application::idle(float nsecsElapsed) { connect(offscreenUi.data(), &OffscreenUi::showDesktop, this, &Application::showDesktop); } - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); if (auto steamClient = PluginManager::getInstance()->getSteamClientPlugin()) { steamClient->runCallbacks(); @@ -3930,9 +3956,11 @@ void Application::updateDialogs(float deltaTime) const { } } +static bool domainLoadingInProgress = false; + void Application::update(float deltaTime) { - PROFILE_RANGE_EX(__FUNCTION__, 0xffff0000, (uint64_t)_frameCount + 1); + PROFILE_RANGE_EX(interfaceapp, __FUNCTION__, 0xffff0000, (uint64_t)_frameCount + 1); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::update()"); @@ -3940,6 +3968,11 @@ void Application::update(float deltaTime) { updateLOD(); if (!_physicsEnabled) { + if (!domainLoadingInProgress) { + PROFILE_ASYNC_BEGIN(interfaceapp, "Scene Loading", ""); + domainLoadingInProgress = true; + } + // we haven't yet enabled physics. we wait until we think we have all the collision information // for nearby entities before starting bullet up. quint64 now = usecTimestampNow(); @@ -3969,6 +4002,9 @@ void Application::update(float deltaTime) { } } } + } else if (domainLoadingInProgress) { + domainLoadingInProgress = false; + PROFILE_ASYNC_END(interfaceapp, "Scene Loading", ""); } { @@ -4062,12 +4098,12 @@ void Application::update(float deltaTime) { QSharedPointer avatarManager = DependencyManager::get(); if (_physicsEnabled) { - PROFILE_RANGE_EX("Physics", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(interfaceapp, "Physics", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("physics"); { - PROFILE_RANGE_EX("UpdateStats", 0xffffff00, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(interfaceapp, "UpdateStats", 0xffffff00, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("updateStates)"); static VectorOfMotionStates motionStates; @@ -4101,14 +4137,14 @@ void Application::update(float deltaTime) { }); } { - PROFILE_RANGE_EX("StepSimulation", 0xffff8000, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(interfaceapp, "StepSimulation", 0xffff8000, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("stepSimulation"); getEntities()->getTree()->withWriteLock([&] { _physicsEngine->stepSimulation(); }); } { - PROFILE_RANGE_EX("HarvestChanges", 0xffffff00, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(interfaceapp, "HarvestChanges", 0xffffff00, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("harvestChanges"); if (_physicsEngine->hasOutgoingChanges()) { getEntities()->getTree()->withWriteLock([&] { @@ -4150,20 +4186,20 @@ void Application::update(float deltaTime) { _avatarSimCounter.increment(); { - PROFILE_RANGE_EX("OtherAvatars", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(interfaceapp, "OtherAvatars", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount()); avatarManager->updateOtherAvatars(deltaTime); } qApp->updateMyAvatarLookAtPosition(); { - PROFILE_RANGE_EX("MyAvatar", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(interfaceapp, "MyAvatar", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount()); avatarManager->updateMyAvatar(deltaTime); } } { - PROFILE_RANGE_EX("Overlays", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(interfaceapp, "Overlays", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); PerformanceTimer perfTimer("overlays"); _overlays.update(deltaTime); } @@ -4183,7 +4219,7 @@ void Application::update(float deltaTime) { // Update my voxel servers with my current voxel query... { - PROFILE_RANGE_EX("QueryOctree", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); + PROFILE_RANGE_EX(interfaceapp, "QueryOctree", 0xffff0000, (uint64_t)getActiveDisplayPlugin()->presentCount()); QMutexLocker viewLocker(&_viewMutex); PerformanceTimer perfTimer("queryOctree"); quint64 sinceLastQuery = now - _lastQueriedTime; @@ -4223,7 +4259,7 @@ void Application::update(float deltaTime) { avatarManager->postUpdate(deltaTime); { - PROFILE_RANGE_EX("PreRenderLambdas", 0xffff0000, (uint64_t)0); + PROFILE_RANGE_EX(interfaceapp, "PreRenderLambdas", 0xffff0000, (uint64_t)0); std::unique_lock guard(_postUpdateLambdasLock); for (auto& iter : _postUpdateLambdas) { @@ -4501,7 +4537,7 @@ QRect Application::getDesirableApplicationGeometry() const { // void Application::loadViewFrustum(Camera& camera, ViewFrustum& viewFrustum) { PerformanceTimer perfTimer("loadViewFrustum"); - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); // We will use these below, from either the camera or head vectors calculated above viewFrustum.setProjection(camera.getProjection()); @@ -4677,7 +4713,7 @@ void Application::displaySide(RenderArgs* renderArgs, Camera& theCamera, bool se myAvatar->preDisplaySide(renderArgs); activeRenderingThread = QThread::currentThread(); - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); PerformanceTimer perfTimer("display"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide()"); diff --git a/interface/src/scripting/TestScriptingInterface.cpp b/interface/src/scripting/TestScriptingInterface.cpp index 46310c9e40..1e1a4d8d0c 100644 --- a/interface/src/scripting/TestScriptingInterface.cpp +++ b/interface/src/scripting/TestScriptingInterface.cpp @@ -10,6 +10,10 @@ #include "TestScriptingInterface.h" #include +#include + +#include +#include TestScriptingInterface* TestScriptingInterface::getInstance() { static TestScriptingInterface sharedInstance; @@ -28,3 +32,27 @@ void TestScriptingInterface::waitForDownloadIdle() { void TestScriptingInterface::waitIdle() { } + +bool TestScriptingInterface::startTracing(QString logrules) { + if (!logrules.isEmpty()) { + QLoggingCategory::setFilterRules(logrules); + } + + if (!DependencyManager::isSet()) { + return false; + } + + DependencyManager::get()->startTracing(); + return true; +} + +bool TestScriptingInterface::stopTracing(QString filename) { + if (!DependencyManager::isSet()) { + return false; + } + + auto tracer = DependencyManager::get(); + tracer->stopTracing(); + tracer->serialize(filename); + return true; +} \ No newline at end of file diff --git a/interface/src/scripting/TestScriptingInterface.h b/interface/src/scripting/TestScriptingInterface.h index 91277ebc78..0c6ab6baaa 100644 --- a/interface/src/scripting/TestScriptingInterface.h +++ b/interface/src/scripting/TestScriptingInterface.h @@ -38,6 +38,17 @@ public slots: */ void waitIdle(); + /**jsdoc + * Start recording Chrome compatible tracing events + * logRules can be used to specify a set of logging category rules to limit what gets captured + */ + bool startTracing(QString logrules = ""); + + /**jsdoc + * Stop recording Chrome compatible tracing events and serialize recorded events to a file + * Using a filename with a .gz extension will automatically compress the output file + */ + bool stopTracing(QString filename); }; #endif // hifi_TestScriptingInterface_h diff --git a/interface/src/ui/ApplicationOverlay.cpp b/interface/src/ui/ApplicationOverlay.cpp index 32336fe3be..f7bbc1aa96 100644 --- a/interface/src/ui/ApplicationOverlay.cpp +++ b/interface/src/ui/ApplicationOverlay.cpp @@ -29,6 +29,7 @@ #include "ui/Stats.h" #include "ui/AvatarInputs.h" #include "OffscreenUi.h" +#include "InterfaceLogging.h" #include const vec4 CONNECTION_STATUS_BORDER_COLOR{ 1.0f, 0.0f, 0.0f, 0.8f }; @@ -56,7 +57,7 @@ ApplicationOverlay::~ApplicationOverlay() { // Renders the overlays either to a texture or to the screen void ApplicationOverlay::renderOverlay(RenderArgs* renderArgs) { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "ApplicationOverlay::displayOverlay()"); buildFramebufferObject(); @@ -95,7 +96,7 @@ void ApplicationOverlay::renderOverlay(RenderArgs* renderArgs) { } void ApplicationOverlay::renderQmlUi(RenderArgs* renderArgs) { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); if (!_uiTexture) { _uiTexture = gpu::TexturePointer(gpu::Texture::createExternal2D(OffscreenQmlSurface::getDiscardLambda())); @@ -123,7 +124,7 @@ void ApplicationOverlay::renderQmlUi(RenderArgs* renderArgs) { } void ApplicationOverlay::renderAudioScope(RenderArgs* renderArgs) { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); gpu::Batch& batch = *renderArgs->_batch; auto geometryCache = DependencyManager::get(); @@ -142,7 +143,7 @@ void ApplicationOverlay::renderAudioScope(RenderArgs* renderArgs) { } void ApplicationOverlay::renderOverlays(RenderArgs* renderArgs) { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); gpu::Batch& batch = *renderArgs->_batch; auto geometryCache = DependencyManager::get(); @@ -261,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(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); auto uiSize = qApp->getUiSize(); if (!_overlayFramebuffer || uiSize != _overlayFramebuffer->getSize()) { @@ -287,4 +288,4 @@ gpu::TexturePointer ApplicationOverlay::getOverlayTexture() { return gpu::TexturePointer(); } return _overlayFramebuffer->getRenderBuffer(0); -} \ No newline at end of file +} diff --git a/interface/src/ui/overlays/Overlays.cpp b/interface/src/ui/overlays/Overlays.cpp index 242821234a..b1f2f60adc 100644 --- a/interface/src/ui/overlays/Overlays.cpp +++ b/interface/src/ui/overlays/Overlays.cpp @@ -19,6 +19,7 @@ #include #include "Application.h" +#include "InterfaceLogging.h" #include "Image3DOverlay.h" #include "Circle3DOverlay.h" #include "Cube3DOverlay.h" @@ -101,7 +102,7 @@ void Overlays::cleanupOverlaysToDelete() { } void Overlays::renderHUD(RenderArgs* renderArgs) { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(interfaceapp, __FUNCTION__); QReadLocker lock(&_lock); gpu::Batch& batch = *renderArgs->_batch; diff --git a/libraries/animation/src/AnimInverseKinematics.cpp b/libraries/animation/src/AnimInverseKinematics.cpp index 7985251002..c067157e98 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("ik/relax", 0xffff00ff, 0); + PROFILE_RANGE_EX(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("ik/computeTargets", 0xffff00ff, 0); + PROFILE_RANGE_EX(animation, "ik/computeTargets", 0xffff00ff, 0); computeTargets(animVars, targets, underPoses); } @@ -450,7 +450,7 @@ const AnimPoseVec& AnimInverseKinematics::overlay(const AnimVariantMap& animVars } else { { - PROFILE_RANGE_EX("ik/shiftHips", 0xffff00ff, 0); + PROFILE_RANGE_EX(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("ik/ccd", 0xffff00ff, 0); + PROFILE_RANGE_EX(animation, "ik/ccd", 0xffff00ff, 0); solveWithCyclicCoordinateDescent(targets); } { - PROFILE_RANGE_EX("ik/measureHipsOffset", 0xffff00ff, 0); + PROFILE_RANGE_EX(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 7601fbc782..09dda3671f 100644 --- a/libraries/animation/src/AnimationCache.cpp +++ b/libraries/animation/src/AnimationCache.cpp @@ -14,6 +14,9 @@ #include "AnimationCache.h" #include "AnimationLogging.h" +#include +#include +#include int animationPointerMetaTypeId = qRegisterMetaType(); @@ -45,9 +48,14 @@ Animation::Animation(const QUrl& url) : Resource(url) {} AnimationReader::AnimationReader(const QUrl& url, const QByteArray& data) : _url(url), _data(data) { + DependencyManager::get()->incrementStat("PendingProcessing"); } void AnimationReader::run() { + DependencyManager::get()->decrementStat("PendingProcessing"); + CounterStat counter("Processing"); + + PROFILE_RANGE_EX(animation, __FUNCTION__, 0xFF00FF00, 0, { { "url", _url.toString() } }); auto originalPriority = QThread::currentThread()->priority(); if (originalPriority == QThread::InheritPriority) { originalPriority = QThread::NormalPriority; diff --git a/libraries/animation/src/AnimationCache.h b/libraries/animation/src/AnimationCache.h index 59e3de9bcb..0e6a94c1b8 100644 --- a/libraries/animation/src/AnimationCache.h +++ b/libraries/animation/src/AnimationCache.h @@ -65,6 +65,8 @@ public: explicit Animation(const QUrl& url); + QString getType() const override { return "Animation"; } + const FBXGeometry& getGeometry() const { return *_geometry; } virtual bool isLoaded() const override; diff --git a/libraries/animation/src/Rig.cpp b/libraries/animation/src/Rig.cpp index 49363c96e2..ab07a9deb9 100644 --- a/libraries/animation/src/Rig.cpp +++ b/libraries/animation/src/Rig.cpp @@ -882,7 +882,7 @@ void Rig::updateAnimationStateHandlers() { // called on avatar update thread (wh void Rig::updateAnimations(float deltaTime, glm::mat4 rootTransform) { - PROFILE_RANGE_EX(__FUNCTION__, 0xffff00ff, 0); + PROFILE_RANGE_EX(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 969c0a95a9..1c73e4dda2 100644 --- a/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp +++ b/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp @@ -16,7 +16,6 @@ #include #include - #if defined(Q_OS_MAC) #include #endif @@ -44,6 +43,7 @@ #include #include "CompositorHelper.h" +#include "Logging.h" const char* SRGB_TO_LINEAR_FRAG = R"SCRIBE( @@ -129,7 +129,7 @@ public: _context->makeCurrent(); while (!_shutdown) { if (_pendingMainThreadOperation) { - PROFILE_RANGE("MainThreadOp") + PROFILE_RANGE(displayPlugins, "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("PluginPresent") + PROFILE_RANGE(displayPlugins, "PluginPresent") currentPlugin->present(); CHECK_GL_ERROR(); } @@ -560,22 +560,22 @@ void OpenGLDisplayPlugin::compositeLayers() { updateCompositeFramebuffer(); { - PROFILE_RANGE_EX("compositeScene", 0xff0077ff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, "compositeScene", 0xff0077ff, (uint64_t)presentCount()) compositeScene(); } { - PROFILE_RANGE_EX("compositeOverlay", 0xff0077ff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, "compositeOverlay", 0xff0077ff, (uint64_t)presentCount()) compositeOverlay(); } auto compositorHelper = DependencyManager::get(); if (compositorHelper->getReticleVisible()) { - PROFILE_RANGE_EX("compositePointer", 0xff0077ff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, "compositePointer", 0xff0077ff, (uint64_t)presentCount()) compositePointer(); } { - PROFILE_RANGE_EX("compositeExtra", 0xff0077ff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, "compositeExtra", 0xff0077ff, (uint64_t)presentCount()) compositeExtra(); } } @@ -595,12 +595,12 @@ void OpenGLDisplayPlugin::internalPresent() { } void OpenGLDisplayPlugin::present() { - PROFILE_RANGE_EX(__FUNCTION__, 0xffffff00, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, __FUNCTION__, 0xffffff00, (uint64_t)presentCount()) updateFrameData(); incrementPresentCount(); { - PROFILE_RANGE_EX("recycle", 0xff00ff00, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, "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("execute", 0xff00ff00, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, "execute", 0xff00ff00, (uint64_t)presentCount()) _gpuContext->executeFrame(_currentFrame); } // Write all layers to a local framebuffer { - PROFILE_RANGE_EX("composite", 0xff00ffff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, "composite", 0xff00ffff, (uint64_t)presentCount()) compositeLayers(); } // Take the composite framebuffer and send it to the output device { - PROFILE_RANGE_EX("internalPresent", 0xff00ffff, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, "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 9964c46c8d..1bfe73b687 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(__FUNCTION__, 0xff00ff00, (uint64_t)presentCount()) + PROFILE_RANGE_EX(displayPlugins, __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 dc5b6cd8d3..593e3e2aca 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("MetaModelRender"); + PROFILE_RANGE(renderlogging, "MetaModelRender"); payload->entity->render(args); } } diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index 7f4cfa78d0..05d508fe79 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/libraries/entities/src/EntityTree.cpp @@ -24,6 +24,7 @@ #include "EntitiesLogging.h" #include "RecurseOctreeToMapOperator.h" #include "LogHandler.h" +#include static const quint64 DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER = USECS_PER_MSEC * 50; const float EntityTree::DEFAULT_MAX_TMP_ENTITY_LIFETIME = 60 * 60; // 1 hour diff --git a/libraries/fbx/src/FBXReader_Node.cpp b/libraries/fbx/src/FBXReader_Node.cpp index 44bb4ac48b..034070c9d7 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(__FUNCTION__, 0xff0000ff, device); + PROFILE_RANGE_EX(modelformat, __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 03e24c9046..8ea2c5fd38 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(__FUNCTION__, 0xffff0000, nullptr); + PROFILE_RANGE_EX(modelformat, __FUNCTION__, 0xffff0000, nullptr); QBuffer buffer { &model }; buffer.open(QIODevice::ReadOnly); diff --git a/libraries/gl/src/gl/GLLogging.cpp b/libraries/gl/src/gl/GLLogging.cpp index 18d2023acd..26ef274616 100644 --- a/libraries/gl/src/gl/GLLogging.cpp +++ b/libraries/gl/src/gl/GLLogging.cpp @@ -11,4 +11,4 @@ #include "GLLogging.h" -Q_LOGGING_CATEGORY(glLogging, "hifi.glLogging") +Q_LOGGING_CATEGORY(glLogging, "hifi.gl") diff --git a/libraries/gl/src/gl/OffscreenQmlSurface.cpp b/libraries/gl/src/gl/OffscreenQmlSurface.cpp index cde779d101..e1e7d46570 100644 --- a/libraries/gl/src/gl/OffscreenQmlSurface.cpp +++ b/libraries/gl/src/gl/OffscreenQmlSurface.cpp @@ -284,7 +284,7 @@ void OffscreenQmlSurface::render() { GLuint texture = offscreenTextures.getNextTexture(_size); glBindFramebuffer(GL_DRAW_FRAMEBUFFER, _fbo); glFramebufferTexture(GL_DRAW_FRAMEBUFFER, GL_COLOR_ATTACHMENT0, texture, 0); - PROFILE_RANGE("qml_render->rendercontrol") + PROFILE_RANGE(glLogging, "qml_render->rendercontrol") _renderControl->render(); glBindFramebuffer(GL_DRAW_FRAMEBUFFER, 0); glBindTexture(GL_TEXTURE_2D, texture); @@ -622,7 +622,7 @@ void OffscreenQmlSurface::updateQuick() { } if (_render) { - PROFILE_RANGE(__FUNCTION__); + 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 dc49c0c4fd..ea9d421cba 100644 --- a/libraries/gpu-gl/src/gpu/gl/GLBackend.cpp +++ b/libraries/gpu-gl/src/gpu/gl/GLBackend.cpp @@ -30,6 +30,7 @@ #include "GLTexture.h" #include "GLShader.h" + using namespace gpu; using namespace gpu::gl; @@ -199,7 +200,7 @@ void GLBackend::renderPassTransfer(const Batch& batch) { _inRenderTransferPass = true; { // Sync all the buffers - PROFILE_RANGE("syncGPUBuffer"); + PROFILE_RANGE(gpugllogging, "syncGPUBuffer"); for (auto& cached : batch._buffers._items) { if (cached._data) { @@ -209,7 +210,7 @@ void GLBackend::renderPassTransfer(const Batch& batch) { } { // Sync all the buffers - PROFILE_RANGE("syncCPUTransform"); + PROFILE_RANGE(gpugllogging, "syncCPUTransform"); _transform._cameras.clear(); _transform._cameraOffsets.clear(); @@ -241,7 +242,7 @@ void GLBackend::renderPassTransfer(const Batch& batch) { } { // Sync the transform buffers - PROFILE_RANGE("syncGPUTransform"); + PROFILE_RANGE(gpugllogging, "syncGPUTransform"); transferTransformState(batch); } @@ -303,7 +304,7 @@ void GLBackend::render(const Batch& batch) { } { - PROFILE_RANGE("Transfer"); + PROFILE_RANGE(gpugllogging, "Transfer"); renderPassTransfer(batch); } @@ -313,7 +314,7 @@ void GLBackend::render(const Batch& batch) { } #endif { - PROFILE_RANGE(_stereo._enable ? "Render Stereo" : "Render"); + PROFILE_RANGE(gpugllogging, _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 c7f4694f3c..f0e87184c1 100644 --- a/libraries/gpu-gl/src/gpu/gl/GLBackendQuery.cpp +++ b/libraries/gpu-gl/src/gpu/gl/GLBackendQuery.cpp @@ -10,6 +10,7 @@ // #include "GLBackend.h" #include "GLQuery.h" +#include "GLShared.h" using namespace gpu; using namespace gpu::gl; @@ -27,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(glquery->_profileRangeId, query->getName().c_str(), 0xFFFF7F00); + PROFILE_RANGE_BEGIN(gpugllogging, glquery->_profileRangeId, query->getName().c_str(), 0xFFFF7F00); ++_queryStage._rangeQueryDepth; glGetInteger64v(GL_TIMESTAMP, (GLint64*)&glquery->_batchElapsedTime); @@ -61,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(glquery->_profileRangeId); + PROFILE_RANGE_END(gpugllogging, glquery->_profileRangeId); (void)CHECK_GL_ERROR(); } diff --git a/libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp b/libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp index 5594be36b6..d7f1cc7fab 100644 --- a/libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp +++ b/libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp @@ -12,7 +12,6 @@ #include #include -#include #include "../gl/GLTexelFormat.h" @@ -123,7 +122,7 @@ void GL41Texture::transferMip(uint16_t mipLevel, uint8_t face) const { } void GL41Texture::startTransfer() { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(gpugllogging, __FUNCTION__); Parent::startTransfer(); glBindTexture(_target, _id); diff --git a/libraries/gpu/src/gpu/Texture.cpp b/libraries/gpu/src/gpu/Texture.cpp index 45aff54b8f..6098d816fb 100755 --- a/libraries/gpu/src/gpu/Texture.cpp +++ b/libraries/gpu/src/gpu/Texture.cpp @@ -17,6 +17,7 @@ #include #include +#include #include @@ -757,6 +758,9 @@ bool sphericalHarmonicsFromTexture(const gpu::Texture& cubeTexture, std::vector< if(width != cubeTexture.getHeight()) { return false; } + + PROFILE_RANGE(gpulogging, "sphericalHarmonicsFromTexture"); + const uint sqOrder = order*order; // allocate memory for calculations @@ -788,6 +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"); auto numComponents = cubeTexture.accessStoredMipFace(0,face)->getFormat().getScalarCount(); auto data = cubeTexture.accessStoredMipFace(0,face)->readData(); @@ -995,4 +1000,4 @@ Texture::ExternalUpdates Texture::getUpdates() const { _externalUpdates.swap(result); } return result; -} \ No newline at end of file +} diff --git a/libraries/model-networking/src/model-networking/ModelCache.cpp b/libraries/model-networking/src/model-networking/ModelCache.cpp index 6eacbab46a..9e0b614292 100644 --- a/libraries/model-networking/src/model-networking/ModelCache.cpp +++ b/libraries/model-networking/src/model-networking/ModelCache.cpp @@ -21,6 +21,8 @@ #include #include "ModelNetworkingLogging.h" +#include +#include class GeometryReader; @@ -39,6 +41,8 @@ class GeometryMappingResource : public GeometryResource { public: GeometryMappingResource(const QUrl& url) : GeometryResource(url) {}; + QString getType() const override { return "GeometryMapping"; } + virtual void downloadFinished(const QByteArray& data) override; private slots: @@ -50,6 +54,9 @@ private: }; void GeometryMappingResource::downloadFinished(const QByteArray& data) { + PROFILE_ASYNC_BEGIN(modelnetworking, "GeometryMappingResource::downloadFinished", _url.toString(), + { { "url", _url.toString() } }); + auto mapping = FSTReader::readMapping(data); QString filename = mapping.value("filename").toString(); @@ -113,6 +120,7 @@ void GeometryMappingResource::onGeometryMappingLoaded(bool success) { disconnect(_connection); // FIXME Should not have to do this } + PROFILE_ASYNC_END(modelnetworking, "GeometryMappingResource::downloadFinished", _url.toString()); finishedLoading(success); } @@ -120,8 +128,15 @@ class GeometryReader : public QRunnable { public: GeometryReader(QWeakPointer& resource, const QUrl& url, const QVariantHash& mapping, const QByteArray& data) : - _resource(resource), _url(url), _mapping(mapping), _data(data) {} - virtual ~GeometryReader() = default; + _resource(resource), _url(url), _mapping(mapping), _data(data) { + + DependencyManager::get()->incrementStat("PendingProcessing"); + //trace::FLOW_BEGIN("GeometryReader", trace::cResource, _url.toString(), { { "url", _url.toString() } }); + + } + virtual ~GeometryReader() { + //trace::FLOW_END("GeometryReader", trace::cResource, _url.toString(), { { "url", _url.toString() } }); + } virtual void run() override; @@ -133,6 +148,10 @@ private: }; void GeometryReader::run() { + DependencyManager::get()->decrementStat("PendingProcessing"); + //trace::ASYNC_BEGIN("GeometryReader::run", trace::cResource, _url.toString(), { { "url", _url.toString() } }); + CounterStat counter("Processing"); + PROFILE_RANGE_EX(modelnetworking, "GeometryReader::run", 0xFF00FF00, 0, { { "url", _url.toString() } }); auto originalPriority = QThread::currentThread()->priority(); if (originalPriority == QThread::InheritPriority) { originalPriority = QThread::NormalPriority; @@ -189,6 +208,7 @@ void GeometryReader::run() { Q_ARG(bool, false)); } } + //trace::ASYNC_END("GeometryReader::run", trace::cResource, _url.toString()); } class GeometryDefinitionResource : public GeometryResource { @@ -197,6 +217,8 @@ public: GeometryDefinitionResource(const QUrl& url, const QVariantHash& mapping, const QUrl& textureBaseUrl) : GeometryResource(url, resolveTextureBaseUrl(url, textureBaseUrl)), _mapping(mapping) {} + QString getType() const override { return "GeometryDefinition"; } + virtual void downloadFinished(const QByteArray& data) override; protected: diff --git a/libraries/model-networking/src/model-networking/ShaderCache.h b/libraries/model-networking/src/model-networking/ShaderCache.h index 4af12fdbfa..bd78e6e7e3 100644 --- a/libraries/model-networking/src/model-networking/ShaderCache.h +++ b/libraries/model-networking/src/model-networking/ShaderCache.h @@ -14,6 +14,9 @@ class NetworkShader : public Resource { public: NetworkShader(const QUrl& url); + + QString getType() const override { return "NetworkShader"; } + virtual void downloadFinished(const QByteArray& data) override; QString _source; diff --git a/libraries/model-networking/src/model-networking/TextureCache.cpp b/libraries/model-networking/src/model-networking/TextureCache.cpp index 215263661d..76dc4e0dc6 100644 --- a/libraries/model-networking/src/model-networking/TextureCache.cpp +++ b/libraries/model-networking/src/model-networking/TextureCache.cpp @@ -33,6 +33,8 @@ #include #include "ModelNetworkingLogging.h" +#include +#include TextureCache::TextureCache() { setUnusedResourceCacheSize(0); @@ -331,6 +333,7 @@ ImageReader::ImageReader(const QWeakPointer& resource, const QByteArra outFile.close(); } #endif + DependencyManager::get()->incrementStat("PendingProcessing"); } void ImageReader::listSupportedImageFormats() { @@ -342,7 +345,12 @@ void ImageReader::listSupportedImageFormats() { } void ImageReader::run() { - PROFILE_RANGE_EX(__FUNCTION__, 0xffff0000, nullptr); + DependencyManager::get()->decrementStat("PendingProcessing"); + + CounterStat counter("Processing"); + + //trace::DURATION_BEGIN("ImageReader::threadSetup", trace::cResource, { { "url", _url.toString() } }); + PROFILE_RANGE_EX(modelnetworking, __FUNCTION__, 0xffff0000, 0, { { "url", _url.toString() } }); auto originalPriority = QThread::currentThread()->priority(); if (originalPriority == QThread::InheritPriority) { originalPriority = QThread::NormalPriority; @@ -356,7 +364,6 @@ void ImageReader::run() { qCWarning(modelnetworking) << "Abandoning load of" << _url << "; could not get strong ref"; return; } - listSupportedImageFormats(); // Help the QImage loader by extracting the image file format from the url filename ext. @@ -378,7 +385,6 @@ void ImageReader::run() { } return; } - gpu::TexturePointer texture = nullptr; { // Double-check the resource still exists between long operations. @@ -390,7 +396,7 @@ void ImageReader::run() { auto url = _url.toString().toStdString(); - PROFILE_RANGE_EX(__FUNCTION__"::textureLoader", 0xffffff00, nullptr); + PROFILE_RANGE_EX(modelnetworking, __FUNCTION__, 0xffffff00, 0); texture.reset(resource.dynamicCast()->getTextureLoader()(image, url)); } diff --git a/libraries/model-networking/src/model-networking/TextureCache.h b/libraries/model-networking/src/model-networking/TextureCache.h index e1fa119e0d..8ccfe5364c 100644 --- a/libraries/model-networking/src/model-networking/TextureCache.h +++ b/libraries/model-networking/src/model-networking/TextureCache.h @@ -63,10 +63,13 @@ public: NetworkTexture(const QUrl& url, Type type, const QByteArray& content); NetworkTexture(const QUrl& url, const TextureLoaderFunc& textureLoader, const QByteArray& content); + QString getType() const override { return "NetworkTexture"; } + int getOriginalWidth() const { return _originalWidth; } int getOriginalHeight() const { return _originalHeight; } int getWidth() const { return _width; } int getHeight() const { return _height; } + Type getTextureType() const { return _type; } TextureLoaderFunc getTextureLoader() const; diff --git a/libraries/model/src/model/TextureMap.cpp b/libraries/model/src/model/TextureMap.cpp index 3e346a564e..83914ae950 100755 --- a/libraries/model/src/model/TextureMap.cpp +++ b/libraries/model/src/model/TextureMap.cpp @@ -14,6 +14,8 @@ #include #include +#include + #include "ModelLogging.h" using namespace model; @@ -744,6 +746,8 @@ 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"); + gpu::Texture* theTexture = nullptr; if ((srcImage.width() > 0) && (srcImage.height() > 0)) { QImage image = processSourceImage(srcImage, true); @@ -801,11 +805,13 @@ gpu::Texture* TextureUsage::processCubeTextureColorFromImage(const QImage& srcIm } if (generateMips) { + PROFILE_RANGE(modelLog, "generateMips"); theTexture->autoGenerateMips(-1); } // Generate irradiance while we are at it if (generateIrradiance) { + PROFILE_RANGE(modelLog, "generateIrradiance"); theTexture->generateIrradiance(); } } diff --git a/libraries/networking/src/AssetClient.cpp b/libraries/networking/src/AssetClient.cpp index 0563141511..37b1af0996 100644 --- a/libraries/networking/src/AssetClient.cpp +++ b/libraries/networking/src/AssetClient.cpp @@ -604,7 +604,7 @@ bool AssetClient::cancelGetAssetRequest(MessageID id) { for (auto& kv : _pendingRequests) { auto& messageCallbackMap = kv.second; auto requestIt = messageCallbackMap.find(id); - if (requestIt != kv.second.end()) { + if (requestIt != messageCallbackMap.end()) { auto& message = requestIt->second.message; if (message) { diff --git a/libraries/networking/src/AssetRequest.cpp b/libraries/networking/src/AssetRequest.cpp index 4449531177..e022eb7802 100644 --- a/libraries/networking/src/AssetRequest.cpp +++ b/libraries/networking/src/AssetRequest.cpp @@ -19,8 +19,12 @@ #include "NetworkLogging.h" #include "NodeList.h" #include "ResourceCache.h" +#include + +static int requestID = 0; AssetRequest::AssetRequest(const QString& hash) : + _requestID(++requestID), _hash(hash) { } @@ -28,11 +32,17 @@ AssetRequest::AssetRequest(const QString& hash) : AssetRequest::~AssetRequest() { auto assetClient = DependencyManager::get(); if (_assetRequestID) { + //trace::ASYNC_END("assetRequest", trace::nameAssetData, _requestID); assetClient->cancelGetAssetRequest(_assetRequestID); } if (_assetInfoRequestID) { + //trace::ASYNC_END("assetRequest", trace::nameAssetInfo, _requestID); assetClient->cancelGetAssetInfoRequest(_assetInfoRequestID); } + if (_assetRequestID || _assetInfoRequestID) { + //trace::ASYNC_END(trace::nameAssetEndedEarly, "assetRequest", _requestID); + //trace::ASYNC_END(trace::nameAssetRequest, "assetRequest", _requestID); + } } void AssetRequest::start() { @@ -46,11 +56,14 @@ void AssetRequest::start() { return; } + //trace::ASYNC_BEGIN(trace::nameAssetRequest, "assetRequest", _requestID); + // in case we haven't parsed a valid hash, return an error now if (!isValidHash(_hash)) { _error = InvalidHash; _state = Finished; + //trace::ASYNC_END(trace::nameAssetRequest, "assetRequest", _requestID); emit finished(this); return; } @@ -63,16 +76,21 @@ void AssetRequest::start() { _error = NoError; _state = Finished; + //trace::ASYNC_END(trace::nameAssetRequest, "assetRequest", _requestID); emit finished(this); return; } _state = WaitingForInfo; + //trace::ASYNC_BEGIN(trace::nameAssetInfo, "assetRequest", _requestID); + auto assetClient = DependencyManager::get(); _assetInfoRequestID = assetClient->getAssetInfo(_hash, [this](bool responseReceived, AssetServerError serverError, AssetInfo info) { + //trace::ASYNC_END(trace::nameAssetInfo, "assetRequest", _requestID); + _assetInfoRequestID = AssetClient::INVALID_MESSAGE_ID; _info = info; @@ -93,6 +111,7 @@ void AssetRequest::start() { if (_error != NoError) { qCWarning(asset_client) << "Got error retrieving asset info for" << _hash; _state = Finished; + //trace::ASYNC_END(trace::nameAssetRequest, "assetRequest", _requestID); emit finished(this); return; @@ -153,6 +172,7 @@ void AssetRequest::start() { } _state = Finished; + //trace::ASYNC_END(trace::nameAssetRequest, "assetRequest", _requestID); emit finished(this); }, [this, that](qint64 totalReceived, qint64 total) { if (!that) { diff --git a/libraries/networking/src/AssetRequest.h b/libraries/networking/src/AssetRequest.h index 0a6810b052..e5d9d119d7 100644 --- a/libraries/networking/src/AssetRequest.h +++ b/libraries/networking/src/AssetRequest.h @@ -56,6 +56,7 @@ signals: void progress(qint64 totalReceived, qint64 total); private: + int _requestID; State _state = NotStarted; Error _error = NoError; AssetInfo _info; diff --git a/libraries/networking/src/AssetResourceRequest.cpp b/libraries/networking/src/AssetResourceRequest.cpp index 11ced60ec4..ff41ffc2fb 100644 --- a/libraries/networking/src/AssetResourceRequest.cpp +++ b/libraries/networking/src/AssetResourceRequest.cpp @@ -17,6 +17,8 @@ #include "AssetUtils.h" #include "MappingRequest.h" #include "NetworkLogging.h" +#include +#include static const int DOWNLOAD_PROGRESS_LOG_INTERVAL_SECONDS = 5; @@ -27,12 +29,18 @@ AssetResourceRequest::AssetResourceRequest(const QUrl& url) : } AssetResourceRequest::~AssetResourceRequest() { - if (_assetMappingRequest) { - _assetMappingRequest->deleteLater(); - } - - if (_assetRequest) { - _assetRequest->deleteLater(); + if (_assetRequest || _assetMappingRequest) { + if (_assetMappingRequest) { + _assetMappingRequest->deleteLater(); +// PROFILE_ASYNC_END("resource", "AssetResourceRequestMapping", _url.toString()); + } + + if (_assetRequest) { + _assetRequest->deleteLater(); + //PROFILE_ASYNC_END("resource", "AssetResourceRequestData", _url.toString()); + } + + //trace::ASYNC_END("AssetResourceRequest", trace::cResource, _url.toString()); } } @@ -44,6 +52,8 @@ bool AssetResourceRequest::urlIsAssetHash() const { } void AssetResourceRequest::doSend() { + //trace::ASYNC_BEGIN("AssetResourceRequest", trace::cResource, _url.toString(), { { "url", _url.toString() } }); + // We'll either have a hash or an ATP path to a file (that maps to a hash) if (urlIsAssetHash()) { // We've detected that this is a hash - simply use AssetClient to request that asset @@ -61,6 +71,8 @@ void AssetResourceRequest::doSend() { } void AssetResourceRequest::requestMappingForPath(const AssetPath& path) { + //trace::ASYNC_BEGIN("AssetResourceRequestMapping", trace::cResource, _url.toString()); + auto assetClient = DependencyManager::get(); _assetMappingRequest = assetClient->createGetMappingRequest(path); @@ -69,6 +81,8 @@ void AssetResourceRequest::requestMappingForPath(const AssetPath& path) { Q_ASSERT(_state == InProgress); Q_ASSERT(request == _assetMappingRequest); + //trace::ASYNC_END("AssetResourceRequestMapping", trace::cResource, _url.toString()); + switch (request->getError()) { case MappingRequest::NoError: // we have no error, we should have a resulting hash - use that to send of a request for that asset @@ -96,6 +110,8 @@ void AssetResourceRequest::requestMappingForPath(const AssetPath& path) { _state = Finished; emit finished(); + //trace::ASYNC_END("AssetResourceRequest", trace::cResource, _url.toString()); + break; } } @@ -108,6 +124,7 @@ void AssetResourceRequest::requestMappingForPath(const AssetPath& path) { } void AssetResourceRequest::requestHash(const AssetHash& hash) { + //trace::ASYNC_BEGIN("AssetResourceRequestData", trace::cResource, _url.toString()); // Make request to atp auto assetClient = DependencyManager::get(); @@ -118,6 +135,8 @@ void AssetResourceRequest::requestHash(const AssetHash& hash) { Q_ASSERT(_state == InProgress); Q_ASSERT(req == _assetRequest); Q_ASSERT(req->getState() == AssetRequest::Finished); + + //trace::ASYNC_END("AssetResourceRequestData", trace::cResource, _url.toString()); switch (req->getError()) { case AssetRequest::Error::NoError: @@ -143,6 +162,8 @@ void AssetResourceRequest::requestHash(const AssetHash& hash) { _assetRequest->deleteLater(); _assetRequest = nullptr; + + //trace::ASYNC_END("AssetResourceRequest", trace::cResource, _url.toString()); }); _assetRequest->start(); diff --git a/libraries/networking/src/Assignment.cpp b/libraries/networking/src/Assignment.cpp index 0114bcb708..028cdb95db 100644 --- a/libraries/networking/src/Assignment.cpp +++ b/libraries/networking/src/Assignment.cpp @@ -19,6 +19,7 @@ #include #include "Assignment.h" #include +#include Assignment::Type Assignment::typeForNodeType(NodeType_t nodeType) { switch (nodeType) { @@ -51,7 +52,7 @@ Assignment::Assignment() : } -Assignment::Assignment(Assignment::Command command, Assignment::Type type, const QString& pool, Assignment::Location location) : +Assignment::Assignment(Assignment::Command command, Assignment::Type type, const QString& pool, Assignment::Location location, QString dataDirectory) : _uuid(), _command(command), _type(type), @@ -60,7 +61,8 @@ Assignment::Assignment(Assignment::Command command, Assignment::Type type, const _payload(), _isStatic(false), _walletUUID(), - _nodeVersion() + _nodeVersion(), + _dataDirectory(dataDirectory) { if (_command == Assignment::CreateCommand) { // this is a newly created assignment, generate a random UUID diff --git a/libraries/networking/src/Assignment.h b/libraries/networking/src/Assignment.h index 97caedcfb3..906a89774c 100644 --- a/libraries/networking/src/Assignment.h +++ b/libraries/networking/src/Assignment.h @@ -55,7 +55,8 @@ public: Assignment(Assignment::Command command, Assignment::Type type, const QString& pool = emptyPool, - Assignment::Location location = Assignment::LocalLocation); + Assignment::Location location = Assignment::LocalLocation, + QString dataDirectory = QString()); Assignment(const Assignment& otherAssignment); Assignment& operator=(const Assignment &rhsAssignment); @@ -103,6 +104,7 @@ protected: bool _isStatic; /// defines if this assignment needs to be re-queued in the domain-server if it stops being fulfilled QUuid _walletUUID; /// the UUID for the wallet that should be paid for this assignment QString _nodeVersion; + QString _dataDirectory; }; uint qHash(const Assignment::Type& key, uint seed); diff --git a/libraries/networking/src/HifiSockAddr.cpp b/libraries/networking/src/HifiSockAddr.cpp index d6981f420d..217d3096f5 100644 --- a/libraries/networking/src/HifiSockAddr.cpp +++ b/libraries/networking/src/HifiSockAddr.cpp @@ -109,6 +109,10 @@ void HifiSockAddr::handleLookupResult(const QHostInfo& hostInfo) { } } +QString HifiSockAddr::toString() const { + return _address.toString() + ":" + QString::number(_port); +} + QDebug operator<<(QDebug debug, const HifiSockAddr& sockAddr) { debug.nospace() << sockAddr._address.toString().toLocal8Bit().constData() << ":" << sockAddr._port; return debug.space(); diff --git a/libraries/networking/src/HifiSockAddr.h b/libraries/networking/src/HifiSockAddr.h index c4ff8cb246..af939de736 100644 --- a/libraries/networking/src/HifiSockAddr.h +++ b/libraries/networking/src/HifiSockAddr.h @@ -53,6 +53,8 @@ public: static int packSockAddr(unsigned char* packetData, const HifiSockAddr& packSockAddr); static int unpackSockAddr(const unsigned char* packetData, HifiSockAddr& unpackDestSockAddr); + QString toString() const; + friend QDebug operator<<(QDebug debug, const HifiSockAddr& sockAddr); friend QDataStream& operator<<(QDataStream& dataStream, const HifiSockAddr& sockAddr); friend QDataStream& operator>>(QDataStream& dataStream, HifiSockAddr& sockAddr); diff --git a/libraries/networking/src/LimitedNodeList.cpp b/libraries/networking/src/LimitedNodeList.cpp index fa404b39d8..9a23964828 100644 --- a/libraries/networking/src/LimitedNodeList.cpp +++ b/libraries/networking/src/LimitedNodeList.cpp @@ -37,6 +37,7 @@ #include "HifiSockAddr.h" #include "NetworkLogging.h" #include "udt/Packet.h" +#include static Setting::Handle LIMITED_NODELIST_LOCAL_PORT("LimitedNodeList.LocalPort", 0); @@ -584,6 +585,7 @@ SharedNodePointer LimitedNodeList::addOrUpdateNode(const QUuid& uuid, NodeType_t return matchingNode; } else { + //trace::ASYNC_BEGIN("Node:" + NodeType::getNodeTypeName(nodeType), "NodeConnection", NodeType::getNodeTypeName(nodeType), { { "type", NodeType::getNodeTypeName(nodeType) } }); // we didn't have this node, so add them Node* newNode = new Node(uuid, nodeType, publicSocket, localSocket, permissions, connectionSecret, this); @@ -628,6 +630,7 @@ SharedNodePointer LimitedNodeList::addOrUpdateNode(const QUuid& uuid, NodeType_t emit nodeActivated(newNodePointer); } else { connect(newNodePointer.data(), &NetworkPeer::socketActivated, this, [=] { + //trace::ASYNC_END("Add" + NodeType::getNodeTypeName(nodeType), "NodeConnection", NodeType::getNodeTypeName(nodeType), { { "type", NodeType::getNodeTypeName(nodeType) } }); emit nodeActivated(newNodePointer); disconnect(newNodePointer.data(), &NetworkPeer::socketActivated, this, 0); }); @@ -1116,7 +1119,6 @@ void LimitedNodeList::flagTimeForConnectionStep(ConnectionStep connectionStep) { } void LimitedNodeList::flagTimeForConnectionStep(ConnectionStep connectionStep, quint64 timestamp) { - if (connectionStep == ConnectionStep::LookupAddress) { QWriteLocker writeLock(&_connectionTimeLock); diff --git a/libraries/networking/src/LimitedNodeList.h b/libraries/networking/src/LimitedNodeList.h index c635744512..0d54c843f6 100644 --- a/libraries/networking/src/LimitedNodeList.h +++ b/libraries/networking/src/LimitedNodeList.h @@ -103,8 +103,7 @@ public: ReceiveFirstAudioPacket }; - Q_ENUMS(ConnectionStep); - + Q_ENUM(ConnectionStep); const QUuid& getSessionUUID() const { return _sessionUUID; } void setSessionUUID(const QUuid& sessionUUID); diff --git a/libraries/networking/src/NetworkLogging.cpp b/libraries/networking/src/NetworkLogging.cpp index 01abd6ae19..834398694d 100644 --- a/libraries/networking/src/NetworkLogging.cpp +++ b/libraries/networking/src/NetworkLogging.cpp @@ -12,5 +12,6 @@ #include "NetworkLogging.h" Q_LOGGING_CATEGORY(networking, "hifi.networking") +Q_LOGGING_CATEGORY(resourceLog, "hifi.networking.resource") Q_LOGGING_CATEGORY(asset_client, "hifi.networking.asset_client") Q_LOGGING_CATEGORY(messages_client, "hifi.networking.messages_client") diff --git a/libraries/networking/src/NetworkLogging.h b/libraries/networking/src/NetworkLogging.h index 37ebc1933d..30116ff405 100644 --- a/libraries/networking/src/NetworkLogging.h +++ b/libraries/networking/src/NetworkLogging.h @@ -14,6 +14,7 @@ #include +Q_DECLARE_LOGGING_CATEGORY(resourceLog) Q_DECLARE_LOGGING_CATEGORY(networking) Q_DECLARE_LOGGING_CATEGORY(asset_client) Q_DECLARE_LOGGING_CATEGORY(messages_client) diff --git a/libraries/networking/src/NetworkPeer.cpp b/libraries/networking/src/NetworkPeer.cpp index 2ebee1b71f..abbd262f3d 100644 --- a/libraries/networking/src/NetworkPeer.cpp +++ b/libraries/networking/src/NetworkPeer.cpp @@ -20,6 +20,8 @@ #include "BandwidthRecorder.h" #include "NetworkLogging.h" +#include +#include "NodeType.h" NetworkPeer::NetworkPeer(QObject* parent) : @@ -156,6 +158,7 @@ void NetworkPeer::activateMatchingOrNewSymmetricSocket(const HifiSockAddr& match } void NetworkPeer::softReset() { + qDebug() << "Soft reset "; // a soft reset should clear the sockets and reset the number of connection attempts _localSocket.clear(); _publicSocket.clear(); diff --git a/libraries/networking/src/NodeList.cpp b/libraries/networking/src/NodeList.cpp index c44681ac79..29b7ea0385 100644 --- a/libraries/networking/src/NodeList.cpp +++ b/libraries/networking/src/NodeList.cpp @@ -31,6 +31,7 @@ #include "NetworkLogging.h" #include "udt/PacketHeaders.h" #include "SharedUtil.h" +#include const int KEEPALIVE_PING_INTERVAL_MS = 1000; diff --git a/libraries/networking/src/ResourceCache.cpp b/libraries/networking/src/ResourceCache.cpp index 5fb686ca6f..db4bc35cd4 100644 --- a/libraries/networking/src/ResourceCache.cpp +++ b/libraries/networking/src/ResourceCache.cpp @@ -23,6 +23,8 @@ #include "NodeList.h" #include "ResourceCache.h" +#include +#include #define clamp(x, min, max) (((x) < (min)) ? (min) :\ (((x) > (max)) ? (max) :\ @@ -495,11 +497,12 @@ const int DEFAULT_REQUEST_LIMIT = 10; int ResourceCache::_requestLimit = DEFAULT_REQUEST_LIMIT; int ResourceCache::_requestsActive = 0; +static int requestID = 0; + Resource::Resource(const QUrl& url) : _url(url), _activeUrl(url), - _request(nullptr) { - + _requestID(++requestID) { init(); } @@ -647,20 +650,24 @@ void Resource::reinsert() { void Resource::makeRequest() { if (_request) { + PROFILE_ASYNC_END(resourceLog, "Resource:" + getType(), QString::number(_requestID)); _request->disconnect(); _request->deleteLater(); } + PROFILE_ASYNC_BEGIN(resourceLog, "Resource:" + getType(), QString::number(_requestID), { { "url", _url.toString() }, { "activeURL", _activeUrl.toString() } }); + _request = ResourceManager::createResourceRequest(this, _activeUrl); if (!_request) { qCDebug(networking).noquote() << "Failed to get request for" << _url.toDisplayString(); ResourceCache::requestCompleted(_self); finishedLoading(false); + PROFILE_ASYNC_END(resourceLog, "Resource:" + getType(), QString::number(_requestID)); return; } - qCDebug(networking).noquote() << "Starting request for:" << _url.toDisplayString(); + qCDebug(resourceLog).noquote() << "Starting request for:" << _url.toDisplayString(); emit loading(); connect(_request, &ResourceRequest::progress, this, &Resource::onProgress); @@ -681,6 +688,11 @@ 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), { + { "from_cache", _request->loadedFromCache() }, + { "size_mb", _bytesTotal / 1000000.0 } + }); + setSize(_bytesTotal); if (!_request || _request != sender()) { diff --git a/libraries/networking/src/ResourceCache.h b/libraries/networking/src/ResourceCache.h index 48b21a1e98..4231785616 100644 --- a/libraries/networking/src/ResourceCache.h +++ b/libraries/networking/src/ResourceCache.h @@ -342,6 +342,8 @@ public: Resource(const QUrl& url); ~Resource(); + + virtual QString getType() const { return "Resource"; } /// Returns the key last used to identify this resource in the unused map. int getLRUKey() const { return _lruKey; } @@ -461,6 +463,7 @@ private: bool isInScript() const { return _isInScript; } void setInScript(bool isInScript) { _isInScript = isInScript; } + int _requestID; ResourceRequest* _request{ nullptr }; int _lruKey{ 0 }; QTimer* _replyTimer{ nullptr }; diff --git a/libraries/networking/src/udt/Connection.cpp b/libraries/networking/src/udt/Connection.cpp index a190fe3ddc..46d06ee220 100644 --- a/libraries/networking/src/udt/Connection.cpp +++ b/libraries/networking/src/udt/Connection.cpp @@ -23,6 +23,7 @@ #include "Packet.h" #include "PacketList.h" #include "Socket.h" +#include using namespace udt; using namespace std::chrono; @@ -32,6 +33,9 @@ Connection::Connection(Socket* parentSocket, HifiSockAddr destination, std::uniq _destination(destination), _congestionControl(move(congestionControl)) { + //trace::ASYNC_BEGIN("Connection", "Connection", _destination.toString()); + //trace::ASYNC_BEGIN("DownHandshake", "Connection", _destination.toString()); + Q_ASSERT_X(parentSocket, "Connection::Connection", "Must be called with a valid Socket*"); Q_ASSERT_X(_congestionControl, "Connection::Connection", "Must be called with a valid CongestionControl object"); @@ -68,6 +72,7 @@ Connection::~Connection() { for (auto& pendingMessage : _pendingReceivedMessages) { _parentSocket->messageFailed(this, pendingMessage.first); } + //trace::ASYNC_END("Connection", "Connection", _destination.toString()); } void Connection::stopSendQueue() { @@ -812,6 +817,7 @@ void Connection::processHandshake(ControlPacketPointer controlPacket) { _parentSocket->writeBasePacket(*_handshakeACK, _destination); // indicate that handshake has been received + //trace::ASYNC_END("DownHandshake", "Connection", _destination.toString()); _hasReceivedHandshake = true; if (_didRequestHandshake) { diff --git a/libraries/networking/src/udt/Connection.h b/libraries/networking/src/udt/Connection.h index f94550426e..c134081dde 100644 --- a/libraries/networking/src/udt/Connection.h +++ b/libraries/networking/src/udt/Connection.h @@ -58,7 +58,7 @@ public: using ControlPacketPointer = std::unique_ptr; Connection(Socket* parentSocket, HifiSockAddr destination, std::unique_ptr congestionControl); - ~Connection(); + virtual ~Connection(); void sendReliablePacket(std::unique_ptr packet); void sendReliablePacketList(std::unique_ptr packet); diff --git a/libraries/networking/src/udt/SendQueue.cpp b/libraries/networking/src/udt/SendQueue.cpp index f42e2b77fb..8e32befe14 100644 --- a/libraries/networking/src/udt/SendQueue.cpp +++ b/libraries/networking/src/udt/SendQueue.cpp @@ -30,6 +30,8 @@ #include "PacketList.h" #include "../UserActivityLogger.h" #include "Socket.h" +#include +#include using namespace udt; using namespace std::chrono; @@ -84,6 +86,7 @@ SendQueue::SendQueue(Socket* socket, HifiSockAddr dest) : _socket(socket), _destination(dest) { + PROFILE_ASYNC_BEGIN(networking, "SendQueue", _destination.toString()); // setup psuedo-random number generation for all instances of SendQueue static std::random_device rd; @@ -102,6 +105,10 @@ SendQueue::SendQueue(Socket* socket, HifiSockAddr dest) : _lastReceiverResponse = QDateTime::currentMSecsSinceEpoch(); } +SendQueue::~SendQueue() { + PROFILE_ASYNC_END(networking, "SendQueue", _destination.toString()); +} + void SendQueue::queuePacket(std::unique_ptr packet) { _packets.queuePacket(std::move(packet)); @@ -220,6 +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()); handshakePacket->writePrimitive(_initialSequenceNumber); _socket->writeBasePacket(*handshakePacket, _destination); @@ -236,6 +244,7 @@ void SendQueue::handshakeACK(SequenceNumber initialSequenceNumber) { std::lock_guard locker { _handshakeMutex }; _hasReceivedHandshakeACK = true; } + PROFILE_ASYNC_END(networking, "SendQueue:Handshake", _destination.toString()); // Notify on the handshake ACK condition _handshakeACKCondition.notify_one(); diff --git a/libraries/networking/src/udt/SendQueue.h b/libraries/networking/src/udt/SendQueue.h index 6e17c5b9c6..484afcb88e 100644 --- a/libraries/networking/src/udt/SendQueue.h +++ b/libraries/networking/src/udt/SendQueue.h @@ -51,6 +51,8 @@ public: }; static std::unique_ptr create(Socket* socket, HifiSockAddr destination); + + virtual ~SendQueue(); void queuePacket(std::unique_ptr packet); void queuePacketList(std::unique_ptr packetList); diff --git a/libraries/networking/src/udt/Socket.cpp b/libraries/networking/src/udt/Socket.cpp index d2583dce72..ae75e0fade 100644 --- a/libraries/networking/src/udt/Socket.cpp +++ b/libraries/networking/src/udt/Socket.cpp @@ -26,6 +26,7 @@ #include "../NLPacket.h" #include "../NLPacketList.h" #include "PacketList.h" +#include using namespace udt; diff --git a/libraries/octree/src/OctreeElement.cpp b/libraries/octree/src/OctreeElement.cpp index 48f6e08303..4eb59d0494 100644 --- a/libraries/octree/src/OctreeElement.cpp +++ b/libraries/octree/src/OctreeElement.cpp @@ -16,6 +16,8 @@ #include +#include + #include #include #include @@ -28,6 +30,7 @@ #include "OctreeLogging.h" #include "OctreeUtils.h" #include "SharedUtil.h" +#include AtomicUIntStat OctreeElement::_octreeMemoryUsage { 0 }; AtomicUIntStat OctreeElement::_octcodeMemoryUsage { 0 }; @@ -389,6 +392,7 @@ 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 872aac974e..908fccaaf6 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("DeferredLighting"); + PROFILE_RANGE(renderlogging, "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 6e1f57778b..77a3830599 100644 --- a/libraries/render-utils/src/Model.cpp +++ b/libraries/render-utils/src/Model.cpp @@ -27,6 +27,7 @@ #include "Model.h" #include "RenderUtilsLogging.h" +#include using namespace std; @@ -280,7 +281,7 @@ void Model::reset() { } bool Model::updateGeometry() { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(renderutils, __FUNCTION__); bool needFullUpdate = false; if (!isLoaded()) { @@ -474,7 +475,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(__FUNCTION__); + PROFILE_RANGE(renderutils, __FUNCTION__); bool calculatedMeshTrianglesNeeded = pickAgainstTriangles && !_calculatedMeshTrianglesValid; if (!_calculatedMeshBoxesValid || calculatedMeshTrianglesNeeded || (!_calculatedMeshPartBoxesValid && pickAgainstTriangles) ) { @@ -967,7 +968,7 @@ Blender::Blender(ModelPointer model, int blendNumber, const Geometry::WeakPointe } void Blender::run() { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE_EX(renderutils, __FUNCTION__, 0xFFFF0000, 0, { { "url", _model->getURL().toString() } }); QVector vertices, normals; if (_model) { int offset = 0; @@ -1088,7 +1089,7 @@ void Model::snapToRegistrationPoint() { } void Model::simulate(float deltaTime, bool fullUpdate) { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(renderutils, __FUNCTION__); fullUpdate = updateGeometry() || fullUpdate || (_scaleToFit && !_scaledToFit) || (_snapModelToRegistrationPoint && !_snappedToRegistrationPoint); diff --git a/libraries/render/src/render/Logging.cpp b/libraries/render/src/render/Logging.cpp new file mode 100644 index 0000000000..eaa777096c --- /dev/null +++ b/libraries/render/src/render/Logging.cpp @@ -0,0 +1,11 @@ +// +// Created by Bradley Austin Davis on 2016-12-14 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#include "Logging.h" + +Q_LOGGING_CATEGORY(renderlogging, "hifi.render") diff --git a/libraries/render/src/render/Logging.h b/libraries/render/src/render/Logging.h new file mode 100644 index 0000000000..e9fdd8a3c5 --- /dev/null +++ b/libraries/render/src/render/Logging.h @@ -0,0 +1,16 @@ +// +// Created by Bradley Austin Davis on 2016-12-14 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#ifndef hifi_render_Logging_h +#define hifi_render_Logging_h + +#include + +Q_DECLARE_LOGGING_CATEGORY(renderlogging) + +#endif // hifi_render_Engine_h diff --git a/libraries/render/src/render/Scene.cpp b/libraries/render/src/render/Scene.cpp index 6bc42ac656..3cb9de7b77 100644 --- a/libraries/render/src/render/Scene.cpp +++ b/libraries/render/src/render/Scene.cpp @@ -11,7 +11,8 @@ #include "Scene.h" #include -#include "gpu/Batch.h" +#include +#include "Logging.h" using namespace render; @@ -77,7 +78,7 @@ void consolidateChangeQueue(PendingChangesQueue& queue, PendingChanges& singleBa } void Scene::processPendingChangesQueue() { - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(renderlogging, __FUNCTION__); _changeQueueMutex.lock(); PendingChanges consolidatedPendingChanges; consolidateChangeQueue(_changeQueue, consolidatedPendingChanges); diff --git a/libraries/render/src/render/Task.h b/libraries/render/src/render/Task.h index 16315de523..067dc290d4 100644 --- a/libraries/render/src/render/Task.h +++ b/libraries/render/src/render/Task.h @@ -23,6 +23,7 @@ #include "SettingHandle.h" #include "Context.h" +#include "Logging.h" #include "gpu/Batch.h" #include @@ -571,7 +572,7 @@ public: void run(const SceneContextPointer& sceneContext, const RenderContextPointer& renderContext) { PerformanceTimer perfTimer(_name.c_str()); - PROFILE_RANGE(_name.c_str()); + PROFILE_RANGE(renderlogging, _name.c_str()); auto start = usecTimestampNow(); _concept->run(sceneContext, renderContext); diff --git a/libraries/shared/CMakeLists.txt b/libraries/shared/CMakeLists.txt index f9b835df5c..1fefda06b3 100644 --- a/libraries/shared/CMakeLists.txt +++ b/libraries/shared/CMakeLists.txt @@ -3,6 +3,8 @@ set(TARGET_NAME shared) # TODO: there isn't really a good reason to have Script linked here - let's get what is requiring it out (RegisteredMetaTypes.cpp) setup_hifi_library(Gui Network Script Widgets) +target_include_directories(${TARGET_NAME} PRIVATE "${CMAKE_BINARY_DIR}/includes") + if (WIN32) target_link_libraries(${TARGET_NAME} Wbemuuid.lib) endif() diff --git a/libraries/shared/src/Profile.cpp b/libraries/shared/src/Profile.cpp new file mode 100644 index 0000000000..18e273a6bb --- /dev/null +++ b/libraries/shared/src/Profile.cpp @@ -0,0 +1,72 @@ +// +// Created by Ryan Huffman on 2016-12-14 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#include "Profile.h" + + +#if defined(NSIGHT_FOUND) +#include "nvToolsExt.h" +#define NSIGHT_TRACING +#endif + +Duration::Duration(const QLoggingCategory& category, const QString& name, uint32_t argbColor, uint64_t payload, QVariantMap args) : _name(name), _category(category) { + if (_category.isDebugEnabled()) { + args["nv_payload"] = QVariant::fromValue(payload); + tracing::traceEvent(_category, _name, tracing::DurationBegin, "", args); + +#if defined(NSIGHT_TRACING) + nvtxEventAttributes_t eventAttrib { 0 }; + eventAttrib.version = NVTX_VERSION; + eventAttrib.size = NVTX_EVENT_ATTRIB_STRUCT_SIZE; + eventAttrib.colorType = NVTX_COLOR_ARGB; + eventAttrib.color = argbColor; + eventAttrib.messageType = NVTX_MESSAGE_TYPE_ASCII; + eventAttrib.message.ascii = name.toUtf8().data(); + eventAttrib.payload.llValue = payload; + eventAttrib.payloadType = NVTX_PAYLOAD_TYPE_UNSIGNED_INT64; + + nvtxRangePushEx(&eventAttrib); +#endif + } +} + +Duration::~Duration() { + if (_category.isDebugEnabled()) { + tracing::traceEvent(_category, _name, tracing::DurationEnd); +#ifdef NSIGHT_TRACING + nvtxRangePop(); +#endif + } +} + +// FIXME +uint64_t Duration::beginRange(const QLoggingCategory& category, const char* name, uint32_t argbColor) { +#ifdef NSIGHT_TRACING + if (category.isDebugEnabled()) { + nvtxEventAttributes_t eventAttrib = { 0 }; + eventAttrib.version = NVTX_VERSION; + eventAttrib.size = NVTX_EVENT_ATTRIB_STRUCT_SIZE; + eventAttrib.colorType = NVTX_COLOR_ARGB; + eventAttrib.color = argbColor; + eventAttrib.messageType = NVTX_MESSAGE_TYPE_ASCII; + eventAttrib.message.ascii = name; + return nvtxRangeStartEx(&eventAttrib); + } +#endif + return 0; +} + +// FIXME +void Duration::endRange(const QLoggingCategory& category, uint64_t rangeId) { +#ifdef NSIGHT_TRACING + if (category.isDebugEnabled()) { + nvtxRangeEnd(rangeId); + } +#endif +} + diff --git a/libraries/shared/src/Profile.h b/libraries/shared/src/Profile.h new file mode 100644 index 0000000000..a89b19e7c6 --- /dev/null +++ b/libraries/shared/src/Profile.h @@ -0,0 +1,63 @@ +// +// Created by Ryan Huffman on 2016-12-14 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// +#pragma once + +#ifndef HIFI_PROFILE_ +#define HIFI_PROFILE_ + +#include "Trace.h" + +class Duration { +public: + Duration(const QLoggingCategory& category, const QString& name, uint32_t argbColor = 0xff0000ff, uint64_t payload = 0, QVariantMap args = QVariantMap()); + ~Duration(); + + static uint64_t beginRange(const QLoggingCategory& category, const char* name, uint32_t argbColor); + static void endRange(const QLoggingCategory& category, uint64_t rangeId); + +private: + QString _name; + const QLoggingCategory& _category; +}; + +inline void asyncBegin(const QLoggingCategory& category, const QString& name, const QString& id, const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap()) { + if (category.isDebugEnabled()) { + tracing::traceEvent(category, name, tracing::AsyncNestableStart, id, args, extra); + } +} + + +inline void asyncEnd(const QLoggingCategory& category, const QString& name, const QString& id, const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap()) { + if (category.isDebugEnabled()) { + tracing::traceEvent(category, name, tracing::AsyncNestableEnd, id, args, extra); + } +} + +inline void instant(const QLoggingCategory& category, const QString& name, const QString& scope = "t", const QVariantMap& args = QVariantMap(), QVariantMap extra = QVariantMap()) { + if (category.isDebugEnabled()) { + extra["s"] = scope; + tracing::traceEvent(category, name, tracing::Instant, "", args, extra); + } +} + +inline void counter(const QLoggingCategory& category, const QString& name, const QVariantMap& args, const QVariantMap& extra = QVariantMap()) { + if (category.isDebugEnabled()) { + tracing::traceEvent(category, name, tracing::Counter, "", args, extra); + } +} + +#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__); + +#endif diff --git a/libraries/shared/src/StatTracker.cpp b/libraries/shared/src/StatTracker.cpp new file mode 100644 index 0000000000..4ec4e31797 --- /dev/null +++ b/libraries/shared/src/StatTracker.cpp @@ -0,0 +1,34 @@ +// +// Created by Ryan Huffman on 2016-12-14 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#include "StatTracker.h" + +StatTracker::StatTracker() { + +} + +QVariant StatTracker::getStat(QString name) { + std::lock_guard lock(_statsLock); + return _stats[name]; +} + +void StatTracker::editStat(QString name, EditStatFunction fn) { + std::lock_guard lock(_statsLock); + _stats[name] = fn(_stats[name]); +} + +void StatTracker::incrementStat(QString name) { + std::lock_guard lock(_statsLock); + QVariant stat = _stats[name]; + _stats[name] = _stats[name].toInt() + 1; +} + +void StatTracker::decrementStat(QString name) { + std::lock_guard lock(_statsLock); + _stats[name] = _stats[name].toInt() - 1; +} \ No newline at end of file diff --git a/libraries/shared/src/StatTracker.h b/libraries/shared/src/StatTracker.h new file mode 100644 index 0000000000..1cdfa8f507 --- /dev/null +++ b/libraries/shared/src/StatTracker.h @@ -0,0 +1,45 @@ +// +// Created by Ryan Huffman on 2016-12-14 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#pragma once + +#include +#include +#include +#include +#include "DependencyManager.h" +#include "Trace.h" + +using EditStatFunction = std::function; + +class StatTracker : public Dependency { +public: + StatTracker(); + QVariant getStat(QString name); + void editStat(QString name, EditStatFunction fn); + void incrementStat(QString name); + void decrementStat(QString name); +private: + std::mutex _statsLock; + QVariantMap _stats; +}; + +class CounterStat { +public: + CounterStat(QString name) : _name(name) { + DependencyManager::get()->incrementStat(_name); + //trace::COUNTER("processing", "stats", { + //{ "active", DependencyManager::get()->getStat("ResourceProcessing").toInt() } + //}); + } + ~CounterStat() { + DependencyManager::get()->decrementStat(_name); + } +private: + QString _name; +}; \ No newline at end of file diff --git a/libraries/shared/src/Trace.cpp b/libraries/shared/src/Trace.cpp new file mode 100644 index 0000000000..0e2b2f213c --- /dev/null +++ b/libraries/shared/src/Trace.cpp @@ -0,0 +1,205 @@ +// +// Created by Ryan Huffman on 2016-12-14 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#include "Trace.h" + +#include + +#include +#include +#include + +#include +#include +#include +#include +#include + +#include +#include + +#include + +#include "Gzip.h" +#include "PortableHighResolutionClock.h" +#include "shared/GlobalAppProperties.h" + +using namespace tracing; + +bool tracing::enabled() { + return DependencyManager::get()->isEnabled(); +} + +void Tracer::startTracing() { + std::lock_guard guard(_eventsMutex); + if (_enabled) { + qWarning() << "Tried to enable tracer, but already enabled"; + return; + } + + _events.clear(); + _enabled = true; +} + +void Tracer::stopTracing() { + std::lock_guard guard(_eventsMutex); + if (!_enabled) { + qWarning() << "Cannot stop tracing, already disabled"; + return; + } + _enabled = false; +} + +void TraceEvent::writeJson(QTextStream& out) const { +#if 0 + // FIXME QJsonObject serialization is very slow, so we should be using manual JSON serialization + out << "{"; + out << "\"name\":\"" << name << "\","; + out << "\"cat\":\"" << category.categoryName() << "\","; + out << "\"ph\":\"" << QString(type) << "\","; + out << "\"ts\":\"" << timestamp << "\","; + out << "\"pid\":\"" << processID << "\","; + out << "\"tid\":\"" << threadID << "\""; + //if (!extra.empty()) { + // auto it = extra.begin(); + // for (; it != extra.end(); it++) { + // ev[it.key()] = QJsonValue::fromVariant(it.value()); + // } + //} + //if (!args.empty()) { + // out << ",\"args\":' + //} + out << '}'; +#else + QJsonObject ev { + { "name", QJsonValue(name) }, + { "cat", category.categoryName() }, + { "ph", QString(type) }, + { "ts", timestamp }, + { "pid", processID }, + { "tid", threadID } + }; + if (!id.isEmpty()) { + ev["id"] = id; + } + if (!args.empty()) { + ev["args"] = QJsonObject::fromVariantMap(args); + } + if (!extra.empty()) { + auto it = extra.begin(); + for (; it != extra.end(); it++) { + ev[it.key()] = QJsonValue::fromVariant(it.value()); + } + } + out << QJsonDocument(ev).toJson(QJsonDocument::Compact); +#endif +} + +void Tracer::serialize(const QString& path) { + std::list currentEvents; + { + std::lock_guard guard(_eventsMutex); + currentEvents.swap(_events); + } + + // If the file exists and we can't remove it, fail early + if (QFileInfo(path).exists() && !QFile::remove(path)) { + return; + } + + // If we can't open a temp file for writing, fail early + QByteArray data; + { + QTextStream out(&data); + out << "[\n"; + bool first = true; + for (const auto& event : currentEvents) { + if (first) { + first = false; + } else { + out << ",\n"; + } + event.writeJson(out); + } + out << "\n]"; + } + + if (path.endsWith(".gz")) { + QByteArray compressed; + gzip(data, compressed); + data = compressed; + } + + { + QFile file(path); + if (!file.open(QIODevice::WriteOnly)) { + return; + } + file.write(data); + file.close(); + } + +#if 0 + QByteArray data; + { + + // "traceEvents":[ + // {"args":{"nv_payload":0},"cat":"hifi.render","name":"render::Scene::processPendingChangesQueue","ph":"B","pid":14796,"tid":21636,"ts":68795933487} + + QJsonArray traceEvents; + + QJsonDocument document { + QJsonObject { + { "traceEvents", traceEvents }, + { "otherData", QJsonObject { + { "version", QString { "High Fidelity Interface v1.0" } +BuildInfo::VERSION } + } } + } + }; + + data = document.toJson(QJsonDocument::Compact); + } +#endif +} + +void Tracer::traceEvent(const QLoggingCategory& category, + const QString& name, EventType type, + qint64 timestamp, qint64 processID, qint64 threadID, + const QString& id, + const QVariantMap& args, const QVariantMap& extra) { + std::lock_guard guard(_eventsMutex); + if (!_enabled) { + return; + } + + _events.push_back({ + id, + name, + type, + timestamp, + processID, + threadID, + category, + args, + extra + }); +} + +void Tracer::traceEvent(const QLoggingCategory& category, + const QString& name, EventType type, const QString& id, + const QVariantMap& args, const QVariantMap& extra) { + if (!_enabled) { + return; + } + + auto timestamp = std::chrono::duration_cast(p_high_resolution_clock::now().time_since_epoch()).count(); + auto processID = QCoreApplication::applicationPid(); + auto threadID = int64_t(QThread::currentThreadId()); + + traceEvent(category, name, type, timestamp, processID, threadID, id, args, extra); +} diff --git a/libraries/shared/src/Trace.h b/libraries/shared/src/Trace.h new file mode 100644 index 0000000000..e075dc24c4 --- /dev/null +++ b/libraries/shared/src/Trace.h @@ -0,0 +1,115 @@ +// +// Created by Ryan Huffman on 2016-12-14 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#pragma once +#ifndef hifi_Trace_h +#define hifi_Trace_h + +#include +#include + +#include +#include +#include +#include +#include + +#include "DependencyManager.h" + +#define TRACE_ENABLED + +namespace tracing { + +bool enabled(); + +using TraceTimestamp = uint64_t; + +enum EventType : char { + DurationBegin = 'B', + DurationEnd = 'E', + + Complete = 'X', + Instant = 'i', + Counter = 'C', + + AsyncNestableStart = 'b', + AsyncNestableInstant = 'n', + AsyncNestableEnd = 'e', + + FlowStart = 's', + FlowStep = 't', + FlowEnd = 'f', + + Sample = 'P', + + ObjectCreated = 'N', + ObjectSnapshot = 'O', + ObjectDestroyed = 'D', + + Metadata = 'M', + + MemoryDumpGlobal = 'V', + MemoryDumpProcess = 'v', + + Mark = 'R', + + ClockSync = 'c', + + ContextEnter = '(', + ContextLeave = ')' +}; + +struct TraceEvent { + QString id; + QString name; + EventType type; + qint64 timestamp; + qint64 processID; + qint64 threadID; + const QLoggingCategory& category; + QVariantMap args; + QVariantMap extra; + + void writeJson(QTextStream& out) const; +}; + +class Tracer : public Dependency { +public: + void traceEvent(const QLoggingCategory& category, + const QString& name, EventType type, + const QString& id = "", + const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap()); + + void startTracing(); + void stopTracing(); + void serialize(const QString& file); + bool isEnabled() const { return _enabled; } + +private: + void traceEvent(const QLoggingCategory& category, + const QString& name, EventType type, + qint64 timestamp, qint64 processID, qint64 threadID, + const QString& id = "", + const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap()); + + bool _enabled { false }; + std::list _events; + std::mutex _eventsMutex; +}; + +inline void traceEvent(const QLoggingCategory& category, const QString& name, EventType type, const QString& id = "", const QVariantMap& args = {}, const QVariantMap& extra = {}) { + DependencyManager::get()->traceEvent(category, name, type, id, args, extra); +} + +inline void traceEvent(const QLoggingCategory& category, const QString& name, EventType type, int id, const QVariantMap& args = {}, const QVariantMap& extra = {}) { + traceEvent(category, name, type, QString::number(id), args, extra); +} + +} + +#endif // hifi_Trace_h diff --git a/libraries/shared/src/shared/GlobalAppProperties.cpp b/libraries/shared/src/shared/GlobalAppProperties.cpp index bfb8f744f1..a8a38457f2 100644 --- a/libraries/shared/src/shared/GlobalAppProperties.cpp +++ b/libraries/shared/src/shared/GlobalAppProperties.cpp @@ -14,6 +14,7 @@ namespace hifi { namespace properties { const char* STEAM = "com.highfidelity.launchedFromSteam"; const char* LOGGER = "com.highfidelity.logger"; const char* TEST = "com.highfidelity.test"; + const char* TRACING = "com.highfidelity.tracing"; namespace gl { const char* BACKEND = "com.highfidelity.gl.backend"; diff --git a/libraries/shared/src/shared/GlobalAppProperties.h b/libraries/shared/src/shared/GlobalAppProperties.h index 4786142a08..92d8388f09 100644 --- a/libraries/shared/src/shared/GlobalAppProperties.h +++ b/libraries/shared/src/shared/GlobalAppProperties.h @@ -16,6 +16,7 @@ namespace hifi { namespace properties { extern const char* STEAM; extern const char* LOGGER; extern const char* TEST; + extern const char* TRACING; namespace gl { extern const char* BACKEND; diff --git a/libraries/shared/src/shared/NsightHelpers.cpp b/libraries/shared/src/shared/NsightHelpers.cpp index fa853029be..6f7408c7c5 100644 --- a/libraries/shared/src/shared/NsightHelpers.cpp +++ b/libraries/shared/src/shared/NsightHelpers.cpp @@ -21,49 +21,6 @@ bool nsightActive() { return nsightLaunched; } - -uint64_t ProfileRange::beginRange(const char* name, uint32_t argbColor) { - nvtxEventAttributes_t eventAttrib = { 0 }; - eventAttrib.version = NVTX_VERSION; - eventAttrib.size = NVTX_EVENT_ATTRIB_STRUCT_SIZE; - eventAttrib.colorType = NVTX_COLOR_ARGB; - eventAttrib.color = argbColor; - eventAttrib.messageType = NVTX_MESSAGE_TYPE_ASCII; - eventAttrib.message.ascii = name; - return nvtxRangeStartEx(&eventAttrib); - // return nvtxRangePushEx(&eventAttrib); -} - -void ProfileRange::endRange(uint64_t rangeId) { - nvtxRangeEnd(rangeId); - // nvtxRangePop(); -} - -ProfileRange::ProfileRange(const char *name) { - // _rangeId = nvtxRangeStart(name); - _rangeId = nvtxRangePush(name); -} - -ProfileRange::ProfileRange(const char *name, uint32_t argbColor, uint64_t payload) { - nvtxEventAttributes_t eventAttrib = {0}; - eventAttrib.version = NVTX_VERSION; - eventAttrib.size = NVTX_EVENT_ATTRIB_STRUCT_SIZE; - eventAttrib.colorType = NVTX_COLOR_ARGB; - eventAttrib.color = argbColor; - eventAttrib.messageType = NVTX_MESSAGE_TYPE_ASCII; - eventAttrib.message.ascii = name; - eventAttrib.payload.llValue = payload; - eventAttrib.payloadType = NVTX_PAYLOAD_TYPE_UNSIGNED_INT64; - - //_rangeId = nvtxRangeStartEx(&eventAttrib); - _rangeId = nvtxRangePushEx(&eventAttrib); -} - -ProfileRange::~ProfileRange() { - // nvtxRangeEnd(_rangeId); - nvtxRangePop(); -} - #else bool nsightActive() { diff --git a/libraries/shared/src/shared/NsightHelpers.h b/libraries/shared/src/shared/NsightHelpers.h index 294ffe0f7d..396d828ff9 100644 --- a/libraries/shared/src/shared/NsightHelpers.h +++ b/libraries/shared/src/shared/NsightHelpers.h @@ -11,35 +11,6 @@ bool nsightActive(); -#if defined(_WIN32) && defined(NSIGHT_FOUND) -#include - -class ProfileRange { -public: - ProfileRange(const char *name); - ProfileRange(const char *name, uint32_t argbColor, uint64_t payload); - ~ProfileRange(); - - static uint64_t beginRange(const char* name, uint32_t argbColor); - static void endRange(uint64_t rangeId); -private: - uint64_t _rangeId{ 0 }; -}; - -#define PROFILE_RANGE(name) ProfileRange profileRangeThis(name); -#define PROFILE_RANGE_EX(name, argbColor, payload) ProfileRange profileRangeThis(name, argbColor, (uint64_t)payload); - -#define PROFILE_RANGE_BEGIN(rangeId, name, argbColor) rangeId = ProfileRange::beginRange(name, argbColor) -#define PROFILE_RANGE_END(rangeId) ProfileRange::endRange(rangeId) - -#else -#define PROFILE_RANGE(name) -#define PROFILE_RANGE_EX(name, argbColor, payload) - - -#define PROFILE_RANGE_BEGIN(rangeId, name, argbColor) -#define PROFILE_RANGE_END(rangeId) - -#endif +#include "../Profile.h" #endif diff --git a/plugins/oculus/src/OculusDisplayPlugin.cpp b/plugins/oculus/src/OculusDisplayPlugin.cpp index d7d734f6a2..5ab9d2f058 100644 --- a/plugins/oculus/src/OculusDisplayPlugin.cpp +++ b/plugins/oculus/src/OculusDisplayPlugin.cpp @@ -110,7 +110,7 @@ void OculusDisplayPlugin::hmdPresent() { return; } - PROFILE_RANGE_EX(__FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) + PROFILE_RANGE_EX(displayplugins, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) int curIndex; ovr_GetTextureSwapChainCurrentIndex(_session, _textureSwapChain, &curIndex); diff --git a/plugins/oculus/src/OculusHelpers.cpp b/plugins/oculus/src/OculusHelpers.cpp index feb0896fa4..a8da2af3e9 100644 --- a/plugins/oculus/src/OculusHelpers.cpp +++ b/plugins/oculus/src/OculusHelpers.cpp @@ -11,7 +11,6 @@ #include #include -#include #include #include #include @@ -20,8 +19,8 @@ #include #include -Q_DECLARE_LOGGING_CATEGORY(oculus) -Q_LOGGING_CATEGORY(oculus, "hifi.plugins.oculus") +Q_LOGGING_CATEGORY(displayplugins, "hifi.plugins.display") +Q_LOGGING_CATEGORY(oculus, "hifi.plugins.display.oculus") static std::atomic refCount { 0 }; static ovrSession session { nullptr }; diff --git a/plugins/oculus/src/OculusHelpers.h b/plugins/oculus/src/OculusHelpers.h index 8244add84e..50ba355b0c 100644 --- a/plugins/oculus/src/OculusHelpers.h +++ b/plugins/oculus/src/OculusHelpers.h @@ -7,6 +7,9 @@ // #pragma once + +#include + #include #include #include @@ -14,6 +17,9 @@ #include +Q_DECLARE_LOGGING_CATEGORY(displayplugins) +Q_DECLARE_LOGGING_CATEGORY(oculus) + void logWarning(const char* what); void logCritical(const char* what); bool oculusAvailable(); diff --git a/plugins/openvr/src/OpenVrDisplayPlugin.cpp b/plugins/openvr/src/OpenVrDisplayPlugin.cpp index bfa61f3b36..5a963db254 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(__FUNCTION__, 0xff7fff00, frameIndex) + PROFILE_RANGE_EX(displayplugins, __FUNCTION__, 0xff7fff00, frameIndex) handleOpenVrEvents(); if (openVrQuitRequested()) { QMetaObject::invokeMethod(qApp, "quit"); @@ -633,7 +633,7 @@ void OpenVrDisplayPlugin::compositeLayers() { } void OpenVrDisplayPlugin::hmdPresent() { - PROFILE_RANGE_EX(__FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) + PROFILE_RANGE_EX(displayplugins, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) if (_threadedSubmit) { _submitThread->waitForPresent(); @@ -654,7 +654,7 @@ void OpenVrDisplayPlugin::hmdPresent() { } void OpenVrDisplayPlugin::postPreview() { - PROFILE_RANGE_EX(__FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) + PROFILE_RANGE_EX(displayplugins, __FUNCTION__, 0xff00ff00, (uint64_t)_currentFrame->frameIndex) PoseData nextRender, nextSim; nextRender.frameIndex = presentCount(); diff --git a/scripts/developer/tests/testTestMode.js b/scripts/developer/tests/testTestMode.js index add106ab72..b535f635e4 100644 --- a/scripts/developer/tests/testTestMode.js +++ b/scripts/developer/tests/testTestMode.js @@ -6,9 +6,19 @@ // See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html // -print("Fooooo"); Script.setTimeout(function() { + var loggingRules = "" + +"*.debug=false\n" + +"hifi.render.debug=true\n" + +"hifi.interface.debug=true\n" + +""; + Test.startTracing(loggingRules); +}, 1 * 1000); + + +Script.setTimeout(function() { + Test.stopTracing("h:/testScriptTrace.json.gz"); Test.quit(); }, 10 * 1000); diff --git a/tests/render-perf/src/main.cpp b/tests/render-perf/src/main.cpp index f52ba78724..0185b1b3cd 100644 --- a/tests/render-perf/src/main.cpp +++ b/tests/render-perf/src/main.cpp @@ -70,6 +70,8 @@ #include "Camera.hpp" +Q_DECLARE_LOGGING_CATEGORY(renderperflogging) +Q_LOGGING_CATEGORY(renderperflogging, "hifi.render_perf") static const QString LAST_SCENE_KEY = "lastSceneFile"; static const QString LAST_LOCATION_KEY = "lastLocation"; @@ -856,7 +858,6 @@ private: EntityUpdateOperator updateOperator(now); //getEntities()->getTree()->recurseTreeWithOperator(&updateOperator); { - PROFILE_RANGE_EX("PreRenderLambdas", 0xffff0000, (uint64_t)0); for (auto& iter : _postUpdateLambdas) { iter.second(); } @@ -899,7 +900,7 @@ private: gpu::doInBatch(gpuContext, [&](gpu::Batch& batch) { batch.resetStages(); }); - PROFILE_RANGE(__FUNCTION__); + PROFILE_RANGE(renderperflogging, __FUNCTION__); PerformanceTimer perfTimer("draw"); // The pending changes collecting the changes here render::PendingChanges pendingChanges; diff --git a/tests/render-texture-load/src/main.cpp b/tests/render-texture-load/src/main.cpp index fb0b16d16c..68f007ce70 100644 --- a/tests/render-texture-load/src/main.cpp +++ b/tests/render-texture-load/src/main.cpp @@ -563,7 +563,6 @@ private: gpu::doInBatch(gpuContext, [&](gpu::Batch& batch) { batch.resetStages(); }); - PROFILE_RANGE(__FUNCTION__); auto framebuffer = DependencyManager::get()->getFramebuffer(); gpu::doInBatch(gpuContext, [&](gpu::Batch& batch) { diff --git a/tests/shared/src/TraceTests.cpp b/tests/shared/src/TraceTests.cpp new file mode 100644 index 0000000000..175cf2cc01 --- /dev/null +++ b/tests/shared/src/TraceTests.cpp @@ -0,0 +1,45 @@ +// +// Created by Bradley Austin Davis on 2016/12/15 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#include "TraceTests.h" + +#include +#include + +#include +#include +#include <../QTestExtensions.h> + +QTEST_MAIN(TraceTests) +Q_LOGGING_CATEGORY(tracertestlogging, "hifi.tracer.test") + +void TraceTests::testTraceSerialization() { + auto tracer = DependencyManager::set(); + tracer->startTracing(); + tracer->traceEvent(tracertestlogging(), "TestEvent", tracing::DurationBegin); + { + auto start = usecTimestampNow(); + for (size_t i = 0; i < 10000; ++i) { + tracer->traceEvent(tracertestlogging(), "TestCounter", tracing::Counter, "", { { "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"); + auto duration = usecTimestampNow() - start; + duration /= USECS_PER_MSEC; + qDebug() << "Serialization took " << duration << "ms"; + } + qDebug() << "Done"; +} + diff --git a/tests/shared/src/TraceTests.h b/tests/shared/src/TraceTests.h new file mode 100644 index 0000000000..c81173d356 --- /dev/null +++ b/tests/shared/src/TraceTests.h @@ -0,0 +1,20 @@ +// +// Created by Bradley Austin Davis on 2016/12/15 +// Copyright 2013-2016 High Fidelity, Inc. +// +// Distributed under the Apache License, Version 2.0. +// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html +// + +#ifndef hifi_TraceTests_h +#define hifi_TraceTests_h + +#include + +class TraceTests : public QObject { + Q_OBJECT +private slots: + void testTraceSerialization(); +}; + +#endif // hifi_TraceTests_h