added profiler

framework/global/CMakeLists.txt

@@ -22,6 +22,7 @@ set(MODULE global)
 include(${CMAKE_CURRENT_LIST_DIR}/modularity/modularity.cmake)
 include(${CMAKE_CURRENT_LIST_DIR}/async/async.cmake)
 include(${PROJECT_SOURCE_DIR}/thirdparty/haw_logger/logger/logger.cmake)
+include(${PROJECT_SOURCE_DIR}/thirdparty/haw_profiler/src/profiler.cmake)
 
 set(MODULE_DEF
     -DHAW_LOGGER_QT_SUPPORT
@@ -31,6 +32,7 @@ set(MODULE_SRC
     ${MODULARITY_SRC}
     ${ASYNC_SRC}
     ${HAW_LOGGER_SRC}
+    ${HAW_PROFILER_SRC}
     ${CMAKE_CURRENT_LIST_DIR}/globalmodule.cpp
     ${CMAKE_CURRENT_LIST_DIR}/globalmodule.h
     ${CMAKE_CURRENT_LIST_DIR}/iinteractive.h

framework/global/globalmodule.cpp

@@ -80,6 +80,26 @@ void GlobalModule::onInit()
 
     LOGI() << "=== Started MuseScore " << framework::Version::fullVersion() << " ===";
 
+    //! --- Setup profiler ---
+    using namespace haw::profiler;
+    struct MyPrinter : public Profiler::Printer
+    {
+        void printDebug(const std::string& str) override { LOG_STREAM(Logger::DEBUG, "Profiler") << str; }
+        void printInfo(const std::string& str) override { LOG_STREAM(Logger::INFO, "Profiler") << str; }
+    };
+
+    Profiler::Options profOpt;
+    profOpt.stepTimeEnabled = true;
+    profOpt.funcsTimeEnabled = true;
+    profOpt.funcsTraceEnabled = false;
+    profOpt.funcsMaxThreadCount = 100;
+    profOpt.dataTopCount = 150;
+
+    Profiler* profiler = Profiler::instance();
+    profiler->setup(profOpt, new MyPrinter());
+
+    //! --- Setup Invoker ---
+
     Invoker::setup();
 
     mu::async::onMainThreadInvoke([](const std::function<void()>& f) {

framework/global/log.h

@@ -20,6 +20,8 @@
 #ifndef MU_FRAMEWORK_LOG_H
 #define MU_FRAMEWORK_LOG_H
 
+#include "thirdparty/haw_profiler/src/profiler.h"
+
 #ifndef HAW_LOGGER_QT_SUPPORT
 #define HAW_LOGGER_QT_SUPPORT
 #endif

main/main.cpp

@@ -36,8 +36,6 @@
 
 int main(int argc, char** argv)
 {
-    std::cout << "Hello world, I am MuseScore!!\n";
-
     // Force the 8-bit text encoding to UTF-8. This is the default encoding on all supported platforms except for MSVC under Windows, which
     // would otherwise default to the local ANSI code page and cause corruption of any non-ANSI Unicode characters in command-line arguments.
     QTextCodec::setCodecForLocale(QTextCodec::codecForName("UTF-8"));
@@ -89,7 +87,6 @@ int main(int argc, char** argv)
 #ifdef BUILD_UI_MU4
     mu::appshell::AppShell app;
     int code = app.run(argcFinal, argvFinal, moduleSetup);
-    std::cout << "after mu::appshell::AppShell app.run, code: " << code << "\n";
 #else
     int code = Ms::runApplication(argcFinal, argvFinal);
 #endif

main/modulessetup.cpp

@@ -20,6 +20,7 @@
 #include "modulessetup.h"
 #include "config.h"
 #include "runtime.h"
+#include "log.h"
 
 #include "framework/global/globalmodule.h"
 #include "framework/ui/uimodule.h"
@@ -60,19 +61,15 @@
 #include "avsomr/avsomrsetup.h"
 #endif
 
-//---------------------------------------------------------
+//! NOTE Separately to initialize logger and profiler as early as possible
-//   ModulesSetup
+static mu::framework::GlobalModule globalModule;
-//---------------------------------------------------------
 
 ModulesSetup::ModulesSetup()
 {
-    //! NOTE `global module` must be first, because all dependent on it
+    //! NOTE `telemetry` must be first, because it install crash handler.
-    //! `telemetry` must be second, because it install crash handler.
     //! others modules order not important (must be)
 
     m_modulesSetupList
-        << new mu::framework::GlobalModule()
-
 #ifdef BUILD_TELEMETRY_MODULE
         << new mu::telemetry::TelemetrySetup()
 #endif
@@ -122,6 +119,15 @@ void ModulesSetup::setup()
     mu::runtime::mainThreadId(); //! NOTE Needs only call
     mu::runtime::setThreadName("main");
 
+    globalModule.registerResources();
+    globalModule.registerExports();
+    globalModule.registerUiTypes();
+    globalModule.onInit();
+
+    //! NOTE Now we can use logger and profiler
+
+    TRACEFUNC;
+
     for (mu::framework::IModuleSetup* m : m_modulesSetupList) {
         m->registerResources();
     }
@@ -130,6 +136,7 @@ void ModulesSetup::setup()
         m->registerExports();
     }
 
+    globalModule.resolveImports();
     for (mu::framework::IModuleSetup* m : m_modulesSetupList) {
         m->registerUiTypes();
         m->resolveImports();
@@ -140,6 +147,7 @@ void ModulesSetup::setup()
     }
 
     //! NOTE Need to move to the place where the application finishes initializing
+    globalModule.onStartApp();
     for (mu::framework::IModuleSetup* m : m_modulesSetupList) {
         m->onStartApp();
     }
@@ -150,4 +158,8 @@ void ModulesSetup::deinit()
     for (mu::framework::IModuleSetup* m : m_modulesSetupList) {
         m->onDeinit();
     }
+
+    PROFILER_PRINT;
+
+    globalModule.onDeinit();
 }

mu4/appshell/appshell.cpp

@@ -37,7 +37,6 @@ AppShell::AppShell()
 
 int AppShell::run(int argc, char** argv, std::function<void()> moduleSetup)
 {
-    std::cout << "begin AppShell::run\n";
     qputenv("QT_STYLE_OVERRIDE", "Fusion");
     QCoreApplication::setAttribute(Qt::AA_EnableHighDpiScaling);
 

mu4/notation/internal/masternotation.cpp

@@ -59,6 +59,8 @@ Meta MasterNotation::metaInfo() const
 
 mu::Ret MasterNotation::load(const io::path& path)
 {
+    TRACEFUNC;
+
     std::string syffix = io::syffix(path);
 
     //! NOTE For "mscz", "mscx" see MsczNotationReader
@@ -79,6 +81,8 @@ MasterScore* MasterNotation::masterScore() const
 
 mu::Ret MasterNotation::load(const io::path& path, const INotationReaderPtr& reader)
 {
+    TRACEFUNC;
+
     ScoreLoad sl;
 
     MasterScore* score = new MasterScore(scoreGlobal()->baseStyle());

mu4/userscores/internal/filescorecontroller.cpp

@@ -145,6 +145,8 @@ io::path FileScoreController::selectScoreSavingFile(const io::path& defaultFileP
 
 void FileScoreController::doOpenScore(const io::path& filePath)
 {
+    TRACEFUNC;
+
     auto notation = notationCreator()->newMasterNotation();
     IF_ASSERT_FAILED(notation) {
         return;

mu4/userscores/internal/userscoresconfiguration.cpp

@@ -47,6 +47,7 @@ void UserScoresConfiguration::init()
 
 ValCh<QStringList> UserScoresConfiguration::recentScoreList() const
 {
+    TRACEFUNC;
     ValCh<QStringList> result;
     result.ch = m_recentListChanged;
     result.val = parseRecentList(settings()->value(RECENT_LIST).toString());

thirdparty/haw_profiler/.gitignore

@@ -0,0 +1,2 @@
+*.user
+build-*

thirdparty/haw_profiler/LICENSE

@@ -0,0 +1,21 @@
+MIT License
+
+Copyright (c) 2020 Igor Korsukov
+
+Permission is hereby granted, free of charge, to any person obtaining a copy
+of this software and associated documentation files (the "Software"), to deal
+in the Software without restriction, including without limitation the rights
+to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+copies of the Software, and to permit persons to whom the Software is
+furnished to do so, subject to the following conditions:
+
+The above copyright notice and this permission notice shall be included in all
+copies or substantial portions of the Software.
+
+THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+SOFTWARE.

thirdparty/haw_profiler/README.md

@@ -0,0 +1,22 @@
+Simple profiler
+---------------
+Simple, embedded profiler with very small overhead  
+(ported from https://github.com/igorkorsukov/qzebradev)
+  
+Features:
+* Embedded profiler (can run anywhere and anytime)
+* Function duration measure
+* Steps duration measure
+* Very small overhead
+* Enabled / disabled on compile time and run time
+* Thread safe (without use mutex)
+* Custom data printer
+
+[Example](tests/main.cpp)
+
+To use Profiler within your software project include the Profiler source into your project
+
+Source:
+* profiler.h/cpp - profiler and macros
+
+or see and include `src/profiler.cmake` in the cmake project

thirdparty/haw_profiler/src/profiler.cmake

@@ -0,0 +1,9 @@
+
+set(HAW_PROFILER_SRC
+    ${CMAKE_CURRENT_LIST_DIR}/profiler.cpp
+    ${CMAKE_CURRENT_LIST_DIR}/profiler.h
+)
+
+set(HAW_PROFILER_INC
+    ${CMAKE_CURRENT_LIST_DIR}
+)

thirdparty/haw_profiler/src/profiler.cpp

@@ -0,0 +1,572 @@
+#include "profiler.h"
+
+#include <iostream>
+#include <iomanip>
+#include <algorithm>
+
+#include <errno.h>
+#include <stdio.h>
+
+using namespace haw::profiler;
+
+Profiler::Options Profiler::m_options;
+
+constexpr int MAIN_THREAD_INDEX(0);
+
+Profiler::Profiler()
+{
+    setup(Options(), new Printer());
+}
+
+Profiler::~Profiler()
+{
+    delete m_printer;
+}
+
+void Profiler::setup(const Options& opt, Printer* printer)
+{
+    m_options = opt;
+    m_options.funcsMaxThreadCount = m_options.funcsMaxThreadCount < 1 ? 1 : m_options.funcsMaxThreadCount;
+
+    //! Func timers
+    m_funcs.timers.resize(m_options.funcsMaxThreadCount);
+    std::fill(m_funcs.timers.begin(), m_funcs.timers.end(), FuncTimers());
+
+    m_funcs.threads.resize(m_options.funcsMaxThreadCount);
+    std::fill(m_funcs.threads.begin(), m_funcs.threads.end(), std::thread::id());
+    m_funcs.threads[MAIN_THREAD_INDEX] = std::this_thread::get_id();
+
+    if (printer) {
+        delete m_printer;
+        m_printer = printer;
+    }
+}
+
+const Profiler::Options& Profiler::options()
+{
+    return m_options;
+}
+
+Profiler::Printer* Profiler::printer() const
+{
+    return m_printer;
+}
+
+void Profiler::stepTime(const std::string& tag, const std::string& info, bool isRestart)
+{
+    std::lock_guard<std::mutex> lock(m_steps.mutex);
+
+    StepTimer* timer{ nullptr };
+    StepTimers::const_iterator it = m_steps.timers.find(tag);
+    if (it == m_steps.timers.end()) {
+        timer = new StepTimer();
+        timer->start();
+        m_steps.timers.insert({ tag, timer });
+    } else {
+        timer = it->second;
+    }
+
+    if (isRestart) {
+        timer->start();
+    }
+
+    printer()->printStep(tag, timer->beginMs(), timer->stepMs(), info);
+
+    timer->nextStep();
+}
+
+Profiler::FuncTimer* Profiler::beginFunc(const std::string& func)
+{
+    std::thread::id th = std::this_thread::get_id();
+    int idx = m_funcs.threadIndex(th);
+    if (idx == -1) {
+        idx = m_funcs.addThread(th);
+        if (idx == -1) {
+            return nullptr;
+        }
+    }
+    size_t index = static_cast<size_t>(idx);
+
+    FuncTimer* timer{ nullptr };
+    FuncTimers& fts = m_funcs.timers[index];
+    FuncTimers::const_iterator it = fts.find(&func);
+    if (it == fts.end()) {
+        timer = new FuncTimer(func);
+        fts.insert({ &func, timer });
+    } else {
+        timer = it->second;
+        if (timer->timer.isValid()) {
+            //! NOTE Recursion detected, measure only first call
+            //printer()->printDebug(std::string("Recursion detected, measure only first call, func: ") + func);
+            return timer;
+        }
+    }
+
+    timer->timer.start();
+
+    if (m_options.funcsTraceEnabled) {
+        ++m_stackCounter;
+        printer()->printTraceBegin(func, m_stackCounter);
+    }
+
+    return timer;
+}
+
+void Profiler::endFunc(FuncTimer* timer, const std::string& func)
+{
+    if (timer) {
+        if (timer->timer.isValid()) { //! NOTE If not valid then it is probably a recursive call
+            double calltimeMs = timer->timer.mlsecsElapsed();
+
+            timer->callcount++;
+            timer->sumtimeMs += calltimeMs;
+            timer->timer.invalidate();
+
+            if (m_options.funcsTraceEnabled) {
+                printer()->printTraceEnd(func, calltimeMs, timer->callcount, timer->sumtimeMs, m_stackCounter);
+                --m_stackCounter;
+            }
+        }
+    }
+}
+
+const std::string& Profiler::staticInfo(const std::string& info)
+{
+    auto found = m_funcs.staticInfo.find(info);
+    if (found != m_funcs.staticInfo.end()) {
+        return *found;
+    }
+
+    auto ins = m_funcs.staticInfo.insert(info);
+    return *ins.first;
+}
+
+void Profiler::clear()
+{
+    {
+        std::lock_guard<std::mutex> lock(m_funcs.mutex);
+
+        std::thread::id empty;
+        for (size_t i = 0; i < m_funcs.threads.size(); ++i) {
+            FuncTimers timers = m_funcs.timers[i];
+            for (auto ft : timers) {
+                delete ft.second;
+            }
+            m_funcs.timers[i] = FuncTimers();
+            m_funcs.threads[i] = empty;
+        }
+        m_funcs.threads[MAIN_THREAD_INDEX] = std::this_thread::get_id();
+    }
+    {
+        std::lock_guard<std::mutex> lock(m_funcs.mutex);
+        for (auto st : m_steps.timers) {
+            delete st.second;
+        }
+        m_steps.timers.clear();
+    }
+}
+
+Profiler::Data Profiler::threadsData(Data::Mode mode) const
+{
+    Data data;
+    data.mainThread = m_funcs.threads[MAIN_THREAD_INDEX];
+
+    std::thread::id empty;
+    for (size_t i = 0; i < m_funcs.threads.size(); ++i) {
+        std::thread::id th = m_funcs.threads[i];
+        if (th == empty) {
+            break;
+        }
+
+        if (i == MAIN_THREAD_INDEX) {
+            if (mode == Data::OnlyOther) {
+                continue;
+            }
+        } else {
+            if (mode == Data::OnlyMain) {
+                continue;
+            }
+        }
+
+        Data::Thread thdata;
+        thdata.thread = th;
+
+        const FuncTimers& timers = m_funcs.timers[i];
+        for (auto it : timers) {
+            const FuncTimer* ft = it.second;
+            Data::Func f(
+                ft->func,
+                ft->callcount,
+                ft->sumtimeMs
+                );
+
+            thdata.funcs[f.func] = f;
+        }
+
+        data.threads[thdata.thread] = thdata;
+
+        if (i == MAIN_THREAD_INDEX) {
+            if (mode == Data::OnlyMain) {
+                break;
+            }
+        }
+    }
+
+    return data;
+}
+
+std::string Profiler::threadsDataString(Data::Mode mode) const
+{
+    Profiler::Data data = threadsData(mode);
+    return printer()->formatData(data, mode, m_options.dataTopCount);
+}
+
+void Profiler::printThreadsData(Data::Mode mode) const
+{
+    Profiler::Data data = threadsData(mode);
+    printer()->printData(data, mode, m_options.dataTopCount);
+}
+
+void Profiler::print(const std::string& str)
+{
+    Profiler::instance()->printer()->printInfo(str);
+}
+
+bool Profiler::save(const std::string& filePath)
+{
+    std::string content = threadsDataString();
+    bool ok = save_file(filePath, content);
+    return ok;
+}
+
+bool Profiler::save_file(const std::string& path, const std::string& content)
+{
+    FILE* pFile = fopen(path.c_str(), "w");
+    if (!pFile) {
+        return false;
+    }
+    const char* data = content.c_str();
+    size_t count = fwrite(data, sizeof(char), content.size(), pFile);
+    fclose(pFile);
+
+    return count > 0;
+}
+
+std::string FuncMarker::formatSig(const std::string& sig)
+{
+    static const std::string Colon("::");
+    static const std::string Space(" ");
+    static const std::string ArgBegin("(");
+
+    std::size_t endFunc = sig.find_first_of(ArgBegin);
+    if (endFunc == std::string::npos) {
+        return sig;
+    }
+
+    std::size_t beginFunc = sig.find_last_of(Colon, endFunc);
+    if (beginFunc == std::string::npos) {
+        return sig;
+    }
+
+    std::size_t beginClassColon = sig.find_last_of(Colon, beginFunc - 2);
+    std::size_t beginClassSpace = sig.find_last_of(Space, beginFunc - 2);
+
+    std::size_t beginClass = std::string::npos;
+    if (beginClassColon == std::string::npos) {
+        beginClass = beginClassSpace;
+    } else if (beginClassSpace == std::string::npos) {
+        beginClass = beginClassColon;
+    } else {
+        beginClass = std::max(beginClassColon, beginClassSpace);
+    }
+
+    if (beginClass == std::string::npos) {
+        beginClass = beginFunc;
+    } else {
+        beginClass += 1;
+    }
+
+    std::string str = sig.substr(beginClass, (endFunc - beginClass));
+    return str;
+}
+
+double Profiler::StepTimer::beginMs() const
+{
+    return beginTime.mlsecsElapsed();
+}
+
+double Profiler::StepTimer::stepMs() const
+{
+    return stepTime.mlsecsElapsed();
+}
+
+void Profiler::StepTimer::start()
+{
+    beginTime.start();
+    stepTime.start();
+}
+
+void Profiler::StepTimer::restart()
+{
+    beginTime.restart();
+    stepTime.restart();
+}
+
+void Profiler::StepTimer::nextStep()
+{
+    stepTime.restart();
+}
+
+int Profiler::FuncsData::threadIndex(std::thread::id th) const
+{
+    std::thread::id empty;
+    size_t count = this->threads.size();
+    for (size_t i = 0; i < count; ++i) {
+        std::thread::id thi = this->threads[i];
+        if (thi == th) {
+            return static_cast<int>(i);
+        }
+
+        if (thi == empty) {
+            return -1;
+        }
+    }
+    return -1;
+}
+
+int Profiler::FuncsData::addThread(std::thread::id th)
+{
+    std::lock_guard<std::mutex> lock(this->mutex);
+
+    int index = threadIndex(th);
+    if (index > -1) {
+        return index;
+    }
+
+    size_t count = this->threads.size();
+    std::thread::id empty;
+    for (size_t i = 0; i < count; ++i) {
+        std::thread::id thi = this->threads[i];
+        if (thi == empty) {
+            this->threads[i] = th;
+            return static_cast<int>(i);
+        }
+    }
+    return -1;
+}
+
+using mclock = std::chrono::high_resolution_clock;
+
+void Profiler::ElapsedTimer::start()
+{
+    _start = mclock::now();
+}
+
+void Profiler::ElapsedTimer::restart()
+{
+    start();
+}
+
+double Profiler::ElapsedTimer::mlsecsElapsed() const
+{
+    auto end = mclock::now();
+    std::chrono::duration<double, std::milli> elapsed = end - _start;
+
+    return elapsed.count();
+}
+
+void Profiler::ElapsedTimer::invalidate()
+{
+    _start = mclock::time_point();
+}
+
+bool Profiler::ElapsedTimer::isValid() const
+{
+    const mclock::duration since_epoch = _start.time_since_epoch();
+    return since_epoch.count() > 0;
+}
+
+Profiler::Printer::~Printer()
+{}
+
+void Profiler::Printer::printDebug(const std::string& str)
+{
+    std::cout << str << '\n';
+}
+
+void Profiler::Printer::printInfo(const std::string& str)
+{
+    std::cout << str << '\n';
+}
+
+static std::string formatDouble(double val, size_t prec)
+{
+    std::stringstream ss;
+    ss << std::fixed << std::setprecision(prec) << val;
+    return ss.str();
+}
+
+void Profiler::Printer::printStep(const std::string& tag, double beginMs, double stepMs, const std::string& info)
+{
+    static const std::string COLON(" : ");
+    static const std::string SEP("/");
+    static const std::string MS(" ms: ");
+
+    std::string str;
+    str.reserve(100);
+
+    str
+    .append(tag)
+    .append(COLON)
+    .append(formatDouble(beginMs, 3))
+    .append(SEP)
+    .append(formatDouble(stepMs, 3))
+    .append(MS)
+    .append(info);
+
+    printDebug(str);
+}
+
+void Profiler::Printer::printTraceBegin(const std::string& func, size_t stackCounter)
+{
+    static const std::string BEGIN("-> ");
+
+    std::string indent;
+    indent.resize(stackCounter, ' ');
+    printDebug(indent + BEGIN + func);
+}
+
+void Profiler::Printer::printTraceEnd(const std::string& func, double calltimeMs, long callcount, double sumtimeMs, size_t stackCounter)
+{
+    static const std::string END("<- ");
+    static const std::string CALLTIME("  calltime: ");
+    static const std::string CALLCOUNT("  callcount: ");
+    static const std::string SUMTIME("  sumtime: ");
+
+    std::string indent;
+    indent.resize(stackCounter, ' ');
+
+    //if (calltimeMs > 10 || callcount%100 == 1.) { //! NOTE Anti spam
+    std::string str;
+    str.reserve(100);
+    str
+    .append(indent)
+    .append(END)
+    .append(func)
+    .append(CALLTIME).append(formatDouble(calltimeMs, 3))
+    .append(CALLCOUNT).append(std::to_string(callcount))
+    .append(SUMTIME).append(formatDouble(sumtimeMs, 3));
+
+    printDebug(str);
+    //}
+}
+
+void Profiler::Printer::printData(const Data& data, Data::Mode mode, int maxcount)
+{
+    printInfo(formatData(data, mode, maxcount));
+}
+
+namespace {
+struct IsLessBySum {
+    bool operator()(const Profiler::Data::Func& f, const Profiler::Data::Func& s) const
+    {
+        return f.sumtimeMs > s.sumtimeMs;
+    }
+};
+}
+
+std::string Profiler::Printer::formatData(const Data& data, Data::Mode mode, int maxcount) const
+{
+    std::stringstream stream;
+    stream << "\n\n";
+
+    using Funcs = std::unordered_map<std::string, Data::Func>;
+    using Threads = std::unordered_map<std::thread::id, Data::Thread>;
+
+    if (mode == Data::OnlyMain || mode == Data::All) {
+        std::list<Data::Func> list;
+        const Funcs& funcs = data.threads.at(data.mainThread).funcs;
+        Funcs::const_iterator it = funcs.cbegin(), end = funcs.cend();
+        for (; it != end; ++it) {
+            list.push_back(it->second);
+        }
+
+        list.sort(IsLessBySum());
+
+        std::string info = "Main thread. Top "
+                           + std::to_string(maxcount)
+                           + " by sum time (total count: "
+                           + std::to_string(list.size())
+                           + ")";
+
+        funcsToStream(stream, info, list, maxcount);
+    }
+
+    if (mode == Data::OnlyOther || mode == Data::All) {
+        std::list<Data::Func> list;
+        Threads::const_iterator it = data.threads.cbegin(), end = data.threads.cend();
+        for (; it != end; ++it) {
+            if (it->first == data.mainThread) {
+                continue;
+            }
+
+            const Funcs& funcs = it->second.funcs;
+            Funcs::const_iterator it = funcs.cbegin(), end = funcs.cend();
+            for (; it != end; ++it) {
+                list.push_back(it->second);
+            }
+        }
+
+        list.sort(IsLessBySum());
+
+        std::string info = "Other threads. Top "
+                           + std::to_string(maxcount)
+                           + " by sum time (total count: "
+                           + std::to_string(list.size())
+                           + ")";
+
+        funcsToStream(stream, info, list, maxcount);
+    }
+
+    return stream.str();
+}
+
+static std::string leftJustified(const std::string& val, size_t width)
+{
+    std::string str;
+    str.resize(width, ' ');
+    size_t lenght = width < val.size() ? width : val.size();
+    for (size_t i = 0; i < lenght; ++i) {
+        str[i] = val[i];
+    }
+    return str;
+}
+
+#define FORMAT(str, width) leftJustified(str, width)
+#define TITLE(str) FORMAT(std::string(str), 18)
+#define VALUE(val, unit) FORMAT(std::to_string(val) + unit, 18)
+#define VALUE_D(val, unit) FORMAT(formatDouble(val, 3) + unit, 18)
+
+void Profiler::Printer::funcsToStream(std::stringstream& stream,
+                                      const std::string& title,
+                                      const std::list<Data::Func>& funcs,
+                                      int count) const
+{
+    stream << title << "\n";
+    stream << FORMAT("Function", 60) << TITLE("Call time") << TITLE("Call count") << TITLE("Sum time") << "\n";
+
+    int i = 0;
+    for (const Data::Func& f : funcs) {
+        stream << FORMAT(f.func, 60)
+               << VALUE_D(f.callcount ? (f.sumtimeMs / static_cast<double>(f.callcount)) : 0, " ms")
+               << VALUE(f.callcount, "")
+               << VALUE_D(f.sumtimeMs, " ms")
+               << "\n";
+        ++i;
+        if (i >= count) {
+            break;
+        }
+    }
+
+    stream << "\n\n";
+}

thirdparty/haw_profiler/src/profiler.h

@@ -0,0 +1,239 @@
+#ifndef HAW_PROFILER_H
+#define HAW_PROFILER_H
+
+#include <string>
+#include <list>
+#include <vector>
+#include <set>
+#include <unordered_map>
+#include <thread>
+#include <mutex>
+#include <chrono>
+#include <sstream>
+
+#define HAW_PROFILER_ENABLED
+
+#ifndef FUNC_INFO
+#if defined(_MSC_VER)
+    #define FUNC_INFO __FUNCSIG__
+#else
+    #define FUNC_INFO __PRETTY_FUNCTION__
+#endif
+#endif
+
+#ifdef HAW_PROFILER_ENABLED
+
+#ifndef TRACEFUNC
+#define TRACEFUNC \
+    static std::string __func_info(haw::profiler::FuncMarker::formatSig(FUNC_INFO)); \
+    haw::profiler::FuncMarker __funcMarker(__func_info);
+#endif
+
+#ifndef TRACEFUNC_C
+#define TRACEFUNC_C(info) \
+    static std::string __func_info(info); \
+    haw::profiler::FuncMarker __funcMarkerInfo(__func_info);
+#endif
+
+#ifndef BEGIN_STEP_TIME
+#define BEGIN_STEP_TIME(tag) \
+    if (haw::profiler::Profiler::options().stepTimeEnabled) \
+    { haw::profiler::Profiler::instance()->stepTime(tag, std::string("Begin"), true); }
+#endif
+
+#ifndef STEP_TIME
+#define STEP_TIME(tag, info) \
+    if (haw::profiler::Profiler::options().stepTimeEnabled) \
+    { haw::profiler::Profiler::instance()->stepTime(tag, info); }
+#endif
+
+#ifndef PROFILER_CLEAR
+#define PROFILER_CLEAR haw::profiler::Profiler::instance()->clear();
+#endif
+
+#ifndef PROFILER_PRINT
+#define PROFILER_PRINT haw::profiler::Profiler::instance()->printThreadsData();
+#endif
+
+#else
+
+#define TRACEFUNC
+#define TRACEFUNC_C(info)
+#define BEGIN_STEP_TIME
+#define STEP_TIME
+#define PROFILER_CLEAR
+#define PROFILER_PRINT
+
+#endif
+
+namespace haw::profiler {
+class Profiler
+{
+public:
+
+    static Profiler* instance()
+    {
+        static Profiler p;
+        return &p;
+    }
+
+    struct Options {
+        bool stepTimeEnabled{ true };
+        bool funcsTimeEnabled{ true };
+        bool funcsTraceEnabled{ false };
+        size_t funcsMaxThreadCount{ 100 };
+        int dataTopCount{ 150 };
+        Options() {}
+    };
+
+    struct Data {
+        enum Mode {
+            All,
+            OnlyMain,
+            OnlyOther
+        };
+
+        struct Func {
+            std::string func;
+            long callcount{ 0 };
+            double sumtimeMs{ 0. };
+            Func() {}
+            Func(const std::string& f, long cc, double st)
+                : func(f), callcount(cc), sumtimeMs(st) {}
+        };
+
+        struct Thread {
+            std::thread::id thread;
+            std::unordered_map<std::string, Func> funcs;
+        };
+
+        std::thread::id mainThread;
+        std::unordered_map<std::thread::id, Thread> threads;
+    };
+
+    struct Printer {
+        virtual ~Printer();
+        virtual void printDebug(const std::string& str);
+        virtual void printInfo(const std::string& str);
+        virtual void printStep(const std::string& tag, double beginMs, double stepMs, const std::string& info);
+        virtual void printTraceBegin(const std::string& func, size_t stackCounter);
+        virtual void printTraceEnd(const std::string& func, double calltimeMs, long callcount, double sumtimeMs, size_t stackCounter);
+        virtual void printData(const Data& data, Data::Mode mode, int maxcount);
+        virtual std::string formatData(const Data& data, Data::Mode mode, int maxcount) const;
+        virtual void funcsToStream(std::stringstream& stream, const std::string& title, const std::list<Data::Func>& funcs,int count) const;
+    };
+
+    struct ElapsedTimer {
+        void start();
+        void restart();
+        double mlsecsElapsed() const; //NOTE fractional milliseconds
+        void invalidate();
+        bool isValid() const;
+
+    private:
+        std::chrono::high_resolution_clock::time_point _start;
+    };
+
+    struct FuncTimer {
+        const std::string& func;
+        ElapsedTimer timer;
+        long callcount;
+        double sumtimeMs;
+        explicit FuncTimer(const std::string& f)
+            : func(f), callcount(0), sumtimeMs(0) {}
+    };
+
+    void setup(const Options& opt = Options(), Printer* printer = nullptr);
+
+    static const Options& options();
+    Printer* printer() const;
+
+    void stepTime(const std::string& tag, const std::string& info, bool isRestart = false);
+
+    FuncTimer* beginFunc(const std::string& func);
+    void endFunc(FuncTimer* timer, const std::string& func);
+
+    const std::string& staticInfo(const std::string& info); //! NOTE Saving string
+
+    void clear();
+
+    Data threadsData(Data::Mode mode = Data::All) const;
+
+    std::string threadsDataString(Data::Mode mode = Data::All) const;
+    void printThreadsData(Data::Mode mode = Data::All) const;
+
+    static void print(const std::string& str);
+
+    bool save(const std::string& filePath);
+
+private:
+    Profiler();
+    ~Profiler();
+
+    friend struct FuncMarker;
+
+    static Options m_options;
+
+    struct StepTimer {
+        ElapsedTimer beginTime;
+        ElapsedTimer stepTime;
+
+        double beginMs() const;
+        double stepMs() const;
+        void start();
+        void restart();
+        void nextStep();
+    };
+
+    typedef std::unordered_map<std::string, StepTimer* > StepTimers;
+    struct StepsData {
+        std::mutex mutex;
+        StepTimers timers;
+    };
+
+    typedef std::unordered_map<const std::string*, FuncTimer* > FuncTimers;
+    struct FuncsData {
+        std::mutex mutex;
+        std::vector<std::thread::id> threads;
+        std::vector<FuncTimers> timers;
+        std::set<std::string> staticInfo;
+
+        int threadIndex(std::thread::id th) const;
+        int addThread(std::thread::id th);
+    };
+
+    bool save_file(const std::string& path, const std::string& content);
+
+    Printer* m_printer{ nullptr };
+
+    StepsData m_steps;
+    FuncsData m_funcs;
+
+    size_t m_stackCounter{ 0 };
+};
+
+struct FuncMarker
+{
+    explicit FuncMarker(const std::string& fn)
+        : func(fn)
+    {
+        if (Profiler::m_options.funcsTimeEnabled) {
+            timer = Profiler::instance()->beginFunc(fn);
+        }
+    }
+
+    ~FuncMarker()
+    {
+        if (Profiler::m_options.funcsTimeEnabled) {
+            Profiler::instance()->endFunc(timer, func);
+        }
+    }
+
+    static std::string formatSig(const std::string& sig);
+
+    Profiler::FuncTimer* timer{ nullptr };
+    const std::string& func;
+};
+}
+
+#endif // XTZ_PROFILER_H

thirdparty/haw_profiler/tests/CMakeLists.txt

@@ -0,0 +1,21 @@
+cmake_minimum_required(VERSION 3.14)
+
+project(haw_profiler LANGUAGES CXX)
+
+set(CMAKE_INCLUDE_CURRENT_DIR ON)
+
+set(CMAKE_CXX_STANDARD 17)
+set(CMAKE_CXX_STANDARD_REQUIRED ON)
+
+include(${CMAKE_CURRENT_LIST_DIR}/../src/profiler.cmake)
+
+include_directories(${HAW_PROFILER_INC})
+
+add_executable(haw_profiler
+    main.cpp
+    ${HAW_PROFILER_SRC}
+)
+
+target_link_libraries(haw_profiler
+    pthread
+)

thirdparty/haw_profiler/tests/main.cpp

@@ -0,0 +1,104 @@
+#include <iostream>
+#include <thread>
+#include <chrono>
+
+#include "profiler.h"
+
+class Example
+{
+public:
+    Example() = default;
+
+    static void th_func()
+    {
+        TRACEFUNC;
+        std::this_thread::sleep_for(std::chrono::milliseconds(2));
+    }
+
+    void func1()
+    {
+        TRACEFUNC;
+        std::this_thread::sleep_for(std::chrono::milliseconds(2));
+    }
+
+    void func2()
+    {
+        TRACEFUNC;
+        std::this_thread::sleep_for(std::chrono::milliseconds(2));
+    }
+
+    void func3()
+    {
+        TRACEFUNC;
+        std::this_thread::sleep_for(std::chrono::milliseconds(10));
+    }
+
+    void func4()
+    {
+        TRACEFUNC;
+        std::this_thread::sleep_for(std::chrono::milliseconds(10));
+
+        STEP_TIME("mark1", "end body func4");
+
+        func3();
+    }
+
+    void example()
+    {
+        std::thread th(th_func);
+
+        TRACEFUNC;
+        func1();
+
+        BEGIN_STEP_TIME("mark1");
+
+        {
+            TRACEFUNC_C("call func2 10 times")
+            for (int i = 0; i < 10; ++i) {
+                func2();
+            }
+        }
+
+        STEP_TIME("mark1", "end call func2 10 times");
+
+        func3();
+        STEP_TIME("mark1", "end func3");
+
+        func4();
+
+        th.join();
+    }
+};
+
+int main(int argc, char* argv[])
+{
+    std::clog << "Hello World, I am Profiler\n";
+
+    Example t;
+    t.example();
+
+    PROFILER_PRINT;
+
+    /* Output:
+        mark1 : 0.000/0.000 ms: Begin
+        mark1 : 21.582/21.545 ms: end call func2 10 times
+        mark1 : 31.699/10.100 ms: end func3
+        mark1 : 41.816/10.098 ms: end body func4
+
+
+        Main thread. Top 150 by sum time (total count: 6)
+        Function                                                    Call time         Call count        Sum time
+        Example::example                                            54.148 ms         1                 54.148 ms
+        call func2 10 times                                         21.520 ms         1                 21.520 ms
+        Example::func2                                              2.150 ms          10                21.500 ms
+        Example::func4                                              20.202 ms         1                 20.202 ms
+        Example::func3                                              10.090 ms         2                 20.180 ms
+        Example::func1                                              2.213 ms          1                 2.213 ms
+
+
+        Other threads. Top 150 by sum time (total count: 1)
+        Function                                                    Call time         Call count        Sum time
+        Example::th_func                                            2.212 ms          1                 2.212 ms
+
+    */
+}