namhyung / uftrace

Function graph tracer for C/C++/Rust/Python
https://uftrace.github.io/slide/
GNU General Public License v2.0
3.04k stars 473 forks source link

-fxray-instrument compiled binary patching shows skipped stats #1695

Open honggyukim opened 1 year ago

honggyukim commented 1 year ago

It's weird that why -fxray-instrument compiled binary shows all the functions are skipped in the stat info when patching everything.

The following shows dynamic: skipped: 601 (99.33%), but all the functions are patched properly and it shows all the trace result.

$ clang -fxray-instrument -fxray-instruction-threshold=1 tests/s-abc.c 

$ uftrace -P. --debug-domain dynamic:3 a.out 
dynamic: dynamic patch type: a.out: 4 (xray)
dynamic: update 0x55c2a00cbd50 for 'main' function entry dynamically to call xray functions
dynamic: update 0x55c2a00cbdb2 for 'main' function exit  dynamically to call xray functions
dynamic: update 0x55c2a00cbdc0 for 'a' function entry dynamically to call xray functions
dynamic: update 0x55c2a00cbdd8 for 'a' function exit  dynamically to call xray functions
dynamic: update 0x55c2a00cbdf0 for 'b' function entry dynamically to call xray functions
dynamic: update 0x55c2a00cbe08 for 'b' function exit  dynamically to call xray functions
dynamic: update 0x55c2a00cbe20 for 'c' function entry dynamically to call xray functions
dynamic: update 0x55c2a00cbe40 for 'c' function exit  dynamically to call xray functions
dynamic: dynamic patch stats for 'a.out'
dynamic:    total:      605
dynamic:  patched:        4 ( 0.66%)
dynamic:   failed:        0 ( 0.00%)
dynamic:  skipped:      601 (99.33%)
dynamic: no match:        0
# DURATION     TID     FUNCTION
            [  9654] | main() {
            [  9654] |   a() {
            [  9654] |     b() {
            [  9654] |       c() {
   1.239 us [  9654] |         getpid();
   2.862 us [  9654] |       } /* c */
   3.040 us [  9654] |     } /* b */
   3.166 us [  9654] |   } /* a */
   3.481 us [  9654] | } /* main */

We need to investigate why they are shown as skipped.

namhyung commented 1 year ago

Maybe it has a lot of support codes for xray implementation. Can you dump the symbol table?

honggyukim commented 1 year ago

It's too long to put everything, but I will just post the beginning part as follows.

$ nm -C a.out
0000000000021dc0 t a
00000000000003b4 r __abi_tag
                 U abort@GLIBC_2.2.5
0000000000021e50 t atexit
                 U atoi@GLIBC_2.2.5
0000000000021df0 t b
0000000000034a39 B __bss_start
0000000000021e20 t c
                 U clock_gettime@GLIBC_2.17
                 U close@GLIBC_2.2.5
0000000000034a40 b completed.0
                 U confstr@GLIBC_2.2.5
                 U __cxa_atexit@GLIBC_2.2.5
                 w __cxa_finalize@GLIBC_2.2.5
0000000000032170 D __data_start
0000000000032170 W data_start
00000000000024d0 t deregister_tm_clones
                 U dl_iterate_phdr@GLIBC_2.2.5
                 U dlsym@GLIBC_2.34
0000000000002540 t __do_global_dtors_aux
0000000000031b00 d __do_global_dtors_aux_fini_array_entry
0000000000032178 D __dso_handle
0000000000031d40 d _DYNAMIC
0000000000034a39 D _edata
00000000000c59b0 B _end
                 U __errno_location@GLIBC_2.2.5
0000000000021e64 T _fini
0000000000002580 t frame_dummy
0000000000031ac8 d __frame_dummy_init_array_entry
000000000002fe4c r __FRAME_END__
                 U fsync@GLIBC_2.2.5
                 U getauxval@GLIBC_2.16
                 U getpid@GLIBC_2.2.5
                 U getrlimit@GLIBC_2.2.5
                 U getrusage@GLIBC_2.2.5
...
honggyukim commented 1 year ago
$ nm -C a.out  | grep " [Tt] " | grep -v sanitizer | grep -v __xray
0000000000021dc0 t a
0000000000021e50 t atexit
0000000000021df0 t b
0000000000021e20 t c
00000000000024d0 t deregister_tm_clones
0000000000002540 t __do_global_dtors_aux
0000000000021e64 T _fini
0000000000002580 t frame_dummy
00000000000023e0 t _GLOBAL__sub_I_xray_basic_logging.cpp
00000000000023f0 t _GLOBAL__sub_I_xray_fdr_logging.cpp
00000000000023a0 t _GLOBAL__sub_I_xray_init.cpp
00000000000023b0 t _GLOBAL__sub_I_xray_interface.cpp
00000000000023d0 t _GLOBAL__sub_I_xray_log_interface.cpp
0000000000002000 T _init
0000000000021d50 T main
0000000000002500 t register_tm_clones
00000000000024a0 T _start
honggyukim commented 1 year ago

It can be easily reproducible by running the compile command above.