Avoid expensive complaint calls when complaints are disabled

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  <palves@redhat.com>

	* 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  <palves@redhat.com>

	* gdb.gdb/complaints.exp (test_initial_complaints)
	(test_serial_complaints, test_short_complaints): Call
	complaint_internal instead of complaint.
This commit is contained in:
Pedro Alves 2017-11-08 23:42:11 +00:00
parent 333d0055f6
commit 62d7ae9234
4 changed files with 44 additions and 16 deletions

View File

@ -148,7 +148,7 @@ find_complaint (struct complaints *complaints, const char *file,
before we stop whining about it? Default is no whining at all, before we stop whining about it? Default is no whining at all,
since so many systems have ill-constructed symbol files. */ 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 /* Print a complaint, and link the complaint block into a chain for
later handling. */ later handling. */
@ -236,7 +236,7 @@ vcomplaint (struct complaints **c, const char *file,
} }
void void
complaint (struct complaints **complaints, const char *fmt, ...) complaint_internal (struct complaints **complaints, const char *fmt, ...)
{ {
va_list args; va_list args;

View File

@ -28,10 +28,25 @@ struct complaints;
/* Predefined categories. */ /* Predefined categories. */
extern struct complaints *symfile_complaints; extern struct complaints *symfile_complaints;
/* Register a complaint. */ /* Helper for complaint. */
extern void complaint (struct complaints **complaints, extern void complaint_internal (struct complaints **complaints,
const char *fmt, const char *fmt, ...)
...) ATTRIBUTE_PRINTF (2, 3); 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, extern void internal_complaint (struct complaints **complaints,
const char *file, int line, const char *file, int line,
const char *fmt, const char *fmt,

View File

@ -1,3 +1,9 @@
2017-11-08 Pedro Alves <palves@redhat.com>
* gdb.gdb/complaints.exp (test_initial_complaints)
(test_serial_complaints, test_short_complaints): Call
complaint_internal instead of complaint.
2017-11-08 Djordje Todorovic <djordje.todorovic@rt-rk.com> 2017-11-08 Djordje Todorovic <djordje.todorovic@rt-rk.com>
* gdb.threads/tls-core.c: New file. * gdb.threads/tls-core.c: New file.

View File

@ -58,16 +58,18 @@ proc test_initial_complaints { } {
gdb_test "set stop_whining = 2" gdb_test "set stop_whining = 2"
# Prime the system # Prime the system
gdb_test_stdio "call complaint (&symfile_complaints, \"Register a complaint\")" \ gdb_test_stdio \
"During symbol reading, Register a complaint." "call complaint_internal (&symfile_complaints, \"Register a complaint\")" \
"During symbol reading, Register a complaint."
# Check that the complaint was inserted and where # Check that the complaint was inserted and where
gdb_test "print symfile_complaints->root->fmt" \ gdb_test "print symfile_complaints->root->fmt" \
".\[0-9\]+ =.*\"Register a complaint\"" ".\[0-9\]+ =.*\"Register a complaint\""
# Re-issue the first message #1 # Re-issue the first message #1
gdb_test_stdio "call complaint (&symfile_complaints, symfile_complaints->root->fmt)" \ gdb_test_stdio \
"During symbol reading, Register a complaint." "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 # 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++ # 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" ".\[0-9\]+ = \(1|true\)" "list has one entry"
# Add a second complaint, expect it # Add a second complaint, expect it
gdb_test_stdio "call complaint (&symfile_complaints, \"Testing! Testing! Testing!\")" \ gdb_test_stdio \
"During symbol reading, Testing. Testing. Testing.." "call complaint_internal (&symfile_complaints, \"Testing! Testing! Testing!\")" \
"During symbol reading, Testing. Testing. Testing.."
return 0 return 0
} }
@ -86,12 +89,14 @@ proc test_serial_complaints { } {
gdb_test_exact "call clear_complaints (&symfile_complaints, 1, 0)" "" "serial start" gdb_test_exact "call clear_complaints (&symfile_complaints, 1, 0)" "" "serial start"
# Prime the system # 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..." \ "During symbol reading...serial line 1..." \
"serial line 1" "serial line 1"
# Add a second complaint, expect it # 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..." \
"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" gdb_test_exact "call clear_complaints (&symfile_complaints, 1, 1)" "" "short start"
# Prime the system # 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..." \
"short line 1" "short line 1"
# Add a second complaint, expect it # 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..." \
"short line 2" "short line 2"