From patchwork Fri Apr 11 18:21:32 2025 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Simon Marchi X-Patchwork-Id: 110297 Return-Path: X-Original-To: patchwork@sourceware.org Delivered-To: patchwork@sourceware.org Received: from server2.sourceware.org (localhost [IPv6:::1]) by sourceware.org (Postfix) with ESMTP id E45EB382EF09 for ; Fri, 11 Apr 2025 18:36:50 +0000 (GMT) DKIM-Filter: OpenDKIM Filter v2.11.0 sourceware.org E45EB382EF09 Authentication-Results: sourceware.org; dkim=pass (1024-bit key, unprotected) header.d=polymtl.ca header.i=@polymtl.ca header.a=rsa-sha256 header.s=default header.b=si6M8F9R X-Original-To: gdb-patches@sourceware.org Delivered-To: gdb-patches@sourceware.org Received: from smtp.polymtl.ca (smtp.polymtl.ca [132.207.4.11]) by sourceware.org (Postfix) with ESMTPS id DD8DB3858405 for ; Fri, 11 Apr 2025 18:28:42 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.2 sourceware.org DD8DB3858405 Authentication-Results: sourceware.org; dmarc=pass (p=none dis=none) header.from=polymtl.ca Authentication-Results: sourceware.org; spf=pass smtp.mailfrom=polymtl.ca ARC-Filter: OpenARC Filter v1.0.0 sourceware.org DD8DB3858405 Authentication-Results: server2.sourceware.org; arc=none smtp.remote-ip=132.207.4.11 ARC-Seal: i=1; a=rsa-sha256; d=sourceware.org; s=key; t=1744396122; cv=none; b=vx/GasJq30Wa686bpOC5xsK2JcNvP49Q8q1bCWCHrG+d/7LUDV8UXCV7g45UEhzMDYVyKzgH7u0UYPfxmeQft0SHOEsOf65boARnYMVhcnM4+OYvtHRV0vTHRLHZen7J91veinSrx8PQi2eNDz1mHvdqblr0x2pkVv7YLh8M7Kw= ARC-Message-Signature: i=1; a=rsa-sha256; d=sourceware.org; s=key; t=1744396122; c=relaxed/simple; bh=JhlBVePjZwTLsxxbdwvD94rjRHjYjHbv7IsUdhqMzbs=; h=DKIM-Signature:From:To:Subject:Date:Message-ID:MIME-Version; b=Fi/ut62PLOoHf0w8C3AxjhrtAAIvbiVFv7BJaSjtTvNz6X3kGLyyMCsTALjtG21FAU3gcUrHALpxdyXUM1b8bKkM4sheX3GulcCTL/tpaLSM64LY0jUL0SQ82HEszbrP46uDNqM00a8PN9//d+TI6g6Ah81khpPkcGtrRtZEBhQ= ARC-Authentication-Results: i=1; server2.sourceware.org DKIM-Filter: OpenDKIM Filter v2.11.0 sourceware.org DD8DB3858405 Received: from simark.ca (simark.ca [158.69.221.121]) (authenticated bits=0) by smtp.polymtl.ca (8.14.7/8.14.7) with ESMTP id 53BISbLb103637 (version=TLSv1/SSLv3 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Fri, 11 Apr 2025 14:28:42 -0400 DKIM-Filter: OpenDKIM Filter v2.11.0 smtp.polymtl.ca 53BISbLb103637 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=polymtl.ca; s=default; t=1744396122; bh=rwFB/OEIoS4kM03XeYHcTpKNh4im+Sw0oCW3PThbtfg=; h=From:To:Cc:Subject:Date:In-Reply-To:From; b=si6M8F9RllyF/NWRaqsrkYHxge5A7n6lV+RGOTOcOGu2d5z1PE0kkZ5k7HIEceG9k GNQykcsXXpM3jbCiyJnmFVMP6Q82VdmCjNIxqQ7BnJs60Eq9XNjNZsLEOk7+1QAp5j /8RCNhvC1pIYjxvAzcxvJlHxONND2Te32t0uJ+sQ= Received: by simark.ca (Postfix, from userid 112) id DEA691E11C; Fri, 11 Apr 2025 14:21:55 -0400 (EDT) X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on server2.sourceware.org X-Spam-Level: X-Spam-Status: No, score=-3187.8 required=5.0 tests=BAYES_00, DKIM_SIGNED, DKIM_VALID, DKIM_VALID_AU, DKIM_VALID_EF, GIT_PATCH_0, RCVD_IN_MSPIKE_H3, RCVD_IN_MSPIKE_WL, SPF_HELO_PASS, SPF_NONE, TXREP autolearn=ham autolearn_force=no version=3.4.6 Received: from simark.localdomain (modemcable238.237-201-24.mc.videotron.ca [24.201.237.238]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature ECDSA (prime256v1) server-digest SHA256) (No client certificate requested) by simark.ca (Postfix) with ESMTPSA id 6BBAF1E0C3; Fri, 11 Apr 2025 14:21:52 -0400 (EDT) From: simon.marchi@polymtl.ca To: gdb-patches@sourceware.org Cc: Simon Marchi Subject: [PATCH 3/3] gdb: add some scoped_time_its to profile startup time Date: Fri, 11 Apr 2025 14:21:32 -0400 Message-ID: <20250411182151.1427430-3-simon.marchi@polymtl.ca> X-Mailer: git-send-email 2.49.0 In-Reply-To: <20250411182151.1427430-1-simon.marchi@polymtl.ca> References: <20250411182151.1427430-1-simon.marchi@polymtl.ca> MIME-Version: 1.0 X-Poly-FromMTA: (simark.ca [158.69.221.121]) at Fri, 11 Apr 2025 18:28:37 +0000 X-BeenThere: gdb-patches@sourceware.org X-Mailman-Version: 2.1.30 Precedence: list List-Id: Gdb-patches mailing list List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: gdb-patches-bounces~patchwork=sourceware.org@sourceware.org From: Simon Marchi 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 (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 +#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;