Bug 29081 - objdump -S tends to be slow for thunderbird with separate debug info
Summary: objdump -S tends to be slow for thunderbird with separate debug info
Status: RESOLVED FIXED
Alias: None
Product: binutils
Classification: Unclassified
Component: binutils (show other bugs)
Version: 2.37
: P2 normal
Target Milestone: ---
Assignee: Not yet assigned to anyone
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2022-04-21 14:02 UTC by Martin Liska
Modified: 2022-08-08 11:53 UTC (History)
0 users

See Also:
Host:
Target:
Build:
Last reconfirmed:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Liska 2022-04-21 14:02:41 UTC
The debug info are big, so it's easiest to use a Docker image one can run locally:

$ cat Dockerfile-thunderbird-objdump
FROM opensuse/tumbleweed
RUN zypper ar -f -c http://download.opensuse.org/source/tumbleweed/repo/oss/ source
RUN zypper ar -f -c http://download.opensuse.org/debug/tumbleweed/repo/oss/ debug
RUN zypper repos
RUN zypper refresh
RUN zypper -n install binutils MozillaThunderbird MozillaThunderbird-debugsource MozillaThunderbird-debuginfo perf
RUN timeout 30 objdump --start-address=0x00000000017529e0 --stop-address=0x0000000001752c90 -S -d /usr/lib64/thunderbird/libxul.so

$ podman build -t test -f Dockerfile-thunderbird-objdump
STEP 1/7: FROM opensuse/tumbleweed
STEP 2/7: RUN zypper ar -f -c http://download.opensuse.org/source/tumbleweed/repo/oss/ source
--> Using cache 2393dd1a2d437960601510c9b9732d59c6a2b10e497e4f497c85bda870b88dc5
--> 2393dd1a2d4
STEP 3/7: RUN zypper ar -f -c http://download.opensuse.org/debug/tumbleweed/repo/oss/ debug
--> Using cache 40f7646c586e72ca9247283da6c8cdc9388f18b636d879d3300afabc5c22d229
--> 40f7646c586
STEP 4/7: RUN zypper repos
--> Using cache 8df3cd9239213c4d6857eb8c006ee239d45c0901571675c2701b0e68be74046b
--> 8df3cd92392
STEP 5/7: RUN zypper refresh
--> Using cache aeaaa59b2269d0af55364f3fabda58d9ae055fdc19ffe56aa7d3e0160723f552
--> aeaaa59b226
STEP 6/7: RUN zypper -n install binutils MozillaThunderbird MozillaThunderbird-debugsource MozillaThunderbird-debuginfo perf
--> Using cache a4759602ecae1b53fe809c2835d42f607740a54bb42e491ea8cd8a3bc7ba6ae3
--> a4759602eca
STEP 7/7: RUN timeout 30 objdump --start-address=0x00000000017529e0 --stop-address=0x0000000001752c90 -S -d /usr/lib64/thunderbird/libxul.so

/usr/lib64/thunderbird/libxul.so:     file format elf64-x86-64


Disassembly of section .text:

