diff mbox series

[3/3] gdb: add some scoped_time_its to profile startup time

Message ID 20250411182151.1427430-3-simon.marchi@polymtl.ca
State New
Headers
Series [1/3] gdbsupport: move run_time_clock::now(user, system) out of run_time_clock |

Checks

Context Check Description
linaro-tcwg-bot/tcwg_gdb_build--master-aarch64 success Build passed
linaro-tcwg-bot/tcwg_gdb_build--master-arm success Build passed
linaro-tcwg-bot/tcwg_gdb_check--master-aarch64 success Test passed
linaro-tcwg-bot/tcwg_gdb_check--master-arm success Test passed

Commit Message

Simon Marchi April 11, 2025, 6:21 p.m. UTC 
  From: Simon Marchi <simon.marchi@polymtl.ca>

I'm investigating some issues where GDB takes a lot of time to start
up (read: for the DWARF index to be ready to do anything useful).
Adding those scoped_time_it instances helped me gain some insights about
where GDB spends time.  I think they would be useful to have upstream,
to make investigating future problems easier.  It would also be useful
to be able to give some numbers in the commit messages.

Here's an example of what GDB outputs:

    Time for "minsyms install worker": wall 0.045, user 0.040, sys 0.004, user+sys 0.044, 97.8 % CPU
    Time for "minsyms install worker": wall 0.511, user 0.457, sys 0.048, user+sys 0.505, 98.8 % CPU
    Time for "minsyms install worker": wall 1.513, user 1.389, sys 0.111, user+sys 1.500, 99.1 % CPU
    Time for "minsyms install worker": wall 1.688, user 1.451, sys 0.102, user+sys 1.553, 92.0 % CPU
    Time for "minsyms install worker": wall 1.897, user 1.518, sys 0.089, user+sys 1.607, 84.7 % CPU
    Time for "minsyms install worker": wall 2.811, user 2.558, sys 0.231, user+sys 2.789, 99.2 % CPU
    Time for "minsyms install worker": wall 3.257, user 3.049, sys 0.188, user+sys 3.237, 99.4 % CPU
    Time for "minsyms install worker": wall 3.617, user 3.089, sys 0.211, user+sys 3.300, 91.2 % CPU
    Time for "DWARF indexing worker": wall 19.517, user 0.894, sys 0.075, user+sys 0.969, 5.0 % CPU
    Time for "DWARF indexing worker": wall 19.807, user 0.891, sys 0.086, user+sys 0.977, 4.9 % CPU
    Time for "DWARF indexing worker": wall 20.270, user 1.559, sys 0.119, user+sys 1.678, 8.3 % CPU
    Time for "DWARF indexing worker": wall 20.329, user 1.878, sys 0.147, user+sys 2.025, 10.0 % CPU
    Time for "DWARF indexing worker": wall 20.848, user 3.483, sys 0.224, user+sys 3.707, 17.8 % CPU
    Time for "DWARF indexing worker": wall 21.088, user 4.285, sys 0.295, user+sys 4.580, 21.7 % CPU
    Time for "DWARF indexing worker": wall 21.109, user 4.501, sys 0.274, user+sys 4.775, 22.6 % CPU
    Time for "DWARF indexing worker": wall 21.198, user 5.087, sys 0.319, user+sys 5.406, 25.5 % CPU
    Time for "DWARF skeletonless type units": wall 4.024, user 3.858, sys 0.115, user+sys 3.973, 98.7 % CPU
    Time for "DWARF add parent map": wall 0.092, user 0.086, sys 0.004, user+sys 0.090, 97.8 % CPU
    Time for "DWARF finalize worker": wall 0.278, user 0.241, sys 0.009, user+sys 0.250, 89.9 % CPU
    Time for "DWARF finalize worker": wall 0.307, user 0.304, sys 0.000, user+sys 0.304, 99.0 % CPU
    Time for "DWARF finalize worker": wall 0.727, user 0.719, sys 0.000, user+sys 0.719, 98.9 % CPU
    Time for "DWARF finalize worker": wall 0.913, user 0.901, sys 0.003, user+sys 0.904, 99.0 % CPU
    Time for "DWARF finalize worker": wall 0.776, user 0.767, sys 0.004, user+sys 0.771, 99.4 % CPU
    Time for "DWARF finalize worker": wall 1.897, user 1.869, sys 0.006, user+sys 1.875, 98.8 % CPU
    Time for "DWARF finalize worker": wall 2.534, user 2.512, sys 0.005, user+sys 2.517, 99.3 % CPU
    Time for "DWARF finalize worker": wall 2.607, user 2.583, sys 0.006, user+sys 2.589, 99.3 % CPU
    Time for "DWARF finalize worker": wall 3.142, user 3.094, sys 0.022, user+sys 3.116, 99.2 % CPU

