Add chrome tracing support

assignment-client/src/AssignmentClient.cpp

@@ -37,6 +37,7 @@
 #include "AssignmentClient.h"
 #include "AssignmentClientLogging.h"
 #include "avatars/ScriptableAvatar.h"
+#include <Trace.h>
 
 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<tracing::Tracer>();
     DependencyManager::set<AccountManager>();
 
     auto scriptableAvatar = DependencyManager::set<ScriptableAvatar>();

domain-server/src/DomainServer.cpp

@@ -43,6 +43,7 @@
 
 #include "DomainServerNodeData.h"
 #include "NodeConnectionData.h"
+#include <Trace.h>
 
 int const DomainServer::EXIT_CODE_REBOOT = 234923;
 
@@ -73,6 +74,8 @@ DomainServer::DomainServer(int argc, char* argv[]) :
 {
     parseCommandLine();
 
+    DependencyManager::set<tracing::Tracer>();
+
     LogUtils::init();
     Setting::init();
 

interface/src/Application.cpp

@@ -47,6 +47,8 @@
 #include <gl/QOpenGLContextWrapper.h>
 
 #include <shared/GlobalAppProperties.h>
+#include <StatTracker.h>
+#include <Trace.h>
 #include <ResourceScriptingInterface.h>
 #include <AccountManager.h>
 #include <AddressManager.h>
@@ -428,6 +430,8 @@ bool setupEssentials(int& argc, char** argv) {
         steamClient->init();
     }
 
+    DependencyManager::set<tracing::Tracer>();
+
 #if defined(Q_OS_WIN)
     // Select appropriate audio DLL
     QString audioDLLPath = QCoreApplication::applicationDirPath();
@@ -450,6 +454,7 @@ bool setupEssentials(int& argc, char** argv) {
 
     // Set dependencies
     DependencyManager::set<AccountManager>(std::bind(&Application::getUserAgent, qApp));
+    DependencyManager::set<StatTracker>();
     DependencyManager::set<ScriptEngines>();
     DependencyManager::set<Preferences>();
     DependencyManager::set<recording::Deck>();
@@ -563,6 +568,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) {
@@ -570,6 +576,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<tracing::Tracer>()->startTracing();
             }
         }
     }
