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>
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.
