Support explicit timestamps in tracing, conditional event output based on duration

libraries/shared/src/Profile.cpp

@@ -7,6 +7,7 @@
 //
 
 #include "Profile.h"
+#include <chrono>
 
 Q_LOGGING_CATEGORY(trace_app, "trace.app")
 Q_LOGGING_CATEGORY(trace_app_detail, "trace.app.detail")
@@ -41,14 +42,22 @@ static bool tracingEnabled() {
     return DependencyManager::isSet<tracing::Tracer>() && DependencyManager::get<tracing::Tracer>()->isEnabled();
 }
 
-Duration::Duration(const QLoggingCategory& category, const QString& name, uint32_t argbColor, uint64_t payload, const QVariantMap& baseArgs) : _name(name), _category(category) {
+DurationBase::DurationBase(const QLoggingCategory& category, const QString& name) : _name(name), _category(category) {
+}
+
+Duration::Duration(const QLoggingCategory& category,
+                   const QString& name,
+                   uint32_t argbColor,
+                   uint64_t payload,
+                   const QVariantMap& baseArgs) :
+    DurationBase(category, name) {
     if (tracingEnabled() && category.isDebugEnabled()) {
         QVariantMap args = baseArgs;
         args["nv_payload"] = QVariant::fromValue(payload);
         tracing::traceEvent(_category, _name, tracing::DurationBegin, "", args);
 
 #if defined(NSIGHT_TRACING)
-        nvtxEventAttributes_t eventAttrib { 0 };
+        nvtxEventAttributes_t eventAttrib{ 0 };
         eventAttrib.version = NVTX_VERSION;
         eventAttrib.size = NVTX_EVENT_ATTRIB_STRUCT_SIZE;
         eventAttrib.colorType = NVTX_COLOR_ARGB;
@@ -98,3 +107,17 @@ void Duration::endRange(const QLoggingCategory& category, uint64_t rangeId) {
 #endif
 }
 
+ConditionalDuration::ConditionalDuration(const QLoggingCategory& category, const QString& name, uint32_t minTime) :
+    DurationBase(category, name), _startTime(tracing::Tracer::now()), _minTime(minTime * USECS_PER_MSEC) {
+}
+
+ConditionalDuration::~ConditionalDuration() {
+    if (tracingEnabled() && _category.isDebugEnabled()) {
+        auto endTime = tracing::Tracer::now();
+        auto duration = endTime - _startTime;
+        if (duration >= _minTime) {
+            tracing::traceEvent(_category, _startTime, _name, tracing::DurationBegin);
+            tracing::traceEvent(_category, endTime, _name, tracing::DurationEnd);
+        }
+    }
+}

libraries/shared/src/Profile.h

@@ -37,17 +37,31 @@ Q_DECLARE_LOGGING_CATEGORY(trace_startup)
 Q_DECLARE_LOGGING_CATEGORY(trace_workload)
 Q_DECLARE_LOGGING_CATEGORY(trace_baker)
 
-class Duration {
+class DurationBase {
+
+protected:
+    DurationBase(const QLoggingCategory& category, const QString& name);
+    const QString _name;
+    const QLoggingCategory& _category;
+};
+
+class Duration : public DurationBase {
 public:
     Duration(const QLoggingCategory& category, const QString& name, uint32_t argbColor = 0xff0000ff, uint64_t payload = 0, const 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);
+};
+
+class ConditionalDuration : public DurationBase {
+public:
+    ConditionalDuration(const QLoggingCategory& category, const QString& name, uint32_t minTime);
+    ~ConditionalDuration();
 
 private:
-    QString _name;
+    const int64_t _startTime;
-    const QLoggingCategory& _category;
+    const int64_t _minTime;
 };
 
 
@@ -95,6 +109,7 @@ inline void metadata(const QString& metadataType, const QVariantMap& args) {
 }
 
 #define PROFILE_RANGE(category, name) Duration profileRangeThis(trace_##category(), name);
+#define PROFILE_RANGE_IF_LONGER(category, name, ms) ConditionalDuration profileRangeThis(trace_##category(), name, ms);
 #define PROFILE_RANGE_EX(category, name, argbColor, payload, ...) Duration profileRangeThis(trace_##category(), name, argbColor, (uint64_t)payload, ##__VA_ARGS__);
 #define PROFILE_RANGE_BEGIN(category, rangeId, name, argbColor) rangeId = Duration::beginRange(trace_##category(), name, argbColor)
 #define PROFILE_RANGE_END(category, rangeId) Duration::endRange(trace_##category(), rangeId)

libraries/shared/src/Trace.cpp

@@ -176,6 +176,10 @@ void Tracer::serialize(const QString& filename) {
 #endif
 }
 
+int64_t Tracer::now() {
+    return std::chrono::duration_cast<std::chrono::microseconds>(p_high_resolution_clock::now().time_since_epoch()).count();
+}
+
 void Tracer::traceEvent(const QLoggingCategory& category,
     const QString& name, EventType type,
     qint64 timestamp, qint64 processID, qint64 threadID,
@@ -226,9 +230,17 @@ void Tracer::traceEvent(const QLoggingCategory& category,
         return;
     }
 
-    auto timestamp = std::chrono::duration_cast<std::chrono::microseconds>(p_high_resolution_clock::now().time_since_epoch()).count();
+    traceEvent(category, name, type, now(), id, args, extra);
+}
+
+void Tracer::traceEvent(const QLoggingCategory& category, 
+    const QString& name, EventType type, int64_t timestamp, const QString& id, 
+    const QVariantMap& args, const QVariantMap& extra) {
+    if (!_enabled && type != Metadata) {
+        return;
+    }
+
     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

@@ -78,11 +78,18 @@ struct TraceEvent {
 
 class Tracer : public Dependency {
 public:
+    static int64_t now();
     void traceEvent(const QLoggingCategory& category, 
         const QString& name, EventType type,
         const QString& id = "", 
         const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap());
 
+    void traceEvent(const QLoggingCategory& category, 
+        const QString& name, EventType type,
+        int64_t timestamp,
+        const QString& id = "", 
+        const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap());
+
     void startTracing();
     void stopTracing();
     void serialize(const QString& file);
@@ -101,6 +108,16 @@ private:
     std::mutex _eventsMutex;
 };
 
+inline void traceEvent(const QLoggingCategory& category, int64_t timestamp, const QString& name, EventType type, const QString& id = "", const QVariantMap& args = {}, const QVariantMap& extra = {}) {
+    if (!DependencyManager::isSet<Tracer>()) {
+        return;
+    }
+    const auto& tracer = DependencyManager::get<Tracer>();
+    if (tracer) {
+        tracer->traceEvent(category, name, type, timestamp, id, args, extra);
+    }
+}
+
 inline void traceEvent(const QLoggingCategory& category, const QString& name, EventType type, const QString& id = "", const QVariantMap& args = {}, const QVariantMap& extra = {}) {
     if (!DependencyManager::isSet<Tracer>()) {
         return;