Added a simple profiler that uses trace event format

2024-03-09 18:45:00 +01:00
parent 41b944040c
commit f36f176a8b
8 changed files with 467 additions and 0 deletions
@@ -10,6 +10,7 @@ add_library(lmsutils SHARED
 	impl/Logger.cpp
 	impl/NetAddress.cpp
 	impl/Path.cpp
+	impl/Profiler.cpp
 	impl/Random.cpp
 	impl/RecursiveSharedMutex.cpp
 	impl/StreamLogger.cpp
@@ -42,3 +43,7 @@ install(TARGETS lmsutils DESTINATION lib)
 if(BUILD_TESTING)
 	add_subdirectory(test)
 endif()
+
+if (BUILD_BENCHMARKS)
+	add_subdirectory(bench)
+endif()
@@ -0,0 +1,9 @@
+
+add_executable(bench-utils
+	ProfilerBench.cpp
+	)
+
+target_link_libraries(bench-utils PRIVATE
+	lmsutils
+	benchmark
+	)
@@ -0,0 +1,53 @@
+/*
+ * Copyright (C) 2024 Emeric Poupon
+ *
+ * This file is part of LMS.
+ *
+ * LMS is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * LMS is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with LMS.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#include <iostream>
+#include <thread>
+#include <benchmark/benchmark.h>
+
+#include "utils/ILogger.hpp"
+#include "utils/IProfiler.hpp"
+#include "utils/StreamLogger.hpp"
+
+
+// Profiler is meant to built/destroyed once
+Service<ILogger> logger{ std::make_unique<StreamLogger>(std::cout, StreamLogger::allSeverities) };
+Service<profiling::IProfiler> profiler{ profiling::createProfiler(::profiling::Level::Overview) };
+
+static void BM_Profiler_Overview(benchmark::State& state)
+{
+    for (auto _ : state)
+    {
+        LMS_SCOPED_PROFILE_OVERVIEW("Cat", "Test");
+    }
+}
+
+static void BM_Profiler_Detailed(benchmark::State& state)
+{
+    for (auto _ : state)
+    {
+        // Should do nothing
+        LMS_SCOPED_PROFILE_DETAILED("Cat", "Test");
+    }
+}
+
+BENCHMARK(BM_Profiler_Overview)->Threads(1)->Threads(std::thread::hardware_concurrency());
+BENCHMARK(BM_Profiler_Detailed)->Threads(1)->Threads(std::thread::hardware_concurrency());
+
+BENCHMARK_MAIN();
@@ -0,0 +1,166 @@
+/*
+ * Copyright (C) 2024 Emeric Poupon
+ *
+ * This file is part of LMS.
+ *
+ * LMS is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * LMS is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with LMS.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#include "Profiler.hpp"
+
+#include <iomanip>
+#include <memory>
+#include <string>
+#include "utils/Exception.hpp"
+#include "utils/ILogger.hpp"
+
+namespace profiling
+{
+    namespace
+    {
+        class CurrentThreadUnregisterer
+        {
+        public:
+            CurrentThreadUnregisterer(Profiler* profiler) : _profiler{ profiler } {}
+            ~CurrentThreadUnregisterer()
+            {
+                if (_profiler)
+                    _profiler->onThreadPreDestroy();
+            }
+
+        private:
+            CurrentThreadUnregisterer(const CurrentThreadUnregisterer&) = delete;
+            CurrentThreadUnregisterer& operator=(const CurrentThreadUnregisterer&) = delete;
+
+            Profiler* _profiler;
+        };
+    }
+
+    thread_local Profiler::Buffer* Profiler::_currentBuffer{};
+
+    std::unique_ptr<IProfiler> createProfiler(Level minLevel, std::size_t bufferSizeInMbytes)
+    {
+        return std::make_unique<Profiler>(minLevel, bufferSizeInMbytes);
+    }
+
+    Profiler::Profiler(Level minLevel, std::size_t bufferSizeinMBytes)
+        : _minLevel{ minLevel }
+        , _start{ clock::now() }
+        , _creatorThreadId{ std::this_thread::get_id() }
+        , _buffers((bufferSizeinMBytes * 1024 * 1024) / BufferSize)
+    {
+        if (bufferSizeinMBytes < MinBufferSizeInMBytes)
+            throw LmsException{ "Profiler must be configured with at least " + std::to_string(MinBufferSizeInMBytes) + " MBytes" };
+
+        for (Buffer& buffer : _buffers)
+            _freeBuffers.push_back(&buffer);
+
+        LMS_LOG(UTILS, INFO, "Profiler: using " << _buffers.size() << " buffers. Buffer size = " << std::to_string(BufferSize));
+    }
+
+    bool Profiler::isLevelActive(Level level) const
+    {
+        return static_cast<std::underlying_type_t<Level>>(level) <= static_cast<std::underlying_type_t<Level>>(_minLevel);
+    }
+
+    void Profiler::write(const CompleteEvent& event)
+    {
+        if (!_currentBuffer)
+            _currentBuffer = acquireBuffer();
+
+        _currentBuffer->durationEvents[_currentBuffer->currentDurationIndex] = event;
+
+        // update the index after writing the event, in case another thread wants to dump
+        if (++_currentBuffer->currentDurationIndex == _currentBuffer->durationEvents.size())
+        {
+            releaseBuffer(_currentBuffer);
+            _currentBuffer = nullptr;
+        }
+    }
+
+    void Profiler::onThreadPreDestroy()
+    {
+        if (_currentBuffer)
+            releaseBuffer(_currentBuffer);
+    }
+
+    Profiler::Buffer* Profiler::acquireBuffer()
+    {
+        // We consider the creator thread will survive the profiler (thus we don't want to release anything on thread destruction)
+        static thread_local CurrentThreadUnregisterer currentThreadUnregister{ _creatorThreadId == std::this_thread::get_id() ? nullptr : this };
+
+        std::scoped_lock lock{ _mutex };
+        assert(!_freeBuffers.empty());
+
+        Profiler::Buffer* buffer{ _freeBuffers.front() };
+        _freeBuffers.pop_front();
+
+        // Empty new buffer only now (we want to keep history on released buffers since we dump them)
+        buffer->currentDurationIndex = 0;
+        return buffer;
+    }
+
+    void Profiler::releaseBuffer(Buffer* buffer)
+    {
+        assert(buffer);
+
+        std::scoped_lock lock{ _mutex };
+        _freeBuffers.push_back(buffer);
+    }
+
+    void Profiler::dumpCurrentBuffer(std::ostream& os)
+    {
+        os << "{" << std::endl;
+        os << "\t\"traceEvents\": [" << std::endl;
+
+        // we allow threads to fill in their current block while dumping
+        {
+            os << "\t\t{ ";
+            os << "\"name\" : \"thread_name\", ";
+            os << "\"pid\" : 1, ";
+            os << "\"tid\" : " << _creatorThreadId << ", ";
+            os << "\"ph\" : \"M\", ";
+            os << "\"args\" : { \"name\" : \"MainThread\" }";
+            os << " }";
+
+            std::scoped_lock lock{ _mutex };
+
+            for (Buffer& buffer : _buffers)
+            {
+                // Looks like tracing viewer is not pleased when nested event start at the same timestamp
+                for (std::size_t i{}; i < buffer.currentDurationIndex; ++i)
+                {
+                    using clockMicro = std::chrono::duration<double, std::micro>;
+                    const CompleteEvent& event{ buffer.durationEvents[i] };
+
+                    os << "," << std::endl;
+                    os << "\t\t{ ";
+                    os << "\"name\" : \"" << event.name.c_str() << "\", ";
+                    os << "\"cat\" : \"" << event.category.c_str() << "\", ";
+                    os << "\"pid\": 1, ";
+                    os << "\"tid\" : " << event.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\"";
+                    os << " }";
+                }
+            }
+        }
+
+        os << std::endl;
+        os << "\t]," << std::endl;
+        os << "\t\"meta_cpu_count\" : " << std::thread::hardware_concurrency() << std::endl;
+        os << "}" << std::endl;
+    }
+}
@@ -0,0 +1,68 @@
+/*
+ * Copyright (C) 2024 Emeric Poupon
+ *
+ * This file is part of LMS.
+ *
+ * LMS is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * LMS is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with LMS.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#pragma once
+
+#include <array>
+#include <deque>
+#include <mutex>
+#include <vector>
+#include <thread>
+
+#include "utils/IProfiler.hpp"
+
+namespace profiling
+{
+    class Profiler : public IProfiler
+    {
+    public:
+        Profiler(Level minLevel, std::size_t bufferSizeinMBytes);
+
+        void onThreadPreDestroy();
+
+    private:
+        bool isLevelActive(Level level) const override;
+        void write(const CompleteEvent& event) override;
+        void dumpCurrentBuffer(std::ostream& os) override;
+
+        static constexpr std::size_t BufferSize{ 32 * 1024 };
+
+        struct alignas(64) Buffer
+        {
+            static constexpr std::size_t CompleteEventCount{ BufferSize / sizeof(CompleteEvent) };
+
+            std::array<CompleteEvent, CompleteEventCount> durationEvents;
+            std::atomic<std::size_t> currentDurationIndex{};
+        };
+
+        Buffer* acquireBuffer();
+        void releaseBuffer(Buffer* buffer);
+
+        const Level _minLevel;
+        const clock::time_point _start;
+        const std::thread::id _creatorThreadId;
+
+        std::vector<Buffer> _buffers; // allocated once during construction
+
+        std::mutex _mutex;
+        std::deque<Buffer*> _freeBuffers;
+
+        static thread_local Buffer* _currentBuffer;
+    };
+}
@@ -0,0 +1,113 @@
+/*
+ * Copyright (C) 2024 Emeric Poupon
+ *
+ * This file is part of LMS.
+ *
+ * LMS is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * LMS is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with LMS.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#pragma once
+
+#include <chrono>
+#include <memory>
+#include <ostream>
+#include <thread>
+
+#include "LiteralString.hpp"
+#include "Service.hpp"
+
+#define LMS_ENABLE_PROFILING 1
+
+#define LMS_CONCAT_IMPL(x, y) x##y
+#define LMS_CONCAT(x, y) LMS_CONCAT_IMPL(x, y)
+
+#if LMS_ENABLE_PROFILING 
+#define LMS_SCOPED_PROFILE(CATEGORY, LEVEL, NAME) ::profiling::ScopedEvent LMS_CONCAT(scopedEvent_, __LINE__){ CATEGORY, LEVEL, NAME }
+
+#else
+#define LMS_SCOPED_PROFILE(CATEGORY, LEVEL, NAME)      (void)0
+#endif
+
+#define LMS_SCOPED_PROFILE_OVERVIEW(CATEGORY, NAME)   LMS_SCOPED_PROFILE(CATEGORY, ::profiling::Level::Overview, NAME)
+#define LMS_SCOPED_PROFILE_DETAILED(CATEGORY, NAME)   LMS_SCOPED_PROFILE(CATEGORY, ::profiling::Level::Detailed, NAME)
+
+namespace profiling
+{
+    using clock = std::chrono::steady_clock;
+
+    enum class Level
+    {
+        Overview,
+        Detailed,
+    };
+
+    class IProfiler
+    {
+    public:
+        struct CompleteEvent
+        {
+            clock::time_point start;
+            clock::duration duration;
+            std::thread::id threadId;
+            LiteralString name;
+            LiteralString category;
+        };
+
+        virtual ~IProfiler() = default;
+
+        virtual bool isLevelActive(Level level) const = 0;
+        virtual void write(const CompleteEvent& entry) = 0;
+        virtual void dumpCurrentBuffer(std::ostream& os) = 0;
+    };
+
+    static constexpr std::size_t MinBufferSizeInMBytes = 16;
+    std::unique_ptr<IProfiler> createProfiler(Level minLevel = Level::Overview, std::size_t bufferSizeInMbytes = MinBufferSizeInMBytes);
+
+    class ScopedEvent
+    {
+    public:
+        ScopedEvent(LiteralString category, Level level, LiteralString name, IProfiler* profiler = Service<IProfiler>::get())
+        {
+            if (profiler && profiler->isLevelActive(level))
+            {
+                _profiler = profiler;
+
+                _event.start = clock::now();
+                _event.threadId = std::this_thread::get_id();
+                _event.name = name;
+                _event.category = category;
+            }
+            else
+            {
+                _profiler = nullptr;
+            }
+        }
+
+        ~ScopedEvent()
+        {
+            if (_profiler)
+            {
+                _event.duration = clock::now() - _event.start;
+                _profiler->write(_event);
+            }
+        }
+
+    private:
+        ScopedEvent(const ScopedEvent&) = delete;
+        ScopedEvent& operator=(const ScopedEvent&) = delete;
+
+        IProfiler* _profiler;
+        IProfiler::CompleteEvent _event;
+    };
+}
@@ -4,6 +4,7 @@ add_executable(test-utils
 	EnumSet.cpp
 	LiteralString.cpp
 	Path.cpp
+	Profiler.cpp
 	RecursiveSharedMutex.cpp
 	String.cpp
 	Utils.cpp
@@ -0,0 +1,52 @@
+/*
+ * Copyright (C) 2024 Emeric Poupon
+ *
+ * This file is part of LMS.
+ *
+ * LMS is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * LMS is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with LMS.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#include <sstream>
+#include <thread>
+#include <gtest/gtest.h>
+
+#include "utils/IProfiler.hpp"
+
+namespace profiling::tests
+{
+    // not much can be tested with this implementation
+    TEST(Profiler, MultipleThreads)
+    {
+        auto profiler{ createProfiler(Level::Overview) };
+
+        std::vector<std::thread> threads;
+        for (std::size_t i{}; i < 16; ++i)
+        {
+            threads.emplace_back([&]
+                {
+                    ScopedEvent loggedEvent{ "MyCategory", Level::Overview, "MyEventLogged", profiler.get() };
+                    ScopedEvent notLoggedEvent{ "MyCategory", Level::Detailed, "MyEventNotLogged", profiler.get() };
+                });
+        }
+
+        for (std::thread& t : threads)
+            t.join();
+
+        std::ostringstream oss;
+        profiler->dumpCurrentBuffer(oss);
+       
+        EXPECT_NE(oss.str().find("MyEventLogged"), std::string::npos);
+        EXPECT_EQ(oss.str().find("MyEventNotLogged"), std::string::npos);
+    }
+}