00000000017529e0 <_ZN7mozilla3gfx11VsyncSource7Display11NotifyVsyncERKNS_9TimeStampES5_>:
objdump: DWARF error: could not find variable specification at offset 0x14bfaa4
objdump: DWARF error: could not find variable specification at offset 0x79e96
objdump: DWARF error: could not find variable specification at offset 0x14fb52b
objdump: DWARF error: could not find variable specification at offset 0x14fb536
objdump: DWARF error: could not find variable specification at offset 0x14fb866
objdump: DWARF error: could not find variable specification at offset 0x1570854
objdump: DWARF error: could not find variable specification at offset 0x15a62fb
objdump: DWARF error: could not find variable specification at offset 0x15a6a5f
objdump: DWARF error: could not find variable specification at offset 0x15a7fde
objdump: DWARF error: could not find variable specification at offset 0x15a927f
objdump: DWARF error: could not find variable specification at offset 0x15ad94a
objdump: DWARF error: could not find variable specification at offset 0x15a89fe
objdump: DWARF error: could not find variable specification at offset 0x15ad9bc
objdump: DWARF error: could not find variable specification at offset 0x15a6b27
objdump: DWARF error: could not find variable specification at offset 0x15ada15
objdump: DWARF error: could not find variable specification at offset 0x15a69f7
objdump: DWARF error: could not find variable specification at offset 0x15a8dd9
objdump: DWARF error: could not find variable specification at offset 0x15a809b
objdump: DWARF error: could not find variable specification at offset 0x15adc31
objdump: DWARF error: could not find variable specification at offset 0x15adcc3
objdump: DWARF error: could not find variable specification at offset 0x15a89dc
objdump: DWARF error: could not find variable specification at offset 0x15add48
objdump: DWARF error: could not find variable specification at offset 0x15add88
objdump: DWARF error: could not find variable specification at offset 0x15a6298
objdump: DWARF error: could not find variable specification at offset 0x15adacf
objdump: DWARF error: could not find variable specification at offset 0x15add03
objdump: DWARF error: could not find variable specification at offset 0x15adc7e
objdump: DWARF error: could not find variable specification at offset 0x15addd2
objdump: DWARF error: could not find variable specification at offset 0x83147e
objdump: DWARF error: could not find variable specification at offset 0x15c988e
objdump: DWARF error: could not find variable specification at offset 0x831489
objdump: DWARF error: could not find variable specification at offset 0x15c9899
objdump: DWARF error: could not find variable specification at offset 0x831494
objdump: DWARF error: could not find variable specification at offset 0x15c98a4
objdump: DWARF error: could not find variable specification at offset 0x83149f
objdump: DWARF error: could not find variable specification at offset 0x15c9fc5
objdump: DWARF error: could not find variable specification at offset 0x15ca89d
objdump: DWARF error: could not find variable specification at offset 0x15cafef
objdump: DWARF error: could not find variable specification at offset 0xc4842
objdump: DWARF error: could not find variable specification at offset 0xf2d9bf
objdump: DWARF error: could not find variable specification at offset 0x117a6f6
Error: error building at STEP "RUN timeout 30 objdump --start-address=0x00000000017529e0 --stop-address=0x0000000001752c90 -S -d /usr/lib64/thunderbird/libxul.so": error while running runtime: exit status 124

Note it's LTO-ed binary built with GCC.

perf shows the time is spent here:

$ perf report --stdio | head -n20
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 117K of event 'cycles:u'
# Event count (approx.): 125022478481
#
# Overhead  Command  Shared Object              Symbol                                         
# ........  .......  .........................  ...............................................
#
    76.03%  objdump  libbfd-2.38.20220411-4.so  [.] comp_unit_maybe_decode_line_info.lto_priv.0
    11.80%  objdump  objdump                    [.] check_gnu_debuglink
     5.19%  objdump  libbfd-2.38.20220411-4.so  [.] find_abstract_instance.lto_priv.0
     1.48%  objdump  libbfd-2.38.20220411-4.so  [.] read_attribute_value.lto_priv.0
     0.85%  objdump  libbfd-2.38.20220411-4.so  [.] arange_add.lto_priv.0
     0.65%  objdump  objdump                    [.] compare_symbols
     0.43%  objdump  libbfd-2.38.20220411-4.so  [.] _bfd_safe_read_leb128.constprop.0
     0.37%  objdump  libc.so.6                  [.] __strlen_avx2
     0.30%  objdump  libc.so.6                  [.] __GI_strstr

and note w/o -S option it finishes pretty quickly:

