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>

5 files changed, 105 insertions, 5 deletions

diff --git a/gdb/maint.c b/gdb/maint.c
index 766ab74..c6f9b32 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<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 0ddc62b..28e6280 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 aea8fa9..cda72ca 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 d8de031..621ba77 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 c789e9d..a985dbb 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.  */