Re: Part 2: perf test case probe libc fails with latest Fedora34 glibc update

[Masami Hiramatsu <mhiramat@kernel.org>]

On Tue, 29 Jun 2021 08:42:15 +0200
Thomas Richter <tmricht@linux.ibm.com> wrote:

> On 6/29/21 7:02 AM, Masami Hiramatsu wrote:
> > On Fri, 25 Jun 2021 12:43:29 +0200
> > Thomas Richter <tmricht@linux.ibm.com> wrote:
> > 
> >> I think I found one issue:
> >>
> >> Fedora 33 named the debug files for glibc 'libc-2.33.so.debug'
> >> [root@s8360047 ~]# rpm -ql glibc-debuginfo-2.33-5.fc34.s390x|fgrep libc-2.33.so
> >> /usr/lib/debug/lib64/libc-2.33.so.debug
> >> [root@s8360047 ~]#
> >>
> >> The file was located in
> >>    /usr/lib/debug/lib64/libc-2.33.so.debug
> >> and hard linked to (or vice versa)
> >>    /usr/lib/debug/usr/lib64/libc-2.33.so.debug
> >>
> >> With Fedora 34 the glibc debug file name changed to:
> >> /usr/lib/debug/lib64/libc-2.33.so-2.33-18.fc34.s390x.debug
> >> and
> >> /usr/lib/debug/usr/lib64/libc-2.33.so-2.33-18.fc34.x86_64.debug
> > 
> > Oh, the naming scheme has been changed.
> > 
> >>
> >> This is important. The call chain is
> >>
> >>  ...
> >>  try_to_find_probe_trace_events()
> >>  +-> open_debuginfo()
> >>      +-> debuginfo__new(/usr/lib64/libc-2.33.so)
> >>          +-> dso__read_binary_type_filename()
> >>
> >> Function dso__read_binary_type_filename() now tries to find the debug file
> >> for /usr/lib64/libc-2.33.so for various distros starting with
> >> FEDORA_DEBUGINFO. Tt builds the file name by prepending
> >> '/usr/lib/debug' and appending '.debug'. This was ok until the Fedora 34
> >> name change. Now the debug file is not found anymore and various other
> >> distro name schemes are tried. None is found and the /usr/lib64/libc-2.33.so
> >> file itself is used.
> > 
> > Hmm, we might need a generic way to get such debuginfo path among
> > linux distros... are there any good command?
> 
> IMHO The only option that makes sense is to use the buildid:
> The s390 compiler team recommended this to me.
> 
> [root@t35lp46 perf]# file /usr/lib64/libc-2.33.so
> /usr/lib64/libc-2.33.so: ELF 64-bit MSB shared object, IBM S/390, version 1 (GNU/Linux), dynamically linked, interpreter /lib/ld64.so.1, BuildID[sha1]=15da6d15f3b4d5042dab1246222479e577fe9190, for GNU/Linux 3.2.0, not stripped
> [root@t35lp46 perf]# ll /root/.debug/.build-id/15/da6d15f3b4d5042dab1246222479e577fe9190/
> total 7912
> -rw-r--r-- 2 root root 6372968 Jun 21 09:01 debug
> -rwxr-xr-x 2 root root 1719672 Jun 21 09:01 elf
> -rw-r--r-- 1 root root    4754 Jun 23 10:23 probes
> [root@t35lp46 perf]# readelf -s /root/.debug/.build-id/15/da6d15f3b4d5042dab1246222479e577fe9190/debug | fgrep ' inet_pton'
>  21092: 0000000000000000     0 FILE    LOCAL  DEFAULT  ABS inet_pton.c
>  21105: 0000000000123150   250 FUNC    LOCAL  DEFAULT   13 inet_pton4
>  21108: 0000000000123250   524 FUNC    LOCAL  DEFAULT   13 inet_pton6
>  27909: 00000000001234c0   106 FUNC    WEAK   DEFAULT   13 inet_pton
> [root@t35lp46 perf]# 

This debug file is copied by perf, isn't it?

