From 36cecef1667f0897f802eaf2fdd45ac0c4399e01 Mon Sep 17 00:00:00 2001 From: Brad Davis Date: Tue, 26 Mar 2019 13:31:55 -0700 Subject: [PATCH] Support explicit timestamps in tracing, conditional event output based on duration --- libraries/shared/src/Profile.cpp | 27 +++++++++++++++++++++++++-- libraries/shared/src/Profile.h | 21 ++++++++++++++++++--- libraries/shared/src/Trace.cpp | 16 ++++++++++++++-- libraries/shared/src/Trace.h | 17 +++++++++++++++++ 4 files changed, 74 insertions(+), 7 deletions(-) diff --git a/libraries/shared/src/Profile.cpp b/libraries/shared/src/Profile.cpp index 272538e26d..018636ad5a 100644 --- a/libraries/shared/src/Profile.cpp +++ b/libraries/shared/src/Profile.cpp @@ -7,6 +7,7 @@ // #include "Profile.h" +#include 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() && DependencyManager::get()->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); + } + } +} diff --git a/libraries/shared/src/Profile.h b/libraries/shared/src/Profile.h index dc2ed6e754..e7084b4f79 100644 --- a/libraries/shared/src/Profile.h +++ b/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 QLoggingCategory& _category; + const int64_t _startTime; + 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) diff --git a/libraries/shared/src/Trace.cpp b/libraries/shared/src/Trace.cpp index 3f6a2dd643..e9e77b55ae 100644 --- a/libraries/shared/src/Trace.cpp +++ b/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(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(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); } diff --git a/libraries/shared/src/Trace.h b/libraries/shared/src/Trace.h index 1e1326968f..917530d6ca 100644 --- a/libraries/shared/src/Trace.h +++ b/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()) { + return; + } + const auto& tracer = DependencyManager::get(); + 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()) { return;