#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; struct pretty_impl { double value; }; pretty_impl pretty(double value) { return {value}; } std::ostream & operator << (std::ostream & os, pretty_impl p) { char const * suf[] = { "ns", "us", "ms", "s", }; double s = 1e-9; for (std::size_t i = 0; i < 4; ++i) { if (p.value < (s * 1000.0) || i == 3) { os << (p.value / s) << ' ' << suf[i]; return os; } s *= 1000.0; } return os; } 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) { auto const & stat = c.second.execution_time; if (stat.count() == 1) log::info() << std::string(depth * 2, ' ') << std::setw(max_name_length + 3) << std::left << std::setfill(' ') << c.first << " " << pretty(stat.mean()) << " (" << stat.count() << " call)"; else log::info() << std::string(depth * 2, ' ') << std::setw(max_name_length + 3) << std::left << std::setfill(' ') << c.first << " avg " << pretty(stat.mean()) << " 25% " << pretty(stat.percentile(0.25)) << " 50% " << pretty(stat.percentile(0.50)) << " 75% " << pretty(stat.percentile(0.75)) << " (" << stat.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() { auto count = clock_.count(); std::lock_guard lock{*(current->mutex)}; current->execution_time.push(count); current = current->parent; } void profiler::dump() { dump_impl(merged_tree(), 0); } }