Change-Id: I9453589b9005c3226499428ae9cab9f4a8c22904
---
 gdb/dwarf2/cooked-index-worker.c |  9 +++++++--
 gdb/dwarf2/cooked-index.c        |  7 ++++++-
 gdb/dwarf2/read.c                |  4 ++++
 gdb/maint.c                      | 11 +++++++----
 gdb/minsyms.c                    |  3 +++
 5 files changed, 27 insertions(+), 7 deletions(-)

Comments

Hannes Domani April 11, 2025, 6:47 p.m. UTC | #1 
Am Freitag, 11. April 2025 um 20:36:57 MESZ hat <simon.marchi@polymtl.ca> Folgendes geschrieben:

> From: Simon Marchi <simon.marchi@polymtl.ca>
>
> I'm investigating some issues where GDB takes a lot of time to start
> up (read: for the DWARF index to be ready to do anything useful).
> Adding those scoped_time_it instances helped me gain some insights about
> where GDB spends time.  I think they would be useful to have upstream,
> to make investigating future problems easier.  It would also be useful
> to be able to give some numbers in the commit messages.
>
> Here's an example of what GDB outputs:
>
>     Time for "minsyms install worker": wall 0.045, user 0.040, sys 0.004, user+sys 0.044, 97.8 % CPU
>     Time for "minsyms install worker": wall 0.511, user 0.457, sys 0.048, user+sys 0.505, 98.8 % CPU
>     Time for "minsyms install worker": wall 1.513, user 1.389, sys 0.111, user+sys 1.500, 99.1 % CPU
>     Time for "minsyms install worker": wall 1.688, user 1.451, sys 0.102, user+sys 1.553, 92.0 % CPU
>     Time for "minsyms install worker": wall 1.897, user 1.518, sys 0.089, user+sys 1.607, 84.7 % CPU
>     Time for "minsyms install worker": wall 2.811, user 2.558, sys 0.231, user+sys 2.789, 99.2 % CPU
>     Time for "minsyms install worker": wall 3.257, user 3.049, sys 0.188, user+sys 3.237, 99.4 % CPU
>     Time for "minsyms install worker": wall 3.617, user 3.089, sys 0.211, user+sys 3.300, 91.2 % CPU
>     Time for "DWARF indexing worker": wall 19.517, user 0.894, sys 0.075, user+sys 0.969, 5.0 % CPU
>     Time for "DWARF indexing worker": wall 19.807, user 0.891, sys 0.086, user+sys 0.977, 4.9 % CPU
>     Time for "DWARF indexing worker": wall 20.270, user 1.559, sys 0.119, user+sys 1.678, 8.3 % CPU
>     Time for "DWARF indexing worker": wall 20.329, user 1.878, sys 0.147, user+sys 2.025, 10.0 % CPU
>     Time for "DWARF indexing worker": wall 20.848, user 3.483, sys 0.224, user+sys 3.707, 17.8 % CPU
>     Time for "DWARF indexing worker": wall 21.088, user 4.285, sys 0.295, user+sys 4.580, 21.7 % CPU
>     Time for "DWARF indexing worker": wall 21.109, user 4.501, sys 0.274, user+sys 4.775, 22.6 % CPU
>     Time for "DWARF indexing worker": wall 21.198, user 5.087, sys 0.319, user+sys 5.406, 25.5 % CPU
>     Time for "DWARF skeletonless type units": wall 4.024, user 3.858, sys 0.115, user+sys 3.973, 98.7 % CPU
>     Time for "DWARF add parent map": wall 0.092, user 0.086, sys 0.004, user+sys 0.090, 97.8 % CPU
>     Time for "DWARF finalize worker": wall 0.278, user 0.241, sys 0.009, user+sys 0.250, 89.9 % CPU
>     Time for "DWARF finalize worker": wall 0.307, user 0.304, sys 0.000, user+sys 0.304, 99.0 % CPU
>     Time for "DWARF finalize worker": wall 0.727, user 0.719, sys 0.000, user+sys 0.719, 98.9 % CPU
>     Time for "DWARF finalize worker": wall 0.913, user 0.901, sys 0.003, user+sys 0.904, 99.0 % CPU
>     Time for "DWARF finalize worker": wall 0.776, user 0.767, sys 0.004, user+sys 0.771, 99.4 % CPU
>     Time for "DWARF finalize worker": wall 1.897, user 1.869, sys 0.006, user+sys 1.875, 98.8 % CPU
>     Time for "DWARF finalize worker": wall 2.534, user 2.512, sys 0.005, user+sys 2.517, 99.3 % CPU
>     Time for "DWARF finalize worker": wall 2.607, user 2.583, sys 0.006, user+sys 2.589, 99.3 % CPU
>     Time for "DWARF finalize worker": wall 3.142, user 3.094, sys 0.022, user+sys 3.116, 99.2 % CPU
>
> Change-Id: I9453589b9005c3226499428ae9cab9f4a8c22904
> ---
> gdb/dwarf2/cooked-index-worker.c |  9 +++++++--
> gdb/dwarf2/cooked-index.c        |  7 ++++++-
> gdb/dwarf2/read.c                |  4 ++++
> gdb/maint.c                      | 11 +++++++----
> gdb/minsyms.c                    |  3 +++
> 5 files changed, 27 insertions(+), 7 deletions(-)
>
> diff --git a/gdb/dwarf2/cooked-index-worker.c b/gdb/dwarf2/cooked-index-worker.c
> index da51a8c72e81..5d7fc462a05d 100644
> --- a/gdb/dwarf2/cooked-index-worker.c
> +++ b/gdb/dwarf2/cooked-index-worker.c
> @@ -20,6 +20,7 @@
> #include "dwarf2/cooked-index-worker.h"
> #include "dwarf2/cooked-index.h"
> #include "gdbsupport/thread-pool.h"
> +#include "maint.h"
> #include "run-on-main-thread.h"
> #include "event-top.h"
> #include "exceptions.h"
> @@ -244,8 +245,12 @@ cooked_index_worker::write_to_cache (const cooked_index *idx)
> void
> cooked_index_worker::done_reading ()
> {
> -  for (auto &one_result : m_results)
> -    m_all_parents_map.add_map (*one_result.get_parent_map ());
> +  {
> +    scoped_time_it time_it ("DWARF add parent map");
> +
> +    for (auto &one_result : m_results)
> +      m_all_parents_map.add_map (*one_result.get_parent_map ());
> +  }
>
>   dwarf2_per_bfd *per_bfd = m_per_objfile->per_bfd;
>   cooked_index *table
> diff --git a/gdb/dwarf2/cooked-index.c b/gdb/dwarf2/cooked-index.c
> index 7948ffac2362..2c7e31e5676c 100644
> --- a/gdb/dwarf2/cooked-index.c
> +++ b/gdb/dwarf2/cooked-index.c
> @@ -21,6 +21,7 @@
> #include "dwarf2/read.h"
> #include "dwarf2/stringify.h"
> #include "event-top.h"
> +#include "maint.h"
> #include "observable.h"
> #include "run-on-main-thread.h"
> #include "gdbsupport/task-group.h"
> @@ -101,7 +102,11 @@ cooked_index::set_contents ()
>     {
>       auto this_shard = shard.get ();
>       const parent_map_map *parent_maps = m_state->get_parent_map_map ();
> -      finalizers.add_task ([=] () { this_shard->finalize (parent_maps); });
> +      finalizers.add_task ([=] ()
> +    {
> +      scoped_time_it time_it ("DWARF finalize worker");
> +      this_shard->finalize (parent_maps);
> +    });
>     }
>
>   finalizers.start ();
> diff --git a/gdb/dwarf2/read.c b/gdb/dwarf2/read.c
> index 6e96afe65e16..a6f3aba6ec28 100644
> --- a/gdb/dwarf2/read.c
> +++ b/gdb/dwarf2/read.c
> @@ -52,6 +52,7 @@
> #include "event-top.h"
> #include "exceptions.h"
> #include "gdbsupport/task-group.h"
> +#include "maint.h"
> #include "symtab.h"
> #include "gdbtypes.h"
> #include "objfiles.h"
> @@ -3509,6 +3510,8 @@ static void
> process_skeletonless_type_units (dwarf2_per_objfile *per_objfile,
>                 cooked_index_worker_result *storage)
> {
> +  scoped_time_it time_it ("DWARF skeletonless type units");
> +
>   /* Skeletonless TUs in DWP files without .gdb_index is not supported yet.  */
>   if (get_dwp_file (per_objfile) == nullptr)
>     for (const dwo_file_up &file : per_objfile->per_bfd->dwo_files)
> @@ -3671,6 +3674,7 @@ cooked_index_worker_debug_info::do_reading ()
>       gdb_assert (iter != last);
>       workers.add_task ([this, task_count, iter, last] ()
>     {
> +      scoped_time_it time_it ("DWARF indexing worker");
>       process_cus (task_count, iter, last);
>     });
>
> diff --git a/gdb/maint.c b/gdb/maint.c
> index 59479e30aac2..5732919c0237 100644
> --- a/gdb/maint.c
> +++ b/gdb/maint.c
> @@ -1152,6 +1152,9 @@ scoped_time_it::scoped_time_it (const char *what)
>
> scoped_time_it::~scoped_time_it ()
> {
> +  if (!m_enabled)
> +    return;
> +
>   namespace chr = std::chrono;
>   auto end_wall = chr::steady_clock::now ();
>
> @@ -1167,10 +1170,10 @@ scoped_time_it::~scoped_time_it ()
>   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);
> +  gdb_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.  */

Shouldn't these 2 hunks of scoped_time_it be part of the previous patch?


> diff --git a/gdb/minsyms.c b/gdb/minsyms.c
> index 649a9f17c3e0..49d3c04fe90c 100644
> --- a/gdb/minsyms.c
> +++ b/gdb/minsyms.c
> @@ -37,6 +37,7 @@
>
>
> #include <ctype.h>
> +#include "maint.h"
> #include "symtab.h"
> #include "bfd.h"
> #include "filenames.h"
> @@ -1481,6 +1482,8 @@ minimal_symbol_reader::install ()
>       gdb::parallel_for_each (10, &msymbols[0], &msymbols[mcount],
>     [&] (minimal_symbol *start, minimal_symbol *end)
>     {
> +      scoped_time_it time_it ("minsyms install worker");
> +
>       for (minimal_symbol *msym = start; msym < end; ++msym)
>         {
>           size_t idx = msym - msymbols;
>
> --
> 2.49.0


Hannes
Simon Marchi April 11, 2025, 8:45 p.m. UTC | #2 
On 4/11/25 2:47 PM, Hannes Domani wrote:
>  Am Freitag, 11. April 2025 um 20:36:57 MESZ hat <simon.marchi@polymtl.ca> Folgendes geschrieben:
> 
>> From: Simon Marchi <simon.marchi@polymtl.ca>
>>
>> I'm investigating some issues where GDB takes a lot of time to start
>> up (read: for the DWARF index to be ready to do anything useful).
>> Adding those scoped_time_it instances helped me gain some insights about
>> where GDB spends time.  I think they would be useful to have upstream,
>> to make investigating future problems easier.  It would also be useful
>> to be able to give some numbers in the commit messages.
>>
>> Here's an example of what GDB outputs:
>>
>>      Time for "minsyms install worker": wall 0.045, user 0.040, sys 0.004, user+sys 0.044, 97.8 % CPU
>>      Time for "minsyms install worker": wall 0.511, user 0.457, sys 0.048, user+sys 0.505, 98.8 % CPU
>>      Time for "minsyms install worker": wall 1.513, user 1.389, sys 0.111, user+sys 1.500, 99.1 % CPU
>>      Time for "minsyms install worker": wall 1.688, user 1.451, sys 0.102, user+sys 1.553, 92.0 % CPU
>>      Time for "minsyms install worker": wall 1.897, user 1.518, sys 0.089, user+sys 1.607, 84.7 % CPU
>>      Time for "minsyms install worker": wall 2.811, user 2.558, sys 0.231, user+sys 2.789, 99.2 % CPU
>>      Time for "minsyms install worker": wall 3.257, user 3.049, sys 0.188, user+sys 3.237, 99.4 % CPU
>>      Time for "minsyms install worker": wall 3.617, user 3.089, sys 0.211, user+sys 3.300, 91.2 % CPU
>>      Time for "DWARF indexing worker": wall 19.517, user 0.894, sys 0.075, user+sys 0.969, 5.0 % CPU
>>      Time for "DWARF indexing worker": wall 19.807, user 0.891, sys 0.086, user+sys 0.977, 4.9 % CPU
>>      Time for "DWARF indexing worker": wall 20.270, user 1.559, sys 0.119, user+sys 1.678, 8.3 % CPU
>>      Time for "DWARF indexing worker": wall 20.329, user 1.878, sys 0.147, user+sys 2.025, 10.0 % CPU
>>      Time for "DWARF indexing worker": wall 20.848, user 3.483, sys 0.224, user+sys 3.707, 17.8 % CPU
>>      Time for "DWARF indexing worker": wall 21.088, user 4.285, sys 0.295, user+sys 4.580, 21.7 % CPU
>>      Time for "DWARF indexing worker": wall 21.109, user 4.501, sys 0.274, user+sys 4.775, 22.6 % CPU
>>      Time for "DWARF indexing worker": wall 21.198, user 5.087, sys 0.319, user+sys 5.406, 25.5 % CPU
>>      Time for "DWARF skeletonless type units": wall 4.024, user 3.858, sys 0.115, user+sys 3.973, 98.7 % CPU
>>      Time for "DWARF add parent map": wall 0.092, user 0.086, sys 0.004, user+sys 0.090, 97.8 % CPU
>>      Time for "DWARF finalize worker": wall 0.278, user 0.241, sys 0.009, user+sys 0.250, 89.9 % CPU
>>      Time for "DWARF finalize worker": wall 0.307, user 0.304, sys 0.000, user+sys 0.304, 99.0 % CPU
>>      Time for "DWARF finalize worker": wall 0.727, user 0.719, sys 0.000, user+sys 0.719, 98.9 % CPU
>>      Time for "DWARF finalize worker": wall 0.913, user 0.901, sys 0.003, user+sys 0.904, 99.0 % CPU
>>      Time for "DWARF finalize worker": wall 0.776, user 0.767, sys 0.004, user+sys 0.771, 99.4 % CPU
>>      Time for "DWARF finalize worker": wall 1.897, user 1.869, sys 0.006, user+sys 1.875, 98.8 % CPU
>>      Time for "DWARF finalize worker": wall 2.534, user 2.512, sys 0.005, user+sys 2.517, 99.3 % CPU
>>      Time for "DWARF finalize worker": wall 2.607, user 2.583, sys 0.006, user+sys 2.589, 99.3 % CPU
>>      Time for "DWARF finalize worker": wall 3.142, user 3.094, sys 0.022, user+sys 3.116, 99.2 % CPU
>>
>> Change-Id: I9453589b9005c3226499428ae9cab9f4a8c22904
>> ---
>> gdb/dwarf2/cooked-index-worker.c |  9 +++++++--
>> gdb/dwarf2/cooked-index.c        |  7 ++++++-
>> gdb/dwarf2/read.c                |  4 ++++
>> gdb/maint.c                      | 11 +++++++----
>> gdb/minsyms.c                    |  3 +++
>> 5 files changed, 27 insertions(+), 7 deletions(-)
>>
>> diff --git a/gdb/dwarf2/cooked-index-worker.c b/gdb/dwarf2/cooked-index-worker.c
>> index da51a8c72e81..5d7fc462a05d 100644
>> --- a/gdb/dwarf2/cooked-index-worker.c
>> +++ b/gdb/dwarf2/cooked-index-worker.c
>> @@ -20,6 +20,7 @@
>> #include "dwarf2/cooked-index-worker.h"
>> #include "dwarf2/cooked-index.h"
>> #include "gdbsupport/thread-pool.h"
>> +#include "maint.h"
>> #include "run-on-main-thread.h"
>> #include "event-top.h"
>> #include "exceptions.h"
>> @@ -244,8 +245,12 @@ cooked_index_worker::write_to_cache (const cooked_index *idx)
>> void
>> cooked_index_worker::done_reading ()
>> {
>> -  for (auto &one_result : m_results)
>> -    m_all_parents_map.add_map (*one_result.get_parent_map ());
>> +  {
>> +    scoped_time_it time_it ("DWARF add parent map");
>> +
>> +    for (auto &one_result : m_results)
>> +      m_all_parents_map.add_map (*one_result.get_parent_map ());
>> +  }
>>
>>    dwarf2_per_bfd *per_bfd = m_per_objfile->per_bfd;
>>    cooked_index *table
>> diff --git a/gdb/dwarf2/cooked-index.c b/gdb/dwarf2/cooked-index.c
>> index 7948ffac2362..2c7e31e5676c 100644
>> --- a/gdb/dwarf2/cooked-index.c
>> +++ b/gdb/dwarf2/cooked-index.c
>> @@ -21,6 +21,7 @@
>> #include "dwarf2/read.h"
>> #include "dwarf2/stringify.h"
>> #include "event-top.h"
>> +#include "maint.h"
>> #include "observable.h"
>> #include "run-on-main-thread.h"
>> #include "gdbsupport/task-group.h"
>> @@ -101,7 +102,11 @@ cooked_index::set_contents ()
>>      {
>>        auto this_shard = shard.get ();
>>        const parent_map_map *parent_maps = m_state->get_parent_map_map ();
>> -      finalizers.add_task ([=] () { this_shard->finalize (parent_maps); });
>> +      finalizers.add_task ([=] ()
>> +    {
>> +      scoped_time_it time_it ("DWARF finalize worker");
>> +      this_shard->finalize (parent_maps);
>> +    });
>>      }
>>
>>    finalizers.start ();
>> diff --git a/gdb/dwarf2/read.c b/gdb/dwarf2/read.c
>> index 6e96afe65e16..a6f3aba6ec28 100644
>> --- a/gdb/dwarf2/read.c
>> +++ b/gdb/dwarf2/read.c
>> @@ -52,6 +52,7 @@
>> #include "event-top.h"
>> #include "exceptions.h"
>> #include "gdbsupport/task-group.h"
>> +#include "maint.h"
>> #include "symtab.h"
>> #include "gdbtypes.h"
>> #include "objfiles.h"
>> @@ -3509,6 +3510,8 @@ static void
>> process_skeletonless_type_units (dwarf2_per_objfile *per_objfile,
>>                  cooked_index_worker_result *storage)
>> {
>> +  scoped_time_it time_it ("DWARF skeletonless type units");
>> +
>>    /* Skeletonless TUs in DWP files without .gdb_index is not supported yet.  */
>>    if (get_dwp_file (per_objfile) == nullptr)
>>      for (const dwo_file_up &file : per_objfile->per_bfd->dwo_files)
>> @@ -3671,6 +3674,7 @@ cooked_index_worker_debug_info::do_reading ()
>>        gdb_assert (iter != last);
>>        workers.add_task ([this, task_count, iter, last] ()
>>      {
>> +      scoped_time_it time_it ("DWARF indexing worker");
>>        process_cus (task_count, iter, last);
>>      });
>>
>> diff --git a/gdb/maint.c b/gdb/maint.c
>> index 59479e30aac2..5732919c0237 100644
>> --- a/gdb/maint.c
>> +++ b/gdb/maint.c
>> @@ -1152,6 +1152,9 @@ scoped_time_it::scoped_time_it (const char *what)
>>
>> scoped_time_it::~scoped_time_it ()
>> {
>> +  if (!m_enabled)
>> +    return;
>> +
>>    namespace chr = std::chrono;
>>    auto end_wall = chr::steady_clock::now ();
>>
>> @@ -1167,10 +1170,10 @@ scoped_time_it::~scoped_time_it ()
>>    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);
>> +  gdb_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.  */
> 
> Shouldn't these 2 hunks of scoped_time_it be part of the previous patch?

Ah yes sorry.  A last minute change that I messed up.  This will require
a v2.

Simon
diff mbox series

Patch

diff --git a/gdb/dwarf2/cooked-index-worker.c b/gdb/dwarf2/cooked-index-worker.c
index da51a8c72e81..5d7fc462a05d 100644
--- a/gdb/dwarf2/cooked-index-worker.c
+++ b/gdb/dwarf2/cooked-index-worker.c
@@ -20,6 +20,7 @@ 
 #include "dwarf2/cooked-index-worker.h"
 #include "dwarf2/cooked-index.h"
 #include "gdbsupport/thread-pool.h"
+#include "maint.h"
 #include "run-on-main-thread.h"
 #include "event-top.h"
 #include "exceptions.h"
@@ -244,8 +245,12 @@  cooked_index_worker::write_to_cache (const cooked_index *idx)
 void
 cooked_index_worker::done_reading ()
 {
-  for (auto &one_result : m_results)
-    m_all_parents_map.add_map (*one_result.get_parent_map ());
+  {
+    scoped_time_it time_it ("DWARF add parent map");
+
+    for (auto &one_result : m_results)
+      m_all_parents_map.add_map (*one_result.get_parent_map ());
+  }
 
   dwarf2_per_bfd *per_bfd = m_per_objfile->per_bfd;
   cooked_index *table
diff --git a/gdb/dwarf2/cooked-index.c b/gdb/dwarf2/cooked-index.c
index 7948ffac2362..2c7e31e5676c 100644
--- a/gdb/dwarf2/cooked-index.c
+++ b/gdb/dwarf2/cooked-index.c
@@ -21,6 +21,7 @@ 
 #include "dwarf2/read.h"
 #include "dwarf2/stringify.h"
 #include "event-top.h"
+#include "maint.h"
 #include "observable.h"
 #include "run-on-main-thread.h"
 #include "gdbsupport/task-group.h"
@@ -101,7 +102,11 @@  cooked_index::set_contents ()
     {
       auto this_shard = shard.get ();
       const parent_map_map *parent_maps = m_state->get_parent_map_map ();
-      finalizers.add_task ([=] () { this_shard->finalize (parent_maps); });
+      finalizers.add_task ([=] ()
+	{
+	  scoped_time_it time_it ("DWARF finalize worker");
+	  this_shard->finalize (parent_maps);
+	});
     }
 
   finalizers.start ();
diff --git a/gdb/dwarf2/read.c b/gdb/dwarf2/read.c
index 6e96afe65e16..a6f3aba6ec28 100644
--- a/gdb/dwarf2/read.c
+++ b/gdb/dwarf2/read.c
@@ -52,6 +52,7 @@ 
 #include "event-top.h"
 #include "exceptions.h"
 #include "gdbsupport/task-group.h"
+#include "maint.h"
 #include "symtab.h"
 #include "gdbtypes.h"
 #include "objfiles.h"
@@ -3509,6 +3510,8 @@  static void
 process_skeletonless_type_units (dwarf2_per_objfile *per_objfile,
 				 cooked_index_worker_result *storage)
 {
+  scoped_time_it time_it ("DWARF skeletonless type units");
+
   /* Skeletonless TUs in DWP files without .gdb_index is not supported yet.  */
   if (get_dwp_file (per_objfile) == nullptr)
     for (const dwo_file_up &file : per_objfile->per_bfd->dwo_files)
@@ -3671,6 +3674,7 @@  cooked_index_worker_debug_info::do_reading ()
       gdb_assert (iter != last);
       workers.add_task ([this, task_count, iter, last] ()
 	{
+	  scoped_time_it time_it ("DWARF indexing worker");
 	  process_cus (task_count, iter, last);
 	});
 
diff --git a/gdb/maint.c b/gdb/maint.c
index 59479e30aac2..5732919c0237 100644
--- a/gdb/maint.c
+++ b/gdb/maint.c
@@ -1152,6 +1152,9 @@  scoped_time_it::scoped_time_it (const char *what)
 
 scoped_time_it::~scoped_time_it ()
 {
+  if (!m_enabled)
+    return;
+
   namespace chr = std::chrono;
   auto end_wall = chr::steady_clock::now ();
 
@@ -1167,10 +1170,10 @@  scoped_time_it::~scoped_time_it ()
   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);
+  gdb_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.  */
diff --git a/gdb/minsyms.c b/gdb/minsyms.c
index 649a9f17c3e0..49d3c04fe90c 100644
--- a/gdb/minsyms.c
+++ b/gdb/minsyms.c
@@ -37,6 +37,7 @@ 
 
 
 #include <ctype.h>
+#include "maint.h"
 #include "symtab.h"
 #include "bfd.h"
 #include "filenames.h"
@@ -1481,6 +1482,8 @@  minimal_symbol_reader::install ()
       gdb::parallel_for_each (10, &msymbols[0], &msymbols[mcount],
 	 [&] (minimal_symbol *start, minimal_symbol *end)
 	 {
+	   scoped_time_it time_it ("minsyms install worker");
+
 	   for (minimal_symbol *msym = start; msym < end; ++msym)
 	     {
 	       size_t idx = msym - msymbols;