> The bad thing is that only the file part xx/yy/debug seems to be agreed upon
> between distros. There are multiple/different locations containing .build-id directories.
> 
> On the other hand, perf is connected to the kernel, so we could 'convince'
> the distro's to use their distro specific locations when they build perf.

Hmm, or they can add /etc/perf.conf, to provide their customized debuginfo path
with a template pattern.

> 
> [....] 
> 
> >>
> >> Second issue:
> >> The symbol 'inet_pton' is defined as WEAK. Even when the correct
> >> debuginfo file is loaded for libc in function dso__read_binary_type_filename(),
> >> the perf probe command fails.
> >> However it works for GLOBAL and LOCAL symbols, so it would be definitly an 
> >> improvement.
> >>
> >> I have no clue on dwarf so I put Masami on the addressee list.
> >> This second issue is somehow related to dwarf_getfuncs() and
> >> the probe_point_search_cb() call back function invoked by dwarf_getfuncs()
> >> in the probe_finder.c file. Too far away from my horizon :-)...
> >>
> >> On 6/23/21 4:21 PM, Thomas Richter wrote:
> >>> I just updated Fedora34 to the latest level and discovered that perf test 78 fails:
> >>> [root@m46lp22 perf]# ./perf test 78
> >>> 78: probe libc's inet_pton & backtrace it with ping                 : FAILED!
> >>> [root@m46lp22 perf]#
> >>>
> >>> It boils down to this command and happens after glibc is update to level 2.33-18.
> >>>
> >>> [root@f34 ~]# perf probe -f -x /usr/lib64/libc-2.33.so -a inet_pton
> >>> Probe point 'inet_pton' not found.
> >>>   Error: Failed to add events.
> > 
> > Hmm, what does "nm" say? Also, Does perf correctly open the debuginfo file or only
> > open the library without debuginfo?
> 
> # nm -D /usr/lib64/libc-2.33.so | fgrep inet_pton
> 00000000001234c0 W inet_pton@@GLIBC_2.2
> 0000000000123460 T __inet_pton_length@@GLIBC_PRIVATE
> # readelf -s /usr/lib64/libc-2.33.so | fgrep inet_pton
>    673: 00000000001234c0   106 FUNC    WEAK   DEFAULT   13 inet_pton@@GLIBC_2.2
> # nm -D /root/.debug/usr/lib64/libc-2.33.so/15da6d15f3b4d5042dab1246222479e577fe9190/debug | fgrep inet_pton
> nm: /root/.debug/usr/lib64/libc-2.33.so/15da6d15f3b4d5042dab1246222479e577fe9190/debug: no symbols
> # readelf -s /root/.debug/usr/lib64/libc-2.33.so/15da6d15f3b4d5042dab1246222479e577fe9190/debug | fgrep inet_pton
>  21092: 0000000000000000     0 FILE    LOCAL  DEFAULT  ABS inet_pton.c
>  21105: 0000000000123150   250 FUNC    LOCAL  DEFAULT   13 inet_pton4
>  21108: 0000000000123250   524 FUNC    LOCAL  DEFAULT   13 inet_pton6
>  24179: 0000000000123460    90 FUNC    LOCAL  DEFAULT   13 __GI___inet_pton[...]
>  24463: 00000000001234c0   106 FUNC    LOCAL  DEFAULT   13 __inet_pton
>  25102: 00000000001234c0   106 FUNC    LOCAL  DEFAULT   13 __GI___inet_pton
>  26439: 00000000001234c0   106 FUNC    LOCAL  DEFAULT   13 __GI_inet_pton
>  27023: 0000000000123460    90 FUNC    GLOBAL DEFAULT   13 __inet_pton_length
>  27909: 00000000001234c0   106 FUNC    WEAK   DEFAULT   13 inet_pton
> # readelf -s /root/.debug/usr/lib64/libc-2.33.so/15da6d15f3b4d5042dab1246222479e577fe9190/elf | fgrep inet_pton
>    673: 00000000001234c0   106 FUNC    WEAK   DEFAULT   13 inet_pton@@GLIBC_2.2
> #
> 
> > 
> >>> [root@f34 ~]# rpm -qa | fgrep glibc
> >>> glibc-all-langpacks-2.33-18.fc34.x86_64
> >>> glibc-common-2.33-18.fc34.x86_64
> >>> glibc-langpack-en-2.33-18.fc34.x86_64
> >>> glibc-2.33-18.fc34.x86_64
> >>> glibc-doc-2.33-18.fc34.noarch
> >>> glibc-headers-x86-2.33-18.fc34.noarch
> >>> glibc-devel-2.33-18.fc34.x86_64
> >>> glibc-debugsource-2.33-18.fc34.x86_64
> >>> glibc-debuginfo-2.33-18.fc34.x86_64
> >>> [root@f34 ~]# 
> >>>
> >>> The symbol inet_pton is now in the .dynsym section of glibc:
> >>> [root@f34 ~]# readelf -sW /usr/lib64/libc-2.33.so | egrep '(dynsym|symtab|inet_pton)'
> >>> Symbol table '.dynsym' contains 2419 entries:
> >>>    628: 000000000011ea00   108 FUNC    WEAK   DEFAULT   15 inet_pton@@GLIBC_2.2.5
> >>>   2251: 000000000011e9b0    76 FUNC    GLOBAL DEFAULT   15 __inet_pton_length@@GLIBC_PRIVATE
> >>> Symbol table '.symtab' contains 104 entries:
> >>> [root@f34 ~]#
> >>>
> >>> The .symtab section does not contain symbol inet_pton. It contains very few symbols
> >>> compared to previous versions.
> > 
> > Hmm, if perf probe can not find the debuginfo, it failback to symbol map,
> > can you add -vvv option to run the perf probe again?
> > 
> 
> # ./perf probe -vvv -f -x /usr/lib64/libc-2.33.so -a inet_pton 

