[2/3] gdb: add scoped_time_it

  From: Simon Marchi <simon.marchi@polymtl.ca>

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
---
 gdb/maint.c                  | 35 +++++++++++++++++++++++++++++++++++
 gdb/maint.h                  | 27 +++++++++++++++++++++++++++
 gdb/mi/mi-main.c             |  2 +-
 gdbsupport/run-time-clock.cc | 20 ++++++++++++++++++--
 gdbsupport/run-time-clock.h  | 17 +++++++++++++++--
 5 files changed, 96 insertions(+), 5 deletions(-)
  

Am Freitag, 11. April 2025 um 20:25:09 MESZ hat <simon.marchi@polymtl.ca> Folgendes geschrieben:

> From: Simon Marchi <simon.marchi@polymtl.ca>
>
> 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
> ---
> gdb/maint.c                  | 35 +++++++++++++++++++++++++++++++++++
> gdb/maint.h                  | 27 +++++++++++++++++++++++++++
> gdb/mi/mi-main.c            |  2 +-
> gdbsupport/run-time-clock.cc | 20 ++++++++++++++++++--
> gdbsupport/run-time-clock.h  | 17 +++++++++++++++--
> 5 files changed, 96 insertions(+), 5 deletions(-)
>
> diff --git a/gdb/maint.c b/gdb/maint.c
> index f5977ecd9194..59479e30aac2 100644
> --- a/gdb/maint.c
> +++ b/gdb/maint.c
> @@ -1138,6 +1138,41 @@ 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 (std::chrono::steady_clock::now ())
> +{
> +  get_run_time (m_start_user, m_start_sys, run_time_scope::thread);
> +}

Is it intentional that steady_clock::now() and get_run_time() are called
even if m_enabled==false?


> +
> +/* See maint.h.  */
> +
> +scoped_time_it::~scoped_time_it ()
> +{
> +  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;
> +
> +  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);
> +}
> +
> /* Options affecting the "maintenance selftest" command.  */
>
> struct maintenance_selftest_options
> diff --git a/gdb/maint.h b/gdb/maint.h
> index 0ddc62bb9e96..28e6280a464c 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 aea8fa9a02e8..cda72ca4f5b3 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 d8de0313148a..621ba77ed9a2 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 c789e9dcf799..a985dbb2667f 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.  */
> --
> 2.49.0


Hannes
  

On 4/11/25 2:57 PM, Hannes Domani wrote:
>  Am Freitag, 11. April 2025 um 20:25:09 MESZ hat <simon.marchi@polymtl.ca> Folgendes geschrieben:
> 
>> From: Simon Marchi <simon.marchi@polymtl.ca>
>>
>> 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
>> ---
>> gdb/maint.c                  | 35 +++++++++++++++++++++++++++++++++++
>> gdb/maint.h                  | 27 +++++++++++++++++++++++++++
>> gdb/mi/mi-main.c            |  2 +-
>> gdbsupport/run-time-clock.cc | 20 ++++++++++++++++++--
>> gdbsupport/run-time-clock.h  | 17 +++++++++++++++--
>> 5 files changed, 96 insertions(+), 5 deletions(-)
>>
>> diff --git a/gdb/maint.c b/gdb/maint.c
>> index f5977ecd9194..59479e30aac2 100644
>> --- a/gdb/maint.c
>> +++ b/gdb/maint.c
>> @@ -1138,6 +1138,41 @@ 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 (std::chrono::steady_clock::now ())
>> +{
>> +  get_run_time (m_start_user, m_start_sys, run_time_scope::thread);
>> +}
> 
> Is it intentional that steady_clock::now() and get_run_time() are called
> even if m_enabled==false?

No, that's an oversight (doesn't break anything, it's just inefficient)!
I will fix it.

Thanks,

Simon
  

>>>>> "Simon" == simon marchi <simon.marchi@polymtl.ca> writes:

Simon>       workers.add_task ([this, task_count, iter, last] ()
Simon> 	{
Simon> 	  scoped_time_it time_it ("DWARF indexing worker");
Simon> 	  process_cus (task_count, iter, last);
Simon> 	});

FWIW I don't think the gdb ui-file machinery is thread-safe and so
printing from a worker task is probably UB.  This is why the DWARF
reader captures complaints and warnings and whatnot.

Printing to gdb_stdlog might be safer though I have not really gone
through to check.

This may not matter in practice.  Though I wonder what happens if:

Simon> +  printf ("Time for \"%s\": wall %.03f, user %.03f, sys %.03f, "
Simon> +	  "user+sys %.03f, %.01f %% CPU\n",
Simon> +	  m_what, wall_ms / 1000.0, user_ms / 1000.0, sys_ms / 1000.0,
Simon> +	  user_plus_sys_ms / 1000.0, user_plus_sys_ms * 100.0 / wall_ms);

... this causes the pager to query from a worker thread.

Tom