From a3c53e160969a17e2f9a33700115406eeedb1585 Mon Sep 17 00:00:00 2001 From: emeric Date: Sun, 31 Mar 2024 23:35:12 +0200 Subject: [PATCH] Tracing: added some details for db operations --- src/libs/core/bench/TraceLoggerBench.cpp | 26 ++++++++ src/libs/core/impl/TraceLogger.cpp | 67 +++++++++++++++++--- src/libs/core/impl/TraceLogger.hpp | 21 ++++-- src/libs/core/include/core/ITraceLogger.hpp | 25 ++++++-- src/libs/core/include/core/LiteralString.hpp | 1 + src/libs/core/test/TraceLogger.cpp | 11 +++- src/libs/database/impl/Artist.cpp | 1 + src/libs/database/impl/Release.cpp | 2 +- src/libs/database/impl/Track.cpp | 1 + src/libs/database/impl/Utils.hpp | 4 +- 10 files changed, 134 insertions(+), 25 deletions(-) diff --git a/src/libs/core/bench/TraceLoggerBench.cpp b/src/libs/core/bench/TraceLoggerBench.cpp index 7c037c0e..34652885 100644 --- a/src/libs/core/bench/TraceLoggerBench.cpp +++ b/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(); \ No newline at end of file diff --git a/src/libs/core/impl/TraceLogger.cpp b/src/libs/core/impl/TraceLogger.cpp index 614713ae..ca56c82b 100644 --- a/src/libs/core/impl/TraceLogger.cpp +++ b/src/libs/core/impl/TraceLogger.cpp @@ -20,6 +20,7 @@ #include "TraceLogger.hpp" #include +#include #include #include #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(event.start - _start).count() << ", "; os << "\"dur\" : " << std::fixed << std::setprecision(3) << std::chrono::duration_cast(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{}(type.str()); + res ^= std::hash{}(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(id) }; - _cachedTraceThreadIds.emplace(threadId, res); - return res; + return static_cast(id); } } \ No newline at end of file diff --git a/src/libs/core/impl/TraceLogger.hpp b/src/libs/core/impl/TraceLogger.hpp index 17e0cea7..ee81090b 100644 --- a/src/libs/core/impl/TraceLogger.hpp +++ b/src/libs/core/impl/TraceLogger.hpp @@ -22,9 +22,10 @@ #include #include #include -#include +#include #include #include +#include #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 durationEvents; std::atomic currentDurationIndex{}; }; @@ -63,9 +68,17 @@ namespace lms::core::tracing std::vector _buffers; // allocated once during construction + std::shared_mutex _argMutex; + struct ArgEntry + { + LiteralString type; + std::string value; + }; + using ArgEntryMap = std::unordered_map; + ArgEntryMap _argEntries; // collisions not handled + std::mutex _threadNameMutex; std::unordered_map _threadNames; - mutable std::unordered_map _cachedTraceThreadIds; std::mutex _mutex; std::deque _freeBuffers; diff --git a/src/libs/core/include/core/ITraceLogger.hpp b/src/libs/core/include/core/ITraceLogger.hpp index 89479dba..dcf87a80 100644 --- a/src/libs/core/include/core/ITraceLogger.hpp +++ b/src/libs/core/include/core/ITraceLogger.hpp @@ -21,6 +21,7 @@ #include #include +#include #include #include #include @@ -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 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::get()) + ScopedTrace(LiteralString category, Level level, LiteralString name, LiteralString argType = {}, std::string_view argValue = {}, ITraceLogger* traceLogger = Service::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 { diff --git a/src/libs/core/include/core/LiteralString.hpp b/src/libs/core/include/core/LiteralString.hpp index 63bda2c1..7c0394bd 100644 --- a/src/libs/core/include/core/LiteralString.hpp +++ b/src/libs/core/include/core/LiteralString.hpp @@ -32,6 +32,7 @@ namespace lms::core template 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; } diff --git a/src/libs/core/test/TraceLogger.cpp b/src/libs/core/test/TraceLogger.cpp index 6d7f1beb..fcee9ea2 100644 --- a/src/libs/core/test/TraceLogger.cpp +++ b/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); } } \ No newline at end of file diff --git a/src/libs/database/impl/Artist.cpp b/src/libs/database/impl/Artist.cpp index b5479f60..001ca984 100644 --- a/src/libs/database/impl/Artist.cpp +++ b/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(); } diff --git a/src/libs/database/impl/Release.cpp b/src/libs/database/impl/Release.cpp index 986caa40..8e3088d8 100644 --- a/src/libs/database/impl/Release.cpp +++ b/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(); } diff --git a/src/libs/database/impl/Track.cpp b/src/libs/database/impl/Track.cpp index 68266d89..b1140ea8 100644 --- a/src/libs/database/impl/Track.cpp +++ b/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(); } diff --git a/src/libs/database/impl/Utils.hpp b/src/libs/database/impl/Utils.hpp index 9604884f..dbd0b6a7 100644 --- a/src/libs/database/impl/Utils.hpp +++ b/src/libs/database/impl/Utils.hpp @@ -48,14 +48,14 @@ namespace lms::db::utils template 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 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(); }