From patchwork Wed Nov 8 23:48:12 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Pedro Alves X-Patchwork-Id: 24170 Received: (qmail 126886 invoked by alias); 8 Nov 2017 23:48:28 -0000 Mailing-List: contact gdb-patches-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Unsubscribe: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-patches-owner@sourceware.org Delivered-To: mailing list gdb-patches@sourceware.org Received: (qmail 125254 invoked by uid 89); 8 Nov 2017 23:48:17 -0000 Authentication-Results: sourceware.org; auth=none X-Virus-Found: No X-Spam-SWARE-Status: No, score=-26.9 required=5.0 tests=BAYES_00, GIT_PATCH_0, GIT_PATCH_1, GIT_PATCH_2, GIT_PATCH_3, RP_MATCHES_RCVD, SPF_HELO_PASS autolearn=ham version=3.3.2 spammy=Prime X-HELO: mx1.redhat.com Received: from mx1.redhat.com (HELO mx1.redhat.com) (209.132.183.28) by sourceware.org (qpsmtpd/0.93/v0.84-503-g423c35a) with ESMTP; Wed, 08 Nov 2017 23:48:15 +0000 Received: from smtp.corp.redhat.com (int-mx02.intmail.prod.int.phx2.redhat.com [10.5.11.12]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 3CBA84E90B for ; Wed, 8 Nov 2017 23:48:14 +0000 (UTC) Received: from cascais.lan (ovpn04.gateway.prod.ext.ams2.redhat.com [10.39.146.4]) by smtp.corp.redhat.com (Postfix) with ESMTP id 92D0760BEC for ; Wed, 8 Nov 2017 23:48:13 +0000 (UTC) From: Pedro Alves To: gdb-patches@sourceware.org Subject: [pushed] Avoid expensive complaint calls when complaints are disabled Date: Wed, 8 Nov 2017 23:48:12 +0000 Message-Id: <1510184892-15400-1-git-send-email-palves@redhat.com> Running perf on "gdb -nx -readnow -batch gdb", I'm seeing a lot of time (24%.75!) spent in gettext, via complaints. 'perf report -g' shows: - 86.23% 0.00% gdb gdb [.] gdb_main - gdb_main - 85.60% catch_command_errors symbol_file_add_main_adapter symbol_file_add_main symbol_file_add_main_1 symbol_file_add - symbol_file_add_with_addrs - 84.31% dw2_expand_all_symtabs - dw2_instantiate_symtab - 83.79% dw2_do_instantiate_symtab - 70.85% process_die - 41.11% dwarf_decode_macros - 41.09% dwarf_decode_macro_bytes - 39.74% dwarf_decode_macro_bytes >>>>>>>>>>>>>>>>>>>>>>> + 24.75% __dcigettext <<<<<<< + 7.37% macro_define_object_internal + 3.16% macro_define_function 0.77% splay_tree_insert + 0.76% savestring + 0.58% free 0.53% read_indirect_string_at_offset_from 0.54% macro_define_object_internal 0.51% macro_start_file + 25.57% process_die + 4.07% dwarf_decode_lines + 4.28% compute_delayed_physnames + 3.85% end_symtab_from_static_block + 3.38% load_cu + 1.29% end_symtab_get_static_block + 0.52% do_my_cleanups + 1.29% read_symbols + 0.54% gdb_init The problem is that we're always computing the arguments to pass to complaint, including passing the format strings through gettext, even when complaints are disabled. As seen above, gettext can be quite expensive. Fix this by wrapping complaint in a macro that skips the real complaint call when complaints are disabled. This improves "gdb -nx -readnow -batch gdb" from ~11.0s => ~7.8s with -O2 -g3, and ~6.0s => ~5.3s with -O2 -g. w/ gcc 5.3.1, on x86_64, for me. gdb/ChangeLog: 2017-11-08 Pedro Alves * complaints.c (stop_whining): Make extern. (complaint): Rename to ... (complaint_internal): ... this. * complaints.h (complaint): Rename to ... (complaint_internal): ... this. (complaint): Reimplement as macro around complaint_internal. gdb/testsuite/ChangeLog: 2017-11-08 Pedro Alves * gdb.gdb/complaints.exp (test_initial_complaints) (test_serial_complaints, test_short_complaints): Call complaint_internal instead of complaint. --- gdb/testsuite/ChangeLog | 6 ++++++ gdb/complaints.c | 4 ++-- gdb/complaints.h | 23 +++++++++++++++++++---- gdb/testsuite/gdb.gdb/complaints.exp | 27 +++++++++++++++++---------- 4 files changed, 44 insertions(+), 16 deletions(-) diff --git a/gdb/testsuite/ChangeLog b/gdb/testsuite/ChangeLog index 2f14e5c..6349259 100644 --- a/gdb/testsuite/ChangeLog +++ b/gdb/testsuite/ChangeLog @@ -1,3 +1,9 @@ +2017-11-08 Pedro Alves + + * gdb.gdb/complaints.exp (test_initial_complaints) + (test_serial_complaints, test_short_complaints): Call + complaint_internal instead of complaint. + 2017-11-08 Djordje Todorovic * gdb.threads/tls-core.c: New file. diff --git a/gdb/complaints.c b/gdb/complaints.c index 58b6b7b..8fd2f2b 100644 --- a/gdb/complaints.c +++ b/gdb/complaints.c @@ -148,7 +148,7 @@ find_complaint (struct complaints *complaints, const char *file, before we stop whining about it? Default is no whining at all, since so many systems have ill-constructed symbol files. */ -static int stop_whining = 0; +int stop_whining = 0; /* Print a complaint, and link the complaint block into a chain for later handling. */ @@ -236,7 +236,7 @@ vcomplaint (struct complaints **c, const char *file, } void -complaint (struct complaints **complaints, const char *fmt, ...) +complaint_internal (struct complaints **complaints, const char *fmt, ...) { va_list args; diff --git a/gdb/complaints.h b/gdb/complaints.h index 54c2b18..62885e9 100644 --- a/gdb/complaints.h +++ b/gdb/complaints.h @@ -28,10 +28,25 @@ struct complaints; /* Predefined categories. */ extern struct complaints *symfile_complaints; -/* Register a complaint. */ -extern void complaint (struct complaints **complaints, - const char *fmt, - ...) ATTRIBUTE_PRINTF (2, 3); +/* Helper for complaint. */ +extern void complaint_internal (struct complaints **complaints, + const char *fmt, ...) + ATTRIBUTE_PRINTF (2, 3); + +/* Register a complaint. This is a macro around complaint_internal to + avoid computing complaint's arguments when complaints are disabled. + Running FMT via gettext [i.e., _(FMT)] can be quite expensive, for + example. */ +#define complaint(COMPLAINTS, FMT, ...) \ + do \ + { \ + extern int stop_whining; \ + \ + if (stop_whining > 0) \ + complaint_internal (COMPLAINTS, FMT, ##__VA_ARGS__); \ + } \ + while (0) + extern void internal_complaint (struct complaints **complaints, const char *file, int line, const char *fmt, diff --git a/gdb/testsuite/gdb.gdb/complaints.exp b/gdb/testsuite/gdb.gdb/complaints.exp index c33fb6e..0b03205 100644 --- a/gdb/testsuite/gdb.gdb/complaints.exp +++ b/gdb/testsuite/gdb.gdb/complaints.exp @@ -58,16 +58,18 @@ proc test_initial_complaints { } { gdb_test "set stop_whining = 2" # Prime the system - gdb_test_stdio "call complaint (&symfile_complaints, \"Register a complaint\")" \ - "During symbol reading, Register a complaint." + gdb_test_stdio \ + "call complaint_internal (&symfile_complaints, \"Register a complaint\")" \ + "During symbol reading, Register a complaint." # Check that the complaint was inserted and where gdb_test "print symfile_complaints->root->fmt" \ ".\[0-9\]+ =.*\"Register a complaint\"" # Re-issue the first message #1 - gdb_test_stdio "call complaint (&symfile_complaints, symfile_complaints->root->fmt)" \ - "During symbol reading, Register a complaint." + gdb_test_stdio \ + "call complaint_internal (&symfile_complaints, symfile_complaints->root->fmt)" \ + "During symbol reading, Register a complaint." # Check that there is only one thing in the list. How the boolean # result is output depends on whether GDB is built as a C or C++ @@ -76,8 +78,9 @@ proc test_initial_complaints { } { ".\[0-9\]+ = \(1|true\)" "list has one entry" # Add a second complaint, expect it - gdb_test_stdio "call complaint (&symfile_complaints, \"Testing! Testing! Testing!\")" \ - "During symbol reading, Testing. Testing. Testing.." + gdb_test_stdio \ + "call complaint_internal (&symfile_complaints, \"Testing! Testing! Testing!\")" \ + "During symbol reading, Testing. Testing. Testing.." return 0 } @@ -86,12 +89,14 @@ proc test_serial_complaints { } { gdb_test_exact "call clear_complaints (&symfile_complaints, 1, 0)" "" "serial start" # Prime the system - test_complaint "call complaint (&symfile_complaints, \"serial line 1\")" \ + test_complaint \ + "call complaint_internal (&symfile_complaints, \"serial line 1\")" \ "During symbol reading...serial line 1..." \ "serial line 1" # Add a second complaint, expect it - test_complaint "call complaint (&symfile_complaints, \"serial line 2\")" \ + test_complaint \ + "call complaint_internal (&symfile_complaints, \"serial line 2\")" \ "serial line 2..." \ "serial line 2" @@ -109,12 +114,14 @@ proc test_short_complaints { } { gdb_test_exact "call clear_complaints (&symfile_complaints, 1, 1)" "" "short start" # Prime the system - test_complaint "call complaint (&symfile_complaints, \"short line 1\")" \ + test_complaint \ + "call complaint_internal (&symfile_complaints, \"short line 1\")" \ "short line 1..." \ "short line 1" # Add a second complaint, expect it - test_complaint "call complaint (&symfile_complaints, \"short line 2\")" \ + test_complaint \ + "call complaint_internal (&symfile_complaints, \"short line 2\")" \ "short line 2..." \ "short line 2"