diff --git a/arbor/include/arbor/profile/profiler.hpp b/arbor/include/arbor/profile/profiler.hpp index fd8dd980c59fa9d4e5c9988b549b50f9a12a171a..810600ebd03b17c05e41a9c0abd8588858f7a046 100644 --- a/arbor/include/arbor/profile/profiler.hpp +++ b/arbor/include/arbor/profile/profiler.hpp @@ -41,6 +41,8 @@ ARB_ARBOR_API void profiler_enter(std::size_t region_id); ARB_ARBOR_API void profiler_leave(); ARB_ARBOR_API profile profiler_summary(); + +ARB_ARBOR_API std::ostream& print_profiler_summary(std::ostream&, double limit=0.0); ARB_ARBOR_API std::size_t profiler_region_id(const std::string& name); ARB_ARBOR_API std::ostream& operator<<(std::ostream&, const profile&); diff --git a/arbor/profile/profiler.cpp b/arbor/profile/profiler.cpp index 0a6af0a2278e97ca08848f397dad86fbd89b494a..fccb33ba874032b6cf1ed99fa5fbf7b781e5a474 100644 --- a/arbor/profile/profiler.cpp +++ b/arbor/profile/profiler.cpp @@ -306,35 +306,73 @@ const std::vector<std::string>& profiler::regions() const { return region_names_; } -void print(std::ostream& o, - profile_node& n, - float wall_time, - unsigned nthreads, - float thresh, - std::string indent="") -{ +struct prof_line { + std::string name; + std::string count; + std::string time; + std::string thread; + std::string percent; +}; + +void print_lines(std::vector<prof_line>& lines, + profile_node& n, + float wall_time, + unsigned nthreads, + float thresh, + std::string indent) { static char buf[80]; - auto name = indent + n.name; float per_thread_time = n.time/nthreads; float proportion = n.time/wall_time*100; // If the percentage of overall time for this region is below the // threashold, stop drawing this branch. - if (proportion<thresh) return; + if (proportion < thresh) return; + + prof_line res; + res.name = indent + n.name; + res.count = (n.count==profile_node::npos) ? "-" : std::to_string(n.count); + snprintf(buf, std::size(buf), "%.3f", float(n.time)); + res.time = buf; + snprintf(buf, std::size(buf), "%.3f", float(per_thread_time)); + res.thread = buf; + snprintf(buf, std::size(buf), "%.1f", float(proportion)); + res.percent = buf; + lines.push_back(res); + // print each of the children in turn + for (auto& c: n.children) print_lines(lines, c, wall_time, nthreads, thresh, indent + " "); +}; - if (n.count==profile_node::npos) { - snprintf(buf, std::size(buf), "_p_ %-20s%12s%12.3f%12.3f%8.1f", - name.c_str(), "-", float(n.time), per_thread_time, proportion); - } - else { - snprintf(buf, std::size(buf), "_p_ %-20s%12lu%12.3f%12.3f%8.1f", - name.c_str(), n.count, float(n.time), per_thread_time, proportion); +void print(std::ostream& os, + profile_node& n, + float wall_time, + unsigned nthreads, + float thresh) { + std::vector<prof_line> lines{{"REGION", "CALLS", "THREAD", "WALL", "\%"}}; + print_lines(lines, n, wall_time, nthreads, thresh, ""); + // fixing up lengths here + std::size_t max_len_name = 0; + std::size_t max_len_count = 0; + std::size_t max_len_thread = 0; + std::size_t max_len_time = 0; + std::size_t max_len_percent = 0; + for (const auto& line: lines) { + max_len_name = std::max(max_len_name, line.name.size()); + max_len_count = std::max(max_len_count, line.count.size()); + max_len_thread = std::max(max_len_thread, line.thread.size()); + max_len_time = std::max(max_len_time, line.time.size()); + max_len_percent = std::max(max_len_percent, line.percent.size()); } - o << "\n" << buf; - // print each of the children in turn - for (auto& c: n.children) print(o, c, wall_time, nthreads, thresh, indent+" "); + auto lpad = [](const std::string& s, std::size_t n) { return std::string(n - s.size(), ' ') + s + " "; }; + auto rpad = [](const std::string& s, std::size_t n) { return s + std::string(n - s.size(), ' ') + " "; }; + + for (const auto& line: lines) os << rpad(line.name, max_len_name) + << lpad(line.count, max_len_count) + << lpad(line.thread, max_len_thread) + << lpad(line.time, max_len_time) + << lpad(line.percent, max_len_percent) + << '\n'; }; // @@ -362,13 +400,8 @@ ARB_ARBOR_API void profiler_initialize(context ctx) { // Print profiler statistics to an ostream ARB_ARBOR_API std::ostream& operator<<(std::ostream& o, const profile& prof) { - char buf[80]; - auto tree = make_profile_tree(prof); - - snprintf(buf, std::size(buf), "_p_ %-20s%12s%12s%12s%8s", "REGION", "CALLS", "THREAD", "WALL", "\%"); - o << buf; - print(o, tree, tree.time, prof.num_threads, 0, ""); + print(o, tree, tree.time, prof.num_threads, 0); return o; } @@ -376,6 +409,13 @@ ARB_ARBOR_API profile profiler_summary() { return profiler::get_global_profiler().results(); } +ARB_ARBOR_API std::ostream& print_profiler_summary(std::ostream& os, double limit) { + auto prof = profiler_summary(); + auto tree = make_profile_tree(prof); + print(os, tree, tree.time, prof.num_threads, limit); + return os; +} + #else ARB_ARBOR_API void profiler_leave() {} @@ -384,6 +424,8 @@ ARB_ARBOR_API profile profiler_summary(); ARB_ARBOR_API profile profiler_summary() {return profile();} ARB_ARBOR_API region_id_type profiler_region_id(const std::string&) {return 0;} ARB_ARBOR_API std::ostream& operator<<(std::ostream& o, const profile&) {return o;} +ARB_ARBOR_API std::ostream& profiler_print_summary(std::ostream& os, double limit) { return os; } + #endif // ARB_HAVE_PROFILING diff --git a/python/profiler.cpp b/python/profiler.cpp index 31fe6b069cc1d8ef10ed67b48d92688a605092ed..b3fe1011bee6becfa014d1bc5fb0a2de898b6752 100644 --- a/python/profiler.cpp +++ b/python/profiler.cpp @@ -59,11 +59,14 @@ void register_profiler(pybind11::module& m) { m.def("profiler_initialize", [](context_shim& ctx) { arb::profile::profiler_initialize(ctx.context); }); - m.def("profiler_summary", [](){ - std::stringstream stream; - stream << arb::profile::profiler_summary(); - return stream.str(); - }); + m.def("profiler_summary", + [](double limit){ + std::stringstream stream; + arb::profile::print_profiler_summary(stream, limit); + return stream.str(); + }, + pybind11::arg_v("limit", 0.0, "Print contributions above <limit> percent. Defaults to showing all.") + ); #endif }