@@ -1630,6 +1640,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<tracing::Tracer>();
+        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<DdeFaceTracker>()->setEnabled(false);
@@ -1986,6 +2003,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<StatTracker>()->getStat("Processing") },
+        { "pending", DependencyManager::get<StatTracker>()->getStat("PendingProcessing") }
+    });
+
     // Some plugins process message events, allowing paintGL to be called reentrantly.
     if (_inPaint || _aboutToQuit) {
         return;
@@ -1997,7 +2024,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) {
@@ -2174,7 +2201,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
@@ -2229,7 +2256,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);
@@ -2317,7 +2344,7 @@ void Application::resizeEvent(QResizeEvent* event) {
 }
 
 void Application::resizeGL() {
-    PROFILE_RANGE(__FUNCTION__);
+    PROFILE_RANGE(interfaceapp, __FUNCTION__);
     if (nullptr == _displayPlugin) {
         return;
     }
@@ -2372,7 +2399,6 @@ bool Application::importSVOFromURL(const QString& urlString) {
 }
 
 bool Application::event(QEvent* event) {
-
     if (!Menu::getInstance()) {
         return false;
     }
@@ -2986,7 +3012,7 @@ void Application::maybeToggleMenuVisible(QMouseEvent* event) const {
 }
 
 void Application::mouseMoveEvent(QMouseEvent* event) {
-    PROFILE_RANGE(__FUNCTION__);
+    PROFILE_RANGE(interfaceapp, __FUNCTION__);
 
     if (_aboutToQuit) {
         return;
@@ -3294,7 +3320,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();
@@ -4059,9 +4085,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()");
@@ -4069,6 +4097,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();
@@ -4098,6 +4131,9 @@ void Application::update(float deltaTime) {
                 }
             }
         }
+    } else if (domainLoadingInProgress) {
+        domainLoadingInProgress = false;
+        PROFILE_ASYNC_END(interfaceapp, "Scene Loading", "");
     }
 
     {
@@ -4191,12 +4227,12 @@ void Application::update(float deltaTime) {
     QSharedPointer<AvatarManager> avatarManager = DependencyManager::get<AvatarManager>();
 
     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;
@@ -4230,14 +4266,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([&] {
@@ -4279,20 +4315,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);
     }
@@ -4312,7 +4348,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;
@@ -4352,7 +4388,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<std::mutex> guard(_postUpdateLambdasLock);
         for (auto& iter : _postUpdateLambdas) {
@@ -4630,7 +4666,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());
 
@@ -4806,7 +4842,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()");
 

interface/src/scripting/TestScriptingInterface.cpp

@@ -10,6 +10,10 @@
 #include "TestScriptingInterface.h"
 
 #include <QtCore/QCoreApplication>
+#include <QtCore/QLoggingCategory>
+
+#include <DependencyManager.h>
+#include <Trace.h>
 
 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<tracing::Tracer>()) {
+        return false;
+    }
+
+    DependencyManager::get<tracing::Tracer>()->startTracing();
+    return true;
+}
+
+bool TestScriptingInterface::stopTracing(QString filename) {
+    if (!DependencyManager::isSet<tracing::Tracer>()) {
+        return false;
+    }
+
+    auto tracer = DependencyManager::get<tracing::Tracer>();
+    tracer->stopTracing();
+    tracer->serialize(filename);
+    return true;
+}

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

interface/src/ui/ApplicationOverlay.cpp

@@ -29,6 +29,7 @@
 #include "ui/Stats.h"
 #include "ui/AvatarInputs.h"
 #include "OffscreenUi.h"
+#include "InterfaceLogging.h"
 #include <QQmlContext>
 
 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<GeometryCache>();
@@ -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<GeometryCache>();
@@ -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()) {

interface/src/ui/overlays/Overlays.cpp

@@ -19,6 +19,7 @@
 #include <RegisteredMetaTypes.h>
 
 #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;
 

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<IKTarget> 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

libraries/animation/src/AnimationCache.cpp

@@ -14,6 +14,9 @@
 
 #include "AnimationCache.h"
 #include "AnimationLogging.h"
+#include <Trace.h>
+#include <StatTracker.h>
+#include <Profile.h>
 
 int animationPointerMetaTypeId = qRegisterMetaType<AnimationPointer>();
 
@@ -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<StatTracker>()->incrementStat("PendingProcessing");
 }
 
 void AnimationReader::run() {
+    DependencyManager::get<StatTracker>()->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;

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;

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);
 

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

@@ -16,7 +16,6 @@
 
 #include <QtOpenGL/QGLWidget>
 #include <QtGui/QImage>
-
 #if defined(Q_OS_MAC)
 #include <OpenGL/CGLCurrent.h>
 #endif
@@ -44,6 +43,7 @@
 #include <CursorManager.h>
 
 #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<CompositorHelper>();
     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();
         }
 

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();

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);
             }
         }

libraries/entities/src/EntityTree.cpp

@@ -24,6 +24,7 @@
 #include "EntitiesLogging.h"
 #include "RecurseOctreeToMapOperator.h"
 #include "LogHandler.h"
+#include <Trace.h>
 
 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

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) {

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);
 

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")

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;
     }

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

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();
     }

libraries/gpu-gl/src/gpu/gl41/GL41BackendTexture.cpp

@@ -12,7 +12,6 @@
 
 #include <unordered_set>
 #include <unordered_map>
-#include <QtCore/QThread>
 
 #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);

libraries/gpu/src/gpu/Texture.cpp

@@ -17,6 +17,7 @@
 
 #include <QtCore/QDebug>
 #include <QtCore/QThread>
+#include <Trace.h>
 
 #include <NumericalConstants.h>
 
@@ -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();

libraries/model-networking/src/model-networking/ModelCache.cpp

@@ -21,6 +21,8 @@
 #include <QThreadPool>
 
 #include "ModelNetworkingLogging.h"
+#include <Trace.h>
+#include <StatTracker.h>
 
 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>& resource, const QUrl& url, const QVariantHash& mapping,
         const QByteArray& data) :
