Tracing: added some details for db operations

src/libs/core/bench/TraceLoggerBench.cpp

@@ -39,6 +39,14 @@ namespace lms::core
         }
     }
 
+    static void BM_TraceLogger_Overview_withArg(benchmark::State& state)
+    {
+        for (auto _ : state)
+        {
+            LMS_SCOPED_TRACE_OVERVIEW_WITH_ARG("Cat", "Test", "ArgType", "My arg that can be very very long, and even as long as needed");
+        }
+    }
+
     static void BM_TraceLogger_Detailed(benchmark::State& state)
     {
         for (auto _ : state)
@@ -48,8 +56,26 @@ namespace lms::core
         }
     }
 
+    static void BM_TraceLogger_Detailed_withArg(benchmark::State& state)
+    {
+        auto someExpensiveArgComputation{ []() -> std::string
+        {
+            std::this_thread::sleep_for(std::chrono::microseconds{ 1 });
+            return "foo";
+        } };
+
+        for (auto _ : state)
+        {
+            // Should do nothing (and cost nothing)
+            LMS_SCOPED_TRACE_DETAILED_WITH_ARG("Cat", "Test", "ArgType", someExpensiveArgComputation());
+        }
+    }
+
     BENCHMARK(BM_TraceLogger_Overview)->Threads(1)->Threads(std::thread::hardware_concurrency());
+    BENCHMARK(BM_TraceLogger_Overview_withArg)->Threads(1)->Threads(std::thread::hardware_concurrency());
     BENCHMARK(BM_TraceLogger_Detailed)->Threads(1)->Threads(std::thread::hardware_concurrency());
+    BENCHMARK(BM_TraceLogger_Detailed_withArg)->Threads(1)->Threads(std::thread::hardware_concurrency());
+
 }
 
 BENCHMARK_MAIN();

src/libs/core/impl/TraceLogger.cpp

@@ -20,6 +20,7 @@
 #include "TraceLogger.hpp"
 
 #include <iomanip>
+#include <iostream>
 #include <memory>
 #include <string>
 #include "core/Exception.hpp"
@@ -68,7 +69,7 @@ namespace lms::core::tracing
         for (Buffer& buffer : _buffers)
             _freeBuffers.push_back(&buffer);
 
-        LMS_LOG(UTILS, INFO, "TraceLogger: using " << _buffers.size() << " buffers. Buffer size = " << std::to_string(BufferSize));
+        LMS_LOG(UTILS, INFO, "TraceLogger: using " << _buffers.size() << " buffers. Buffer size = " << std::to_string(BufferSize) << ", entry size = " << sizeof(CompleteEvent) << ", entry count per buffer = " << Buffer::CompleteEventCount);
     }
 
     bool TraceLogger::isLevelActive(Level level) const
@@ -110,6 +111,7 @@ namespace lms::core::tracing
 
         // Empty new buffer only now (we want to keep history on released buffers since we dump them)
         buffer->currentDurationIndex = 0;
+        buffer->threadId = std::this_thread::get_id();
         return buffer;
     }
 
@@ -154,6 +156,8 @@ namespace lms::core::tracing
 
             for (Buffer& buffer : _buffers)
             {
+                const auto threadId{ toTraceThreadId(buffer.threadId) };
+
                 for (std::size_t i{}; i < buffer.currentDurationIndex; ++i)
                 {
                     // Looks like tracing viewer is not pleased when nested event start at the same timestamp
@@ -171,10 +175,23 @@ namespace lms::core::tracing
                     os << "\"name\" : \"" << event.name.c_str() << "\", ";
                     os << "\"cat\" : \"" << event.category.c_str() << "\", ";
                     os << "\"pid\": 1, ";
-                    os << "\"tid\" : " << toTraceThreadId(event.threadId) << ", ";
+                    os << "\"tid\" : " << threadId << ", ";
                     os << "\"ts\" : " << std::fixed << std::setprecision(3) << std::chrono::duration_cast<clockMicro>(event.start - _start).count() << ", ";
                     os << "\"dur\" : " << std::fixed << std::setprecision(3) << std::chrono::duration_cast<clockMicro>(event.duration).count() << ", ";
                     os << "\"ph\" : \"X\"";
+                    if (event.arg.has_value())
+                    {
+                        ArgEntryMap::const_iterator itArgEntry;
+                        {
+                            std::shared_lock lock{ _argMutex };
+                            itArgEntry = _argEntries.find(*event.arg);
+                            assert(itArgEntry != _argEntries.cend());
+                        }
+
+                        os << ", \"args\" : { \"" << itArgEntry->second.type.c_str() << "\" : \"";
+                        stringUtils::writeJSEscapedString(os, std::string_view{ itArgEntry->second.value });
+                        os << "\" }";
+                    }
                     os << " }";
                 }
             }