$ time objdump --start-address=0x00000000017529e0 --stop-address=0x0000000001752c90 -d /usr/lib64/thunderbird/libxul.so
...
 1752c77:	5b                   	pop    %rbx
 1752c78:	5d                   	pop    %rbp
 1752c79:	41 5c                	pop    %r12
 1752c7b:	41 5d                	pop    %r13
 1752c7d:	41 5e                	pop    %r14
 1752c7f:	41 5f                	pop    %r15
 1752c81:	e9 ca c3 22 ff       	jmp    97f050 <_ZN7mozilla6detail9MutexImpl6unlockEv@plt>
 1752c86:	e8 b5 a1 22 ff       	call   97ce40 <__stack_chk_fail@plt>
 1752c8b:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)

real	0m4.330s
user	0m3.998s
sys	0m0.332s
Comment 1 Martin Liska 2022-08-08 08:02:11 UTC
It's much better with 2.39 and I've got one more improvement:
https://sourceware.org/pipermail/binutils/2022-August/122273.html
Comment 2 Sourceware Commits 2022-08-08 11:52:38 UTC
The master branch has been updated by Martin Liska <marxin@sourceware.org>:

https://sourceware.org/git/gitweb.cgi?p=binutils-gdb.git;h=e441b55e94c905c6ee4417be3e5d88021d9c5aa6

commit e441b55e94c905c6ee4417be3e5d88021d9c5aa6
Author: Martin Liska <mliska@suse.cz>
Date:   Wed Aug 3 11:28:10 2022 +0200

    add splay tree for info_ptr -> CU mapping
    
    While using perf top for MozillaThunderbird I noticed quite some slow
    dissably call with source code involved. E.g.
    
    time ./objdump --start-address=0x0000000004e0dcd0 --stop-address=0x0000000004e0df8b -l -d --no-show-raw-insn -S -C /usr/lib64/thunderbird/libxul.so
    
    took 2.071s and I noticed quite some time is spent in
    find_abstract_instance:
    
        33.46%  objdump  objdump               [.] find_abstract_instance
        18.22%  objdump  objdump               [.] arange_add
        13.77%  objdump  objdump               [.] read_attribute_value
         4.82%  objdump  objdump               [.] comp_unit_maybe_decode_line_info
         3.10%  objdump  libc.so.6             [.] __memset_avx2_unaligned_erms
    
    where linked list of CU is iterated when searing for where info_ptr
    belongs to:
    
             : 3452   for (u = unit->prev_unit; u != NULL; u = u->prev_unit)
        0.00 :   4c61f7: mov    0x10(%rbx),%rax
        0.00 :   4c61fb: test   %rax,%rax
        0.00 :   4c61fe: je     4c6215 <find_abstract_instance+0x365>
             : 3453   if (info_ptr >= u->info_ptr_unit && info_ptr < u->end_ptr)
        0.00 :   4c6200: cmp    0x60(%rax),%rdx
       83.20 :   4c6204: jb     4c620c <find_abstract_instance+0x35c>
        0.00 :   4c6206: cmp    0x78(%rax),%rdx
        6.89 :   4c620a: jb     4c6270 <find_abstract_instance+0x3c0>
             : 3452   for (u = unit->prev_unit; u != NULL; u = u->prev_unit)
        0.00 :   4c620c: mov    0x10(%rax),%rax
        7.90 :   4c6210: test   %rax,%rax
        0.00 :   4c6213: jne    4c6200 <find_abstract_instance+0x350>
    
    The following scan can be replaced with search in a splay tree and with
    that I can get to 1.5s and there are other symbols where the difference
    is even bigger.
    
    bfd/ChangeLog:
    
            PR 29081
            * dwarf2.c (struct addr_range): New.
            (addr_range_intersects): Likewise.
            (splay_tree_compare_addr_range): Likewise.
            (splay_tree_free_addr_range): Likewise.
            (struct dwarf2_debug_file): Add comp_unit_tree.
            (find_abstract_instance): Use the splay tree when searching
            for a info_ptr.
            (stash_comp_unit): Insert to the splay tree.
            (_bfd_dwarf2_cleanup_debug_info): Clean up the splay tree.
Comment 3 Martin Liska 2022-08-08 11:53:39 UTC
Fixed, the speed up I made will be in 2.40.