-        _resource(resource), _url(url), _mapping(mapping), _data(data) {}
+        _resource(resource), _url(url), _mapping(mapping), _data(data) {
-    virtual ~GeometryReader() = default;
+
+        DependencyManager::get<StatTracker>()->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<StatTracker>()->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:

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;

libraries/model-networking/src/model-networking/TextureCache.cpp

@@ -33,6 +33,8 @@
 #include <PathUtils.h>
 
 #include "ModelNetworkingLogging.h"
+#include <Trace.h>
+#include <StatTracker.h>
 
 TextureCache::TextureCache() {
     setUnusedResourceCacheSize(0);
@@ -331,6 +333,7 @@ ImageReader::ImageReader(const QWeakPointer<Resource>& resource, const QByteArra
         outFile.close();
     }
 #endif
+    DependencyManager::get<StatTracker>()->incrementStat("PendingProcessing");
 }
 
 void ImageReader::listSupportedImageFormats() {
@@ -342,7 +345,12 @@ void ImageReader::listSupportedImageFormats() {
 }
 
 void ImageReader::run() {
-    PROFILE_RANGE_EX(__FUNCTION__, 0xffff0000, nullptr);
+    DependencyManager::get<StatTracker>()->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<NetworkTexture>()->getTextureLoader()(image, url));
     }
 

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;
 

libraries/model/src/model/TextureMap.cpp

@@ -14,6 +14,8 @@
 #include <QPainter>
 #include <QDebug>
 
+#include <Profile.h>
+
 #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();
             }
         }

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) {

libraries/networking/src/AssetRequest.cpp

@@ -19,8 +19,12 @@
 #include "NetworkLogging.h"
 #include "NodeList.h"
 #include "ResourceCache.h"
+#include <Trace.h>
+
+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<AssetClient>();
     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<AssetClient>();
     _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) {

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;

libraries/networking/src/AssetResourceRequest.cpp

@@ -17,6 +17,8 @@
 #include "AssetUtils.h"
 #include "MappingRequest.h"
 #include "NetworkLogging.h"
+#include <Trace.h>
+#include <Profile.h>
 
 static const int DOWNLOAD_PROGRESS_LOG_INTERVAL_SECONDS = 5;
 
@@ -27,12 +29,18 @@ AssetResourceRequest::AssetResourceRequest(const QUrl& url) :
 }
 
 AssetResourceRequest::~AssetResourceRequest() {
+    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<AssetClient>();
     _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<AssetClient>();
@@ -119,6 +136,8 @@ void AssetResourceRequest::requestHash(const AssetHash& hash) {
         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:
                 _data = req->getData();
@@ -143,6 +162,8 @@ void AssetResourceRequest::requestHash(const AssetHash& hash) {
 
         _assetRequest->deleteLater();
         _assetRequest = nullptr;
+
+        //trace::ASYNC_END("AssetResourceRequest", trace::cResource, _url.toString());
     });
 
     _assetRequest->start();

libraries/networking/src/Assignment.cpp

@@ -19,6 +19,7 @@
 #include <BuildInfo.h>
 #include "Assignment.h"
 #include <QtCore/QStandardPaths>
+#include <QtCore/QDir>
 
 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

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);

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();

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);

libraries/networking/src/LimitedNodeList.cpp

@@ -37,6 +37,7 @@
 #include "HifiSockAddr.h"
 #include "NetworkLogging.h"
 #include "udt/Packet.h"
+#include <Trace.h>
 
 static Setting::Handle<quint16> 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);
 

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);
 

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")

libraries/networking/src/NetworkLogging.h

@@ -14,6 +14,7 @@
 
 #include <QLoggingCategory>
 
+Q_DECLARE_LOGGING_CATEGORY(resourceLog)
 Q_DECLARE_LOGGING_CATEGORY(networking)
 Q_DECLARE_LOGGING_CATEGORY(asset_client)
 Q_DECLARE_LOGGING_CATEGORY(messages_client)

libraries/networking/src/NetworkPeer.cpp

@@ -20,6 +20,8 @@
 
 #include "BandwidthRecorder.h"
 #include "NetworkLogging.h"
+#include <Trace.h>
+#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();

libraries/networking/src/NodeList.cpp

@@ -32,6 +32,7 @@
 #include "NetworkLogging.h"
 #include "udt/PacketHeaders.h"
 #include "SharedUtil.h"
+#include <Trace.h>
 
 const int KEEPALIVE_PING_INTERVAL_MS = 1000;
 

libraries/networking/src/ResourceCache.cpp

@@ -23,6 +23,8 @@
 #include "NodeList.h"
 
 #include "ResourceCache.h"
+#include <Trace.h>
+#include <Profile.h>
 
 #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()) {

libraries/networking/src/ResourceCache.h

@@ -343,6 +343,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 };

libraries/networking/src/udt/Connection.cpp

@@ -23,6 +23,7 @@
 #include "Packet.h"
 #include "PacketList.h"
 #include "Socket.h"
