diff --git a/libs/util/include/psemek/util/profiler.hpp b/libs/util/include/psemek/util/profiler.hpp index 45eb7612..df7192ce 100644 --- a/libs/util/include/psemek/util/profiler.hpp +++ b/libs/util/include/psemek/util/profiler.hpp @@ -9,14 +9,13 @@ namespace psemek::util struct profiler { - profiler(std::string_view name) - : name_(std::move(name)) - {} + profiler(std::string const & name); ~ profiler(); + static void dump(); + private: - std::string_view const name_; util::clock<> clock_; }; diff --git a/libs/util/source/profiler.cpp b/libs/util/source/profiler.cpp index 6ded5164..b0559493 100644 --- a/libs/util/source/profiler.cpp +++ b/libs/util/source/profiler.cpp @@ -1,14 +1,127 @@ #include #include +#include #include +#include +#include +#include +#include +#include +#include +#include namespace psemek::util { + namespace + { + + struct profiler_tree + { + profiler_tree * parent = nullptr; + std::mutex * mutex = nullptr; + + statistics execution_time; + + std::map children; + }; + + static std::map roots; + static std::mutex roots_mutex; + static std::unordered_map thread_mutex; + + static thread_local profiler_tree * current = nullptr; + + void dump_impl(profiler_tree const & node, std::size_t depth) + { + std::size_t max_name_length = 0; + + for (auto const & c : node.children) + max_name_length = std::max(max_name_length, c.first.size()); + + for (auto const & c : node.children) + { + log::info() << std::string(depth * 2, ' ') << std::setw(max_name_length + 3) << std::left << std::setfill(' ') << c.first + << util::pretty(std::chrono::duration{c.second.execution_time.mean()}, std::chrono::microseconds{}) + << " (" << c.second.execution_time.count() << " calls)"; + dump_impl(c.second, depth + 1); + } + } + + profiler_tree merge(profiler_tree t1, profiler_tree const & t2) + { + t1.execution_time = merge(t1.execution_time, t2.execution_time); + + for (auto const & p : t2.children) + { + auto it = t1.children.find(p.first); + if (it == t1.children.end()) + { + t1.children.insert(p); + } + else + { + it->second = merge(std::move(it->second), p.second); + } + } + + return t1; + } + + profiler_tree merged_tree() + { + std::vector r; + + { + std::lock_guard lock{roots_mutex}; + for (auto const & p : roots) + r.push_back(&p.second); + } + + profiler_tree result; + + for (auto root : r) + { + std::lock_guard lock{*(root->mutex)}; + result = merge(std::move(result), *root); + } + + return result; + } + + } + + profiler::profiler(std::string const & name) + { + auto const id = std::this_thread::get_id(); + + if (!current) + { + std::lock_guard lock{roots_mutex}; + current = &roots[id]; + current->mutex = &thread_mutex[id]; + } + + std::lock_guard lock{*(current->mutex)}; + + auto next = ¤t->children[name]; + next->parent = current; + next->mutex = current->mutex; + current = next; + clock_.restart(); + } + profiler::~profiler() { - log::info() << name_ << ": " << util::pretty(clock_.duration(), std::chrono::microseconds{1}); + std::lock_guard lock{*(current->mutex)}; + current->execution_time.push(clock_.count()); + current = current->parent; + } + + void profiler::dump() + { + dump_impl(merged_tree(), 0); } }