@@ -199,14 +216,48 @@ namespace lms::core::tracing
         _threadNames.emplace(id, threadName);
     }
 
-    std::uint32_t TraceLogger::toTraceThreadId(std::thread::id threadId) const
+    TraceLogger::ArgHashType TraceLogger::computeArgHash(LiteralString type, std::string_view value)
     {
+        ArgHashType res{};
+        res ^= std::hash<std::string_view>{}(type.str());
+        res ^= std::hash<std::string_view>{}(value);
+        return res;
+    }
+
+    TraceLogger::ArgHashType TraceLogger::registerArg(LiteralString argType, std::string_view argValue)
+    {
+        const ArgHashType hash{ computeArgHash(argType, argValue) };
+
         {
-            auto it{ _cachedTraceThreadIds.find(threadId) };
-            if (it != std::cend(_cachedTraceThreadIds))
-            return it->second;
+            const std::shared_lock lock{ _argMutex };
+
+            auto itArgEntry{ _argEntries.find(hash) };
+            if (itArgEntry != std::cend(_argEntries))
+            {
+                assert(itArgEntry->second.type == argType);
+                assert(itArgEntry->second.value == argValue);
+                return hash;
+            }
         }
 
+        {
+            const std::unique_lock lock{ _argMutex };
+
+            auto itArgEntry{ _argEntries.find(hash) };
+            if (itArgEntry != std::cend(_argEntries))
+            {
+                assert(itArgEntry->second.type == argType);
+                assert(itArgEntry->second.value == argValue);
+                return hash;
+            }
+
+            _argEntries.emplace(hash, ArgEntry{ argType, std::string{ argValue } });
+            return hash;
+        }
+    }
+
+    std::uint32_t TraceLogger::toTraceThreadId(std::thread::id threadId)
+    {
         // Pefetto UI does not accept 64bits thread ids
         std::ostringstream oss;
         oss << threadId;
@@ -215,8 +266,6 @@ namespace lms::core::tracing
         std::uint64_t id;
         iss >> id;
 
-        const std::uint32_t res{ static_cast<std::uint32_t>(id) };
-        _cachedTraceThreadIds.emplace(threadId, res);
-        return res;
+        return static_cast<std::uint32_t>(id);
     }
 }

src/libs/core/impl/TraceLogger.hpp

@@ -22,9 +22,10 @@
 #include <array>
 #include <deque>
 #include <mutex>
-#include <vector>
+#include <shared_mutex>
 #include <thread>
 #include <unordered_map>
+#include <vector>
 
 #include "core/ITraceLogger.hpp"
 
@@ -42,14 +43,18 @@ namespace lms::core::tracing
         void write(const CompleteEvent& event) override;
         void dumpCurrentBuffer(std::ostream& os) override;
         void setThreadName(std::thread::id id, std::string_view threadName) override;
-        std::uint32_t toTraceThreadId(std::thread::id threadId) const;
+        ArgHashType registerArg(LiteralString argType, std::string_view argValue) override;
 
-        static constexpr std::size_t BufferSize{ 32 * 1024 };
+        static ArgHashType computeArgHash(LiteralString type, std::string_view value);
+        static std::uint32_t toTraceThreadId(std::thread::id threadId);
+
+        static constexpr std::size_t BufferSize{ 64 * 1024 };
 
         struct alignas(64) Buffer
         {
             static constexpr std::size_t CompleteEventCount{ BufferSize / sizeof(CompleteEvent) };
 
+            std::thread::id threadId;
             std::array<CompleteEvent, CompleteEventCount> durationEvents;
             std::atomic<std::size_t> currentDurationIndex{};
         };
@@ -63,9 +68,17 @@ namespace lms::core::tracing
 
         std::vector<Buffer> _buffers; // allocated once during construction
 
+        std::shared_mutex _argMutex;
+        struct ArgEntry
+        {
+            LiteralString type;
+            std::string value;
+        };
+        using ArgEntryMap = std::unordered_map<ArgHashType, ArgEntry>;
+        ArgEntryMap _argEntries; // collisions not handled
+
         std::mutex _threadNameMutex;
         std::unordered_map<std::thread::id, std::string> _threadNames;
-        mutable std::unordered_map<std::thread::id, std::uint32_t> _cachedTraceThreadIds;
 
         std::mutex _mutex;
         std::deque<Buffer*> _freeBuffers;