+#include <Trace.h>
 
 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) {

libraries/networking/src/udt/Connection.h

@@ -58,7 +58,7 @@ public:
     using ControlPacketPointer = std::unique_ptr<ControlPacket>;
     
     Connection(Socket* parentSocket, HifiSockAddr destination, std::unique_ptr<CongestionControl> congestionControl);
-    ~Connection();
+    virtual ~Connection();
 
     void sendReliablePacket(std::unique_ptr<Packet> packet);
     void sendReliablePacketList(std::unique_ptr<PacketList> packet);

libraries/networking/src/udt/SendQueue.cpp

@@ -30,6 +30,8 @@
 #include "PacketList.h"
 #include "../UserActivityLogger.h"
 #include "Socket.h"
+#include <Trace.h>
+#include <Profile.h>
 
 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> 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<std::mutex> locker { _handshakeMutex };
             _hasReceivedHandshakeACK = true;
         }
+        PROFILE_ASYNC_END(networking, "SendQueue:Handshake", _destination.toString());
 
         // Notify on the handshake ACK condition
         _handshakeACKCondition.notify_one();

libraries/networking/src/udt/SendQueue.h

@@ -52,6 +52,8 @@ public:
     
     static std::unique_ptr<SendQueue> create(Socket* socket, HifiSockAddr destination);
 
+    virtual ~SendQueue();
+    
     void queuePacket(std::unique_ptr<Packet> packet);
     void queuePacketList(std::unique_ptr<PacketList> packetList);
 

libraries/networking/src/udt/Socket.cpp

@@ -26,6 +26,7 @@
 #include "../NLPacket.h"
 #include "../NLPacketList.h"
 #include "PacketList.h"
+#include <Trace.h>
 
 using namespace udt;
 

libraries/octree/src/OctreeElement.cpp

@@ -16,6 +16,8 @@
 
 #include <QtCore/QDebug>
 
+#include <Profile.h>
+
 #include <LogHandler.h>
 #include <NodeList.h>
 #include <PerfStat.h>
@@ -28,6 +30,7 @@
 #include "OctreeLogging.h"
 #include "OctreeUtils.h"
 #include "SharedUtil.h"
+#include <Trace.h>
 
 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;
 }

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();

libraries/render-utils/src/Model.cpp

@@ -27,6 +27,7 @@
 #include "Model.h"
 
 #include "RenderUtilsLogging.h"
+#include <Trace.h>
 
 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<glm::vec3> 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);
 

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")

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 <QLoggingCategory>
+
+Q_DECLARE_LOGGING_CATEGORY(renderlogging)
+
+#endif // hifi_render_Engine_h

libraries/render/src/render/Scene.cpp

@@ -11,7 +11,8 @@
 #include "Scene.h"
 
 #include <numeric>
-#include "gpu/Batch.h"
+#include <gpu/Batch.h>
+#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);

libraries/render/src/render/Task.h

@@ -23,6 +23,7 @@
 #include "SettingHandle.h"
 
 #include "Context.h"
+#include "Logging.h"
 
 #include "gpu/Batch.h"
 #include <PerfStat.h>
