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 <tom@tromey.com>

diff --git a/gdb/maint.c b/gdb/maint.c
index 766ab74e6d5125ec4e20b16b8e8adae34b686d87..c6f9b322e504ffa0f460b10b664328923d55640f 100644 (file)
--- 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<chr::milliseconds> (user).count ();
+  auto sys_ms = chr::duration_cast<chr::milliseconds> (sys).count ();
+  auto wall_ms = chr::duration_cast<chr::milliseconds> (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 0ddc62bb9e963fa96edc819f4896a25c9e545405..28e6280a464c0c7f032684c3e5f88d574cafb8d0 100644 (file)
--- 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 aea8fa9a02e8d435d634f8c51b41517dfba82c6f..cda72ca4f5b3ccfedba4c19715fa928a512f52f3 100644 (file)
--- 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 d8de0313148adc91b85d46bebc979429d30be9ed..621ba77ed9a27604df07a72c96c49d7480facafb 100644 (file)
--- 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 c789e9dcf7993ee1bd38aafb32f8a4ba011682ef..a985dbb2667fb569aaef86f3dfebfcce608e505f 100644 (file)
--- 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.  */