src/libs/core/include/core/ITraceLogger.hpp

@@ -21,6 +21,7 @@
 
 #include <chrono>
 #include <memory>
+#include <optional>
 #include <ostream>
 #include <string_view>
 #include <thread>
@@ -34,14 +35,19 @@
 #define LMS_CONCAT(x, y) LMS_CONCAT_IMPL(x, y)
 
 #if LMS_SUPPORT_TRACING 
-#define LMS_SCOPED_TRACE(CATEGORY, LEVEL, NAME) ::lms::core::tracing::ScopedTrace LMS_CONCAT(ScopedTrace_, __LINE__){ CATEGORY, LEVEL, NAME }
-
+#define LMS_SCOPED_TRACE(CATEGORY, LEVEL, NAME, ARGTYPE, ARGVALUE) \
+std::optional<::lms::core::tracing::ScopedTrace> LMS_CONCAT(ScopedTrace_, __LINE__); \
+if (::lms::core::tracing::ITraceLogger* traceLogger{ ::lms::core::Service<::lms::core::tracing::ITraceLogger>::get() }; traceLogger && traceLogger->isLevelActive(LEVEL)) \
+    LMS_CONCAT(ScopedTrace_, __LINE__).emplace(CATEGORY, LEVEL, NAME, ARGTYPE, ARGVALUE, traceLogger);
 #else
 #define LMS_SCOPED_TRACE(CATEGORY, LEVEL, NAME)      (void)0
 #endif
 
