gdb/dwarf: add logging for CU expansion

I was trying to get an understanding of which CUs were expanded when,
and how much time it was taking.  I wrote this patch to add some logging
related to that, and I think it would be useful to have upstream, to
better understand performance problems related to over-eager CU
expansion, for example.

 - add DWARF_READ_SCOPED_DEBUG_START_END
 - use it in process_queue, to wrap the related expansion messages
   together
 - add a message in maybe_queue_comp_unit when enqueuing a comp unit
 - add timing information to messages in process_queue, indicating how
   much time it took to expand a given symtab
 - count the number of expansions done in a single call to process_queue

    [dwarf-read] process_queue: start: Expanding one or more symtabs of objfile /home/smarchi/build/binutils-gdb/gdb/testsuite/outputs/gdb.dwarf2/dw-form-ref-addr-with-type-units/dw-form-ref-addr-with-type-units ...
      [dwarf-read] process_queue: Expanding symtab of CU at offset 0xc
      [dwarf-read] maybe_queue_comp_unit: Queuing CU for expansion: section offset = 0x38b, queue size = 2
      [dwarf-read] process_queue: Done expanding CU at offset 0xc, took 0.001s
      [dwarf-read] process_queue: Expanding symtab of CU at offset 0x38b
      [dwarf-read] process_queue: Done expanding CU at offset 0x38b, took 0.000s
      [dwarf-read] process_queue: Done expanding 2 symtabs.
    [dwarf-read] process_queue: end: Expanding one or more symtabs of objfile /home/smarchi/build/binutils-gdb/gdb/testsuite/outputs/gdb.dwarf2/dw-form-ref-addr-with-type-units/dw-form-ref-addr-with-type-units ...

Change-Id: I5237d50e0c1d06be33ea83a9120b5fe1cf7ab8c2
Approved-By: Tom Tromey <tom@tromey.com>

1 files changed, 36 insertions, 6 deletions

diff --git a/gdb/dwarf2/read.c b/gdb/dwarf2/read.c
index e5bb4e2..4e30a56 100644
--- a/gdb/dwarf2/read.c
+++ b/gdb/dwarf2/read.c
@@ -113,6 +113,12 @@ static unsigned int dwarf_read_debug = 0;
   debug_prefixed_printf_cond (dwarf_read_debug >= 2, "dwarf-read", fmt, \
 			      ##__VA_ARGS__)
 
+/* Print "dwarf-read" start/end debug statements.  */
+
+#define DWARF_READ_SCOPED_DEBUG_START_END(fmt, ...)                           \
+  scoped_debug_start_end ([] { return dwarf_read_debug >= 1; }, "dwarf-read", \
+			  fmt, ##__VA_ARGS__)
+
 /* When non-zero, dump DIEs after they are read in.  */
 static unsigned int dwarf_die_debug = 0;
 
@@ -4715,6 +4721,12 @@ maybe_queue_comp_unit (struct dwarf2_cu *dependent_cu,
       /* Add it to the queue.  */
       queue_comp_unit (per_cu, per_objfile, pretend_language);
       queued = true;
+
+      dwarf_read_debug_printf ("Queuing CU for expansion: "
+			       "section offset = 0x%" PRIx64 ", "
+			       "queue size = %zu",
+			       to_underlying (per_cu->sect_off),
+			       per_objfile->queue->size ());
     }
 
   /* If the compilation unit is already loaded, just mark it as
@@ -4733,8 +4745,11 @@ maybe_queue_comp_unit (struct dwarf2_cu *dependent_cu,
 static void
 process_queue (dwarf2_per_objfile *per_objfile)
 {
-  dwarf_read_debug_printf ("Expanding one or more symtabs of objfile %s ...",
-			   objfile_name (per_objfile->objfile));
+  DWARF_READ_SCOPED_DEBUG_START_END
+    ("Expanding one or more symtabs of objfile %s ...",
+     objfile_name (per_objfile->objfile));
+
+  unsigned int expanded_count = 0;
 
   /* The queue starts out with one item, but following a DIE reference
      may load a new CU, adding it to the end of the queue.  */
@@ -4750,8 +4765,11 @@ process_queue (dwarf2_per_objfile *per_objfile)
 	  /* Skip dummy CUs.  */
 	  if (cu != nullptr)
 	    {
+	      namespace chr = std::chrono;
+
 	      unsigned int debug_print_threshold;
 	      char buf[100];
+	      std::optional<chr::time_point<chr::steady_clock>> start_time;
 
 	      if (per_cu->is_debug_types)
 		{
@@ -4773,7 +4791,12 @@ process_queue (dwarf2_per_objfile *per_objfile)
 		}
 
 	      if (dwarf_read_debug >= debug_print_threshold)
-		dwarf_read_debug_printf ("Expanding symtab of %s", buf);
+		{
+		  dwarf_read_debug_printf ("Expanding symtab of %s", buf);
+		  start_time = chr::steady_clock::now ();
+		}
+
+	      ++expanded_count;
 
 	      if (per_cu->is_debug_types)
 		process_full_type_unit (cu, item.pretend_language);
@@ -4781,7 +4804,15 @@ process_queue (dwarf2_per_objfile *per_objfile)
 		process_full_comp_unit (cu, item.pretend_language);
 
 	      if (dwarf_read_debug >= debug_print_threshold)
-		dwarf_read_debug_printf ("Done expanding %s", buf);
+		{
+		  const auto end_time = chr::steady_clock::now ();
+		  const auto time_spent = end_time - *start_time;
+		  const auto ms
+		    = chr::duration_cast<chr::milliseconds> (time_spent);
+
+		  dwarf_read_debug_printf ("Done expanding %s, took %.3fs", buf,
+					   ms.count () / 1000.0);
+		}
 	    }
 	}
 
@@ -4789,8 +4820,7 @@ process_queue (dwarf2_per_objfile *per_objfile)
       per_objfile->queue->pop ();
     }
 
-  dwarf_read_debug_printf ("Done expanding symtabs of %s.",
-			   objfile_name (per_objfile->objfile));
+  dwarf_read_debug_printf ("Done expanding %u symtabs.", expanded_count);
 }
 
 /* Load the DIEs associated with PER_CU into memory.