gdb: add some scoped_time_its to profile startup time

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
Approved-By: Tom Tromey <tom@tromey.com>

diff --git a/gdb/dwarf2/cooked-index-worker.c b/gdb/dwarf2/cooked-index-worker.c
index da51a8c72e81c31e04751840735d90a14cbfbe4e..5d7fc462a05dd4df19244c9cd922f16d0c980ad9 100644 (file)
--- 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 7948ffac23628ea9c7a52cfc4f3d0b46aa9d4458..2c7e31e5676cc6de7b50834e130a0b4ed42f2007 100644 (file)
--- 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 a177a056e1359a85acf8602839360117bc19f8f0..a48fb65566d0ec3e9583b79bef6e593f39f55182 100644 (file)
--- 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"
@@ -3515,6 +3516,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 (per_objfile->per_bfd->dwp_file == nullptr)
     for (const dwo_file_up &file : per_objfile->per_bfd->dwo_files)
@@ -3677,6 +3680,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/minsyms.c b/gdb/minsyms.c
index 9ac3145cb629de27ecc1e3021466f7fc47c0e4e7..124d96d90b5627cfdaf27e5c76d7a39b7be770e2 100644 (file)
--- 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;