-#define LMS_SCOPED_TRACE_OVERVIEW(CATEGORY, NAME)   LMS_SCOPED_TRACE(CATEGORY, ::lms::core::tracing::Level::Overview, NAME)
-#define LMS_SCOPED_TRACE_DETAILED(CATEGORY, NAME)   LMS_SCOPED_TRACE(CATEGORY, ::lms::core::tracing::Level::Detailed, NAME)
+#define LMS_SCOPED_TRACE_OVERVIEW_WITH_ARG(CATEGORY, NAME, ARGTYPE, ARGVALUE)   LMS_SCOPED_TRACE(CATEGORY, ::lms::core::tracing::Level::Overview, NAME, ARGTYPE, ARGVALUE)
+#define LMS_SCOPED_TRACE_DETAILED_WITH_ARG(CATEGORY, NAME, ARGTYPE, ARGVALUE)   LMS_SCOPED_TRACE(CATEGORY, ::lms::core::tracing::Level::Detailed, NAME, ARGTYPE, ARGVALUE)
+
+#define LMS_SCOPED_TRACE_OVERVIEW(CATEGORY, NAME)   LMS_SCOPED_TRACE_OVERVIEW_WITH_ARG(CATEGORY, NAME, "", "")
+#define LMS_SCOPED_TRACE_DETAILED(CATEGORY, NAME)   LMS_SCOPED_TRACE_DETAILED_WITH_ARG(CATEGORY, NAME, "", "")
 
 namespace lms::core::tracing
 {
@@ -56,13 +62,15 @@ namespace lms::core::tracing
     class ITraceLogger
     {
     public:
+        using ArgHashType = std::size_t;
+
         struct CompleteEvent
         {
             clock::time_point start;
             clock::duration duration;
-            std::thread::id threadId;
             LiteralString name;
             LiteralString category;
+            std::optional<ArgHashType> arg;
         };
 
         virtual ~ITraceLogger() = default;
@@ -71,6 +79,8 @@ namespace lms::core::tracing
         virtual void write(const CompleteEvent& entry) = 0;
         virtual void dumpCurrentBuffer(std::ostream& os) = 0;
         virtual void setThreadName(std::thread::id id, std::string_view threadName) = 0;
+
+        virtual ArgHashType registerArg(LiteralString argType, std::string_view argValue) = 0;
     };
 
     static constexpr std::size_t MinBufferSizeInMBytes = 16;
@@ -79,16 +89,17 @@ namespace lms::core::tracing
     class ScopedTrace
     {
     public:
-        ScopedTrace(LiteralString category, Level level, LiteralString name, ITraceLogger* traceLogger = Service<ITraceLogger>::get())
+        ScopedTrace(LiteralString category, Level level, LiteralString name, LiteralString argType = {}, std::string_view argValue = {}, ITraceLogger* traceLogger = Service<ITraceLogger>::get())
         {
             if (traceLogger && traceLogger->isLevelActive(level))
             {
                 _traceLogger = traceLogger;
 
                 _event.start = clock::now();
-                _event.threadId = std::this_thread::get_id();
                 _event.name = name;
                 _event.category = category;
+                if (!argType.empty() && !argValue.empty())
+                    _event.arg = traceLogger->registerArg(argType, argValue);
             }
             else
             {

src/libs/core/include/core/LiteralString.hpp

@@ -32,6 +32,7 @@ namespace lms::core
         template<std::size_t N>
         constexpr LiteralString(const char(&str)[N]) noexcept : _str{ str, N - 1 } { static_assert(N > 0); }
 
+        constexpr bool empty() const noexcept { return _str.empty(); }
         constexpr const char* c_str() const noexcept { return _str.data(); }
         constexpr std::size_t length() const noexcept { return _str.length(); }
         constexpr std::string_view str() const noexcept { return _str; }

src/libs/core/test/TraceLogger.cpp

@@ -35,8 +35,8 @@ namespace lms::core::tracing::tests
         {
             threads.emplace_back([&]
                 {
-                    ScopedTrace loggedEvent{ "MyCategory", Level::Overview, "MyEventLogged", traceLogger.get() };
-                    ScopedTrace notLoggedEvent{ "MyCategory", Level::Detailed, "MyEventNotLogged", traceLogger.get() };
+                    ScopedTrace loggedEvent{ "MyCategory", Level::Overview, "MyEventLogged", "SomeArgType", "SomeArg", traceLogger.get() };
+                    ScopedTrace notLoggedEvent{ "MyNotLoggedCategory", Level::Detailed, "MyEventNotLogged", "SomeNotLoggedArgType", "SomeNotLoggedArg", traceLogger.get() };
                 });
         }
 
@@ -47,6 +47,13 @@ namespace lms::core::tracing::tests
         traceLogger->dumpCurrentBuffer(oss);
 
         EXPECT_NE(oss.str().find("MyEventLogged"), std::string::npos);
+        EXPECT_NE(oss.str().find("MyCategory"), std::string::npos);
+        EXPECT_NE(oss.str().find("SomeArgType"), std::string::npos);
+        EXPECT_NE(oss.str().find("SomeArg"), std::string::npos);
+
         EXPECT_EQ(oss.str().find("MyEventNotLogged"), std::string::npos);
+        EXPECT_EQ(oss.str().find("MyNotLoggedCategory"), std::string::npos);
+        EXPECT_EQ(oss.str().find("SomeNotLoggedArgType"), std::string::npos);
+        EXPECT_EQ(oss.str().find("SomeNotLoggedArg"), std::string::npos);
     }
 }

src/libs/database/impl/Artist.cpp

@@ -205,6 +205,7 @@ namespace lms::db
 
         for (auto itResult{ collection.begin() }; itResult != collection.end(); ++itResult)
         {
+            LMS_SCOPED_TRACE_DETAILED("Database", "ExecQueryRangeForEach");
             func(*itResult);
             lastRetrievedArtist = (*itResult)->getId();
         }

src/libs/database/impl/Release.cpp

@@ -301,9 +301,9 @@ namespace lms::db
         }
 
         auto collection{ utils::execMultiResultQuery(query) };
-
         for (auto itResult{ collection.begin() }; itResult != collection.end(); ++itResult)
         {
+            LMS_SCOPED_TRACE_DETAILED("Database", "ExecQueryRangeForEach");
             func(*itResult);
             lastRetrievedRelease = (*itResult)->getId();
         }

src/libs/database/impl/Track.cpp

@@ -243,6 +243,7 @@ namespace lms::db
 
         for (auto itResult{ collection.begin() }; itResult != collection.end(); ++itResult)
         {
+            LMS_SCOPED_TRACE_DETAILED("Database", "ExecQueryRangeForEach");
             func(*itResult);
             lastRetrievedTrack = (*itResult)->getId();
         }

src/libs/database/impl/Utils.hpp

@@ -48,14 +48,14 @@ namespace lms::db::utils
     template <typename Query>
     auto execSingleResultQuery(const Query& query)
     {
-        LMS_SCOPED_TRACE_DETAILED("Database", "ExecSingleResultQuery");
+        LMS_SCOPED_TRACE_DETAILED_WITH_ARG("Database", "ExecSingleResultQuery", "Query", query.asString());
         return query.resultValue();
     }
 
     template <typename Query>
     auto execMultiResultQuery(const Query& query)
     {
-        LMS_SCOPED_TRACE_DETAILED("Database", "ExecMultiResultQuery");
+        LMS_SCOPED_TRACE_DETAILED_WITH_ARG("Database", "ExecMultiResultQuery", "Query", query.asString());
         return query.resultList();
     }