From: Simon Marchi Date: Thu, 17 Apr 2025 19:23:53 +0000 (-0400) Subject: gdb: add scoped_time_it X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=0b79576c9d398caec787fa913c3b115afdc3d06a;p=thirdparty%2Fbinutils-gdb.git gdb: add scoped_time_it New in v2: - actually use m_enabled in the constructor and destructor - output using gdb_stdlog->write_async_safe instead of gdb_printf scoped_time_it is a small utility that measures and prints how much time a given thread spent in a given scope. Similar to the time(1) command, it prints the time spent in user mode, system mode, and the wall clock time. It also prints the CPU utilization percentage, which is: (user + sys) / wall This can help spot cases where the workload is not well balanced between workers, or the CPU utilization is not optimal (perhaps due to contention around a lock for example). To use it, just add it in some scope. For instance, a subsequent patch adds it here: workers.add_task ([this, task_count, iter, last] () { scoped_time_it time_it ("DWARF indexing worker"); process_cus (task_count, iter, last); }); On destruction, if enabled, it prints a line showing the time spent by that thread, similar to what time(1) prints. The example above prints this (one line for each worker thread): Time for "DWARF indexing worker": wall 0.173, user 0.120, sys 0.034, user+sys 0.154, 89.0 % CPU Time for "DWARF indexing worker": wall 0.211, user 0.144, sys 0.047, user+sys 0.191, 90.5 % CPU Time for "DWARF indexing worker": wall 0.368, user 0.295, sys 0.057, user+sys 0.352, 95.7 % CPU Time for "DWARF indexing worker": wall 0.445, user 0.361, sys 0.072, user+sys 0.433, 97.3 % CPU Time for "DWARF indexing worker": wall 0.592, user 0.459, sys 0.113, user+sys 0.572, 96.6 % CPU Time for "DWARF indexing worker": wall 0.739, user 0.608, sys 0.115, user+sys 0.723, 97.8 % CPU Time for "DWARF indexing worker": wall 0.831, user 0.677, sys 0.140, user+sys 0.817, 98.3 % CPU Time for "DWARF indexing worker": wall 0.949, user 0.789, sys 0.144, user+sys 0.933, 98.3 % CPU The object is only enabled if per_command_time (controlled by "maint set per-command time") is true at construction time. I wanted to avoid adding a new command for now, but eventually if there are too many scoped_time_it around the code base and we want to be able to enabled them selectively (e.g. just the ones in the DWARF reader, or in the symbol searching functions, etc), we could have a dedicated command for that. I added this functionality to GDB because it relies on gdb_printf and per_command_time, but if we ever need it in gdbsupport, I'm sure we could find a way to put it there. Change-Id: I5416ac1448f960f44d85f8449943d994198a271e Approved-By: Tom Tromey --- diff --git a/gdb/maint.c b/gdb/maint.c index 766ab74e6d5..c6f9b322e50 100644 --- a/gdb/maint.c +++ b/gdb/maint.c @@ -1151,6 +1151,50 @@ set_per_command_cmd (const char *args, int from_tty) } } +/* See maint.h. */ + +scoped_time_it::scoped_time_it (const char *what) + : m_enabled (per_command_time), + m_what (what), + m_start_wall (m_enabled + ? std::chrono::steady_clock::now () + : std::chrono::steady_clock::time_point ()) +{ + if (m_enabled) + get_run_time (m_start_user, m_start_sys, run_time_scope::thread); +} + +/* See maint.h. */ + +scoped_time_it::~scoped_time_it () +{ + if (!m_enabled) + return; + + namespace chr = std::chrono; + auto end_wall = chr::steady_clock::now (); + + user_cpu_time_clock::time_point end_user; + system_cpu_time_clock::time_point end_sys; + get_run_time (end_user, end_sys, run_time_scope::thread); + + auto user = end_user - m_start_user; + auto sys = end_sys - m_start_sys; + auto wall = end_wall - m_start_wall; + auto user_ms = chr::duration_cast (user).count (); + auto sys_ms = chr::duration_cast (sys).count (); + auto wall_ms = chr::duration_cast (wall).count (); + auto user_plus_sys_ms = user_ms + sys_ms; + + auto str + = string_printf ("Time for \"%s\": wall %.03f, user %.03f, sys %.03f, " + "user+sys %.03f, %.01f %% CPU\n", + m_what, wall_ms / 1000.0, user_ms / 1000.0, + sys_ms / 1000.0, user_plus_sys_ms / 1000.0, + user_plus_sys_ms * 100.0 / wall_ms); + gdb_stdlog->write_async_safe (str.data (), str.size ()); +} + /* Options affecting the "maintenance selftest" command. */ struct maintenance_selftest_options diff --git a/gdb/maint.h b/gdb/maint.h index 0ddc62bb9e9..28e6280a464 100644 --- a/gdb/maint.h +++ b/gdb/maint.h @@ -70,6 +70,33 @@ class scoped_command_stats int m_start_nr_blocks; }; +/* RAII structure used to measure the time spent by the current thread in a + given scope. */ + +struct scoped_time_it +{ + /* WHAT is the prefix to show when the summary line is printed. */ + scoped_time_it (const char *what); + + DISABLE_COPY_AND_ASSIGN (scoped_time_it); + ~scoped_time_it (); + +private: + bool m_enabled; + + /* Summary line prefix. */ + const char *m_what; + + /* User time at the start of execution. */ + user_cpu_time_clock::time_point m_start_user; + + /* System time at the start of execution. */ + system_cpu_time_clock::time_point m_start_sys; + + /* Wall-clock time at the start of execution. */ + std::chrono::steady_clock::time_point m_start_wall; +}; + extern obj_section *maint_obj_section_from_bfd_section (bfd *abfd, asection *asection, objfile *ofile); diff --git a/gdb/mi/mi-main.c b/gdb/mi/mi-main.c index aea8fa9a02e..cda72ca4f5b 100644 --- a/gdb/mi/mi-main.c +++ b/gdb/mi/mi-main.c @@ -2218,7 +2218,7 @@ timestamp (struct mi_timestamp *tv) using namespace std::chrono; tv->wallclock = steady_clock::now (); - get_run_time (tv->utime, tv->stime); + get_run_time (tv->utime, tv->stime, run_time_scope::process); } static void diff --git a/gdbsupport/run-time-clock.cc b/gdbsupport/run-time-clock.cc index d8de0313148..621ba77ed9a 100644 --- a/gdbsupport/run-time-clock.cc +++ b/gdbsupport/run-time-clock.cc @@ -39,12 +39,28 @@ timeval_to_microseconds (struct timeval *tv) void get_run_time (user_cpu_time_clock::time_point &user, - system_cpu_time_clock::time_point &system) noexcept + system_cpu_time_clock::time_point &system, + run_time_scope scope) noexcept { #ifdef HAVE_GETRUSAGE struct rusage rusage; + int who; - getrusage (RUSAGE_SELF, &rusage); + switch (scope) + { + case run_time_scope::thread: + who = RUSAGE_THREAD; + break; + + case run_time_scope::process: + who = RUSAGE_SELF; + break; + + default: + gdb_assert_not_reached ("invalid run_time_scope value"); + } + + getrusage (who, &rusage); microseconds utime = timeval_to_microseconds (&rusage.ru_utime); microseconds stime = timeval_to_microseconds (&rusage.ru_stime); diff --git a/gdbsupport/run-time-clock.h b/gdbsupport/run-time-clock.h index c789e9dcf79..a985dbb2667 100644 --- a/gdbsupport/run-time-clock.h +++ b/gdbsupport/run-time-clock.h @@ -51,12 +51,25 @@ struct system_cpu_time_clock static time_point now () noexcept = delete; }; +/* Whether to measure time run time for the whole process or just one + thread. */ + +enum class run_time_scope +{ + process, + thread, +}; + /* Return the user/system time as separate time points, if supported. If not supported, then the combined user+kernel time - is returned in USER and SYSTEM is set to zero. */ + is returned in USER and SYSTEM is set to zero. + + SCOPE indicates whether to return the run time for the whole process or + just for the calling thread. */ void get_run_time (user_cpu_time_clock::time_point &user, - system_cpu_time_clock::time_point &system) noexcept; + system_cpu_time_clock::time_point &system, + run_time_scope scope) noexcept; /* Count the total amount of time spent executing in userspace+kernel mode. */