@@ -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);

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()

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
+}
+

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

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<std::mutex> lock(_statsLock);
+    return _stats[name];
+}
+
+void StatTracker::editStat(QString name, EditStatFunction fn) {
+    std::lock_guard<std::mutex> lock(_statsLock);
+    _stats[name] = fn(_stats[name]);
+}
+
+void StatTracker::incrementStat(QString name) {
+    std::lock_guard<std::mutex> lock(_statsLock);
+    QVariant stat = _stats[name];
+    _stats[name] = _stats[name].toInt() + 1;
+}
+
+void StatTracker::decrementStat(QString name) {
+    std::lock_guard<std::mutex> lock(_statsLock);
+    _stats[name] = _stats[name].toInt() - 1;
+}

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 <QString>
+#include <QVariant>
+#include <QVariantMap>
+#include <mutex>
+#include "DependencyManager.h"
+#include "Trace.h"
+
+using EditStatFunction = std::function<QVariant(QVariant currentValue)>;
+
+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<StatTracker>()->incrementStat(_name);
+        //trace::COUNTER("processing", "stats", {
+            //{ "active", DependencyManager::get<StatTracker>()->getStat("ResourceProcessing").toInt() }
+        //});
+    }    
+    ~CounterStat() {
+        DependencyManager::get<StatTracker>()->decrementStat(_name);
+    }    
+private:
+    QString _name;
+};

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 <chrono>
+
+#include <QtCore/QDebug>
+#include <QtCore/QCoreApplication>
+#include <QtCore/QThread>
+
+#include <QtCore/QFile>
+#include <QtCore/QFileInfo>
+#include <QtCore/QTemporaryFile>
+#include <QtCore/QDataStream>
+#include <QtCore/QTextStream>
+
+#include <QtCore/QJsonObject>
+#include <QtCore/QJsonDocument>
+
+#include <BuildInfo.h>
+
+#include "Gzip.h"
+#include "PortableHighResolutionClock.h"
+#include "shared/GlobalAppProperties.h"
+
+using namespace tracing;
+
+bool tracing::enabled() {
+    return DependencyManager::get<Tracer>()->isEnabled();
+}
+
+void Tracer::startTracing() {
+    std::lock_guard<std::mutex> guard(_eventsMutex);
+    if (_enabled) {
+        qWarning() << "Tried to enable tracer, but already enabled";
+        return;
+    }
+
+    _events.clear();
+    _enabled = true;
+}
+
+void Tracer::stopTracing() {
+    std::lock_guard<std::mutex> 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<TraceEvent> currentEvents;
+    {
+        std::lock_guard<std::mutex> 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<std::mutex> 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<std::chrono::microseconds>(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);
+}

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 <cstdint>
+#include <mutex>
+
+#include <QtCore/QString>
+#include <QtCore/QVariantMap>
+#include <QtCore/QHash>
+#include <QtCore/QSet>
+#include <QtCore/QLoggingCategory>
+
+#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<TraceEvent> _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<Tracer>()->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

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";

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;

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() {

libraries/shared/src/shared/NsightHelpers.h

@@ -11,35 +11,6 @@
 
 bool nsightActive();
 
-#if defined(_WIN32) && defined(NSIGHT_FOUND)
+#include "../Profile.h"
-#include <stdint.h>
-
-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
 
 #endif

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);

plugins/oculus/src/OculusHelpers.cpp

@@ -11,7 +11,6 @@
 #include <atomic>
 
 #include <Windows.h>
-#include <QtCore/QLoggingCategory>
 #include <QtCore/QFile>
 #include <QtCore/QDir>
 #include <QtCore/QProcessEnvironment>
@@ -20,8 +19,8 @@
 #include <controllers/Pose.h>
 #include <NumericalConstants.h>
 
-Q_DECLARE_LOGGING_CATEGORY(oculus)
+Q_LOGGING_CATEGORY(displayplugins, "hifi.plugins.display")
-Q_LOGGING_CATEGORY(oculus, "hifi.plugins.oculus")
+Q_LOGGING_CATEGORY(oculus, "hifi.plugins.display.oculus")
 
 static std::atomic<uint32_t> refCount { 0 };
 static ovrSession session { nullptr };

plugins/oculus/src/OculusHelpers.h

@@ -7,6 +7,9 @@
 //
 #pragma once
 
+
+#include <QtCore/QLoggingCategory>
+
 #include <OVR_CAPI_GL.h>
 #include <GLMHelpers.h>
 #include <glm/gtc/type_ptr.hpp>
@@ -14,6 +17,9 @@
 
 #include <controllers/Forward.h>
 
+Q_DECLARE_LOGGING_CATEGORY(displayplugins)
+Q_DECLARE_LOGGING_CATEGORY(oculus)
+
 void logWarning(const char* what);
 void logCritical(const char* what);
 bool oculusAvailable();

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();
 

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);
 

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;

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<FramebufferCache>()->getFramebuffer();
 
         gpu::doInBatch(gpuContext, [&](gpu::Batch& batch) {

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 <QtTest/QtTest>
+#include <Trace.h>
+
+#include <SharedUtil.h>
+#include <NumericalConstants.h>
+#include <../QTestExtensions.h>
+
+QTEST_MAIN(TraceTests)
+Q_LOGGING_CATEGORY(tracertestlogging, "hifi.tracer.test")
+
+void TraceTests::testTraceSerialization() {
+    auto tracer = DependencyManager::set<tracing::Tracer>();
+    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";
+}
+

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 <QtCore/QObject>
+
+class TraceTests : public QObject {
+    Q_OBJECT
+private slots:
+    void testTraceSerialization();
+};
+
+#endif // hifi_TraceTests_h