Ah, OK. This helps me a lot. 

> probe-definition(0): inet_pton
> symbol:inet_pton file:(null) line:0 offset:0 return:0 lazy:(null)
> 0 arguments
> symbol:__v1setjmp file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:longjmp file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:longjmp_target file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:lll_lock_wait_private file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:cond_destroy file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:cond_init file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_arena_max file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_arena_test file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_tunable_tcache_max_bytes file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_tunable_tcache_count file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_tunable_tcache_unsorted_limit file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_trim_threshold file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_top_pad file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_mmap_threshold file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_mmap_max file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_perturb file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_mxfast file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_heap_new file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_sbrk_less file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_heap_free file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_tcache_double_free file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_heap_less file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_heap_more file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_sbrk_more file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_arena_reuse_free_list file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_arena_reuse file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_arena_reuse_wait file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_arena_new file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_arena_retry file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_malloc_retry file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_memalign_retry file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt_free_dyn_thresholds file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_realloc_retry file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_calloc_retry file:(null) line:0 offset:0 return:0 lazy:(null)
> symbol:memory_mallopt file:(null) line:0 offset:0 return:0 lazy:(null)
> Open Debuginfo file: /usr/lib64/libc-2.33.so
> Try to find probe point from debuginfo.

Hmm, strange. Does the /usr/lib64/libc-2.33.so have .debuginfo??
(or, did you copy it?)

> try_to_find_probe_trace_events ntevs 0
> try_to_find_probe_trace_events ret -2
> try_to_find_probe_trace_events ntevs2 0
> Probe point 'inet_pton' not found.
>   Error: Failed to add events. Reason: No such file or directory (Code: -2)

I guess the libc binary may have a partial debuginfo and it has no
full DIE tree. Thus the try_to_find_probe_trace_events() failed.

I'll try to check on the Fedora34. 

Thank you,

> # 
> [....]
> > 
> > Thank you,
> > 
> 
> 
> -- 
> Thomas Richter, Dept 3303, IBM s390 Linux Development, Boeblingen, Germany
> --
> Vorsitzender des Aufsichtsrats: Gregor Pillen
> Geschäftsführung: Dirk Wittkopp
> Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294


-- 
Masami Hiramatsu <mhiramat@kernel.org>