support nested library calls #141

namhyung · 2017-09-02T17:08:36Z

@honggyukim suggested to support tracing nested library calls (i.e. libxxx calls a function in libyyy). This can be useful to understand behavior of prebuilt library (or executable). I added --nest-libcall option to enable this as it's disabled by default (for performance reason - never profiled though).

Some low-level libraries are excluded due to crash. But it seems that PLT in libraries with BIND-NOW have almost nothing. Need to investigate more..

I pushed the code to review/nest-libcall-v1.

Here's an example.

$ cat libcall-nest.c
#include <stdlib.h>
    
extern int lib_a(int);
eextern void foo(int);
    
int main(int argc, char *argv[])
{
   int n = 1;
   if (argc > 1)
      n = atoi(argv[1]);
    
   lib_a(n);
   foo(n);
    
   return 0;
}

The lib_a() and foo() are defined in separate libraries which are not built with -pg. So we cannot see the inside of the functions.

$ uftrace a.out
1
# DURATION    TID     FUNCTION
            [ 5436] | main() {
   2.973 us [ 5436] |   lib_a();
  18.348 us [ 5436] |   foo();
  22.610 us [ 5436] | } /* main */

But with --nest-libcall we can at least see the external function calls they made.

$ uftrace --nest-libcall -D3 a.out
1
# DURATION    TID     FUNCTION
            [ 5439] | main() {
            [ 5439] |   lib_a() {
   0.579 us [ 5439] |     getpid();
   2.973 us [ 5439] |   } /* lib_a */
            [ 5439] |   foo() {
  10.234 us [ 5439] |     std::basic_ostream::operator <<();
   7.300 us [ 5439] |     std::basic_ostream::operator <<();
  18.348 us [ 5439] |   } /* foo */
  22.610 us [ 5439] | } /* main */

The text was updated successfully, but these errors were encountered:

honggyukim · 2017-09-03T01:42:07Z

@namhyung I really appreciate doing this work! I've tested the branch but found that it's not working as of now. Here is the steps I followed.

$ cat new-delete.cc
int main()
{
        int *p = new int;
        delete p;
}

$ g++ -pg -O0 new-delete.cc
$ uftrace record --nest-libcall a.out
mcount: /home/honggyu/work/uftrace/git/uftrace/libmcount/plthook.c:44:segv_handler
 ERROR: invalid memory access: 601010: exiting.

Here is the detail log.

$ uftrace record --nest-libcall -vv a.out
uftrace: removing uftrace.data.old directory
symbol: check trace functions in a.out
uftrace: creating 10 thread(s) for recording
uftrace: using libmcount.so library for tracing
uftrace: start writer thread 0
    ...
uftrace: start writer thread 9
mcount: initializing mcount library
symbol: loading dynamic symbols from /home/honggyu/work/uftrace/git/uftrace/kim/a.out (offset: 0x400000)
symbol: loaded 8 symbols
mcount: setup plthook data for /home/honggyu/work/uftrace/git/uftrace/kim/a.out (offset: 0)
mcount: opening executable image: /home/honggyu/work/uftrace/git/uftrace/kim/a.out
mcount: module: /home/honggyu/work/uftrace/git/uftrace/kim/a.out (id: 7f9035caa168), addr = 0, PLTGOT = 0x601000
symbol: loaded 8 symbols
mcount: found GOT at 0x601000 (PLT resolver: 0x7f9035a9a870)
mcount: overwrite [5] mcount: 0x7f90358765c0
mcount: setup plthook data for /home/honggyu/work/uftrace/git/uftrace/kim/a.out (offset: 7ffdaf6e8000)
mcount: opening executable image: /home/honggyu/work/uftrace/git/uftrace/kim/a.out
mcount: /home/honggyu/work/uftrace/git/uftrace/libmcount/plthook.c:44:segv_handler
 ERROR: invalid memory access: 601010: exiting.
uftrace: all process/thread exited
uftrace: child terminated with exit code: 1
uftrace: stop writer thread 6
    ...

Here is cgdb log.

173│         if (!pltgot_addr || (!plt_found && !bind_now)) {
174│                 pr_dbg("no PLT nor BIND-NOW.. ignoring...\n");
175│                 return 0;
176│         }
177│
178│         pd = xmalloc(sizeof(*pd));
179│         pd->mod_name   = xstrdup(modname);
180│         pd->pltgot_ptr = (void *)pltgot_addr;
181├───────> pd->module_id  = pd->pltgot_ptr[1];
182│         pd->base_addr  = offset;
183│
/home/honggyu/work/uftrace/git/uftrace/libmcount/plthook.c

(gdb) p *pd
$1 = {
  list = {
    prev = 0x7ffff76170c8,
    next = 0x7ffff76170c8
  },
  mod_name = 0x614c20 "/home/honggyu/work/uftrace/git/uftrace/kim/a.out",
  module_id = 6376336,
  base_addr = 4121673475313787750,
  dsymtab = {
    sym = 0x2020313233343835,
    sym_names = 0x2020202020202020,
    nr_sym = 2314885530818453536,
    nr_alloc = 4069054363051241248,
    name_sorted = 54
  },
  pltgot_ptr = 0x6c2f756e672d7875,
  resolved_addr = 0x6165726874706269,
  special_funcs = 0x732e33322e322d64,
  nr_special = 1714883183
}

(gdb) p pd->pltgot_ptr[1]
Cannot access memory at address 0x6c2f756e672d787d

Please take a look at it again. Thanks!

namhyung · 2017-09-03T02:52:07Z

Hmm.. it works on my machine.

$ uftrace --nest-libcall a.out
# DURATION    TID     FUNCTION
            [ 9826] | main() {
   0.986 us [ 9826] |   operator new();
            [ 9826] |   operator delete() {
            [ 9826] |     operator delete() {
   0.679 us [ 9826] |       free();
   1.506 us [ 9826] |     } /* operator delete */
   2.333 us [ 9826] |   } /* operator delete */
   5.924 us [ 9826] | } /* main */

Looking at the log, I found that the a.out was set up twice:

mcount: setup plthook data for /home/honggyu/work/uftrace/git/uftrace/kim/a.out (offset: 0)
mcount: opening executable image: /home/honggyu/work/uftrace/git/uftrace/kim/a.out
mcount: module: /home/honggyu/work/uftrace/git/uftrace/kim/a.out (id: 7f9035caa168), addr = 0, PLTGOT = 0x601000
symbol: loaded 8 symbols
mcount: found GOT at 0x601000 (PLT resolver: 0x7f9035a9a870)
mcount: overwrite [5] mcount: 0x7f90358765c0
mcount: setup plthook data for /home/honggyu/work/uftrace/git/uftrace/kim/a.out (offset: 7ffdaf6e8000)
mcount: opening executable image: /home/honggyu/work/uftrace/git/uftrace/kim/a.out
mcount: /home/honggyu/work/uftrace/git/uftrace/libmcount/plthook.c:44:segv_handler

The first was with offset 0 and it's ok. The second was with non-zero offset and caused the crash. I don't know why it does the job twice for the same binary - probably it's actually mapped twice for some reason. Anyway it might work when we skip the second setup, could you please try below patch?

diff --git a/libmcount/plthook.c b/libmcount/plthook.c
index 90fef65..ea1e8e1 100644
--- a/libmcount/plthook.c
+++ b/libmcount/plthook.c
@@ -435,6 +435,8 @@ static int setup_mod_plthook_data(struct dl_phdr_info *info, size_t sz, void *ar
 
        if (exename[0] == '\0')
                exename = arg;
+       else if (!strcmp(basename(exename), basename(arg)))
+               return 0;
 
        for (k = 0; k < ARRAY_SIZE(skip_libs); k++) {
                if (!strcmp(basename(exename), skip_libs[k]))

honggyukim · 2017-09-03T03:34:12Z

Hm.. I has the same problem even if I applied the change above.
One more thing I'm wondering about it is why it doesn't show malloc inside operator new in the below trace.

$ uftrace --nest-libcall a.out
# DURATION    TID     FUNCTION
            [ 9826] | main() {
   0.986 us [ 9826] |   operator new();
            [ 9826] |   operator delete() {
            [ 9826] |     operator delete() {
   0.679 us [ 9826] |       free();
   1.506 us [ 9826] |     } /* operator delete */
   2.333 us [ 9826] |   } /* operator delete */
   5.924 us [ 9826] | } /* main */

namhyung · 2017-09-03T03:34:56Z

OK, I set up a container and could reproduce it. It really called the dl_iterate_phdr() call back twice for the main binary (i.e. empty exename). Following patch worked for me (please ignore the above patch).
nest-libcall-fix-on-ubuntu.patch.txt

diff --git a/libmcount/plthook.c b/libmcount/plthook.c
index 90fef65..94c65c1 100644
--- a/libmcount/plthook.c
+++ b/libmcount/plthook.c
@@ -432,9 +432,15 @@ static int setup_mod_plthook_data(struct dl_phdr_info *info, size_t sz, void *ar
                "ld-linux-x86-64.so.2",
        };
        size_t k;
+       static bool once = true;
+
+       if (exename[0] == '\0') {
+               if (!once)
+                       return 0;
 
-       if (exename[0] == '\0')
                exename = arg;
+               once = false;
+       }
 
        for (k = 0; k < ARRAY_SIZE(skip_libs); k++) {

namhyung · 2017-09-03T03:36:51Z

One more thing I'm wondering about it is why it doesn't show malloc inside operator new in the below trace.

I don't know neither. Maybe need more investigation..

honggyukim · 2017-09-03T03:42:40Z

Thanks! Now it shows the below trace output:

$ uftrace --nest-libcall a.out
# DURATION    TID     FUNCTION
            [193944] | main() {
   2.207 us [193944] |   operator new();
            [193944] |   operator delete() {
   1.743 us [193944] |     free();
   3.767 us [193944] |   } /* operator delete */
  10.704 us [193944] | } /* main */

But still doesn't show malloc yet.

honggyukim · 2017-09-03T03:43:27Z

FYI, here is the log in details.

$ uftrace --nest-libcall -vv a.out
    ...
uftrace: start writer thread 9
uftrace: using libmcount.so library for tracing
mcount: initializing mcount library
symbol: loading dynamic symbols from /home/honggyu/work/uftrace/git/uftrace/kim/a.out (offset: 0x400000)
symbol: loaded 6 symbols
mcount: setup plthook data for /home/honggyu/work/uftrace/git/uftrace/kim/a.out (offset: 0)
mcount: opening executable image: /home/honggyu/work/uftrace/git/uftrace/kim/a.out
mcount: module: /home/honggyu/work/uftrace/git/uftrace/kim/a.out (id: 7fc2f5fcf168), addr = 0, PLTGOT = 0x601000
symbol: loaded 6 symbols
mcount: found GOT at 0x601000 (PLT resolver: 0x7fc2f5dbf870)
mcount: overwrite [3] mcount: 0x7fc2f5b9b5d0
mcount: setup plthook data for /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (offset: 7fc2f5802000)
mcount: opening executable image: /usr/lib/x86_64-linux-gnu/libstdc++.so.6
mcount: module: /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (id: 7fc2f5fcca40), addr = 7fc2f5802000, PLTGOT = 0x7fc2f5b7e000
symbol: loaded 803 symbols
mcount: found GOT at 0x7fc2f5b7e000 (PLT resolver: 0x7fc2f5dbf870)
mcount: setup plthook data for /usr/lib/x86_64-linux-gnu/libelf.so.1 (offset: 7fc2f5220000)
mcount: opening executable image: /usr/lib/x86_64-linux-gnu/libelf.so.1
mcount: module: /usr/lib/x86_64-linux-gnu/libelf.so.1 (id: 7fc2f5fb34e8), addr = 7fc2f5220000, PLTGOT = 0x7fc2f5437000
symbol: loaded 42 symbols
mcount: found GOT at 0x7fc2f5437000 (PLT resolver: 0x7fc2f5dbf870)
mcount: setup plthook data for /lib/x86_64-linux-gnu/librt.so.1 (offset: 7fc2f5018000)
mcount: opening executable image: /lib/x86_64-linux-gnu/librt.so.1
mcount: module: /lib/x86_64-linux-gnu/librt.so.1 (id: 7fc2f5fb39d8), addr = 7fc2f5018000, PLTGOT = 0x7fc2f521f000
symbol: loaded 51 symbols
mcount: found GOT at 0x7fc2f521f000 (PLT resolver: 0x7fc2f5dbf870)
mcount: setup plthook data for /lib/x86_64-linux-gnu/libdl.so.2 (offset: 7fc2f4e14000)
mcount: opening executable image: /lib/x86_64-linux-gnu/libdl.so.2
mcount: module: /lib/x86_64-linux-gnu/libdl.so.2 (id: 7fc2f5fb2000), addr = 7fc2f4e14000, PLTGOT = 0x7fc2f5017000
symbol: loaded 10 symbols
mcount: found GOT at 0x7fc2f5017000 (PLT resolver: 0x7fc2f5dbf870)
mcount: setup plthook data for /lib/x86_64-linux-gnu/libm.so.6 (offset: 7fc2f48ee000)
mcount: opening executable image: /lib/x86_64-linux-gnu/libm.so.6
mcount: module: /lib/x86_64-linux-gnu/libm.so.6 (id: 7fc2f5fb2a60), addr = 7fc2f48ee000, PLTGOT = 0x7fc2f4bf6000
symbol: loaded 25 symbols
mcount: found GOT at 0x7fc2f4bf6000 (PLT resolver: 0x7fc2f5dbf870)
mcount: setup plthook data for /lib/x86_64-linux-gnu/libz.so.1 (offset: 7fc2f44be000)
mcount: opening executable image: /lib/x86_64-linux-gnu/libz.so.1
mcount: module: /lib/x86_64-linux-gnu/libz.so.1 (id: 7fc2f5fb1568), addr = 7fc2f44be000, PLTGOT = 0x7fc2f46d7000
symbol: loaded 17 symbols
mcount: found GOT at 0x7fc2f46d7000 (PLT resolver: 0x7fc2f5dbf870)
mcount: mcount setup done
mcount: preparing shmem buffers
uftrace: MSG SESSION: 194053: /home/honggyu/work/uftrace/git/uftrace/kim/a.out (18ae791d4397323d)
mcount: shmem_finish: tid: 194053 seqnum = 0 curr = 0, nr_buf = 2 max_buf = 2
mcount: releasing all shmem buffers for task 194053
mcount: destroy plthook special function index
symbol: unload symbol tables
uftrace: MSG START: /uftrace-18ae791d4397323d-194053-000
uftrace: MSG TASK_START : 194053/194053
uftrace: MSG  END : /uftrace-18ae791d4397323d-194053-000
uftrace: MSG TASK_END : 194053/194053
uftrace: all process/thread exited
uftrace: child terminated with exit code: 0
uftrace: stop writer thread 4
    ...

honggyukim · 2017-09-03T04:07:38Z

Ah.. there's some more log that shows some error.

    ...
uftrace: stop writer thread 5
uftrace: stop writer thread 8
uftrace: stop writer thread 7
uftrace: reading /tmp/uftrace-live-kM7W6k/task.txt file
session: new task: tid = 194660
uftrace: unlink for session: f17d41b954ff6547
symbol: loading symbols from a.out (offset: 0)
symbol: loaded 6 symbols
symbol: loading dynamic symbols from a.out (offset: 0)
symbol: load dynamic symbols for bind-now
symbol: loaded 6 symbols from .plt.got section
symbol: saving symbols to /tmp/uftrace-live-kM7W6k/a.out.sym
symbol: load module dynamic symbol: [vsyscall]
symbol: error during open symbol file: [vsyscall]: No such file or directory
symbol: load module dynamic symbol: [vdso]
symbol: error during open symbol file: [vdso]: No such file or directory
symbol: load module dynamic symbol: [stack]
symbol: error during open symbol file: [stack]: No such file or directory
symbol: load module dynamic symbol: /lib/x86_64-linux-gnu/ld-2.23.so
symbol: loading dynamic symbols from /lib/x86_64-linux-gnu/ld-2.23.so (offset: 0x7f4a51450000)
symbol: loaded 4 symbols
symbol: load module dynamic symbol: /home/honggyu/usr/lib/libmcount.so
symbol: load module dynamic symbol: /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.21
symbol: loading dynamic symbols from /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.21 (offset: 0x7f4a50eaa000)
symbol: loaded 803 symbols
    ...

namhyung · 2017-09-03T04:16:22Z

I looked at the problem, and found the solution! :)

It was because the malloc was resolved before we hook the PLTGOT so it didn't call the malloc throughout the PLT0. I restored the PLTGOT of all the resolved entries and could see malloc inside the operator new. The new code is available at review/nest-libcall-v2.

root@ubuntu-1604:~# uftrace --nest-libcall a.out
# DURATION    TID     FUNCTION
            [ 1892] | main() {
            [ 1892] |   operator new() {
   0.524 us [ 1892] |     malloc();
   2.117 us [ 1892] |   } /* operator new */
            [ 1892] |   operator delete() {
   0.827 us [ 1892] |     free();
   1.912 us [ 1892] |   } /* operator delete */
   5.926 us [ 1892] | } /* main */

namhyung · 2017-09-03T04:17:45Z

OK, it needs to skip special kernel mappings started with '[', thanks!

honggyukim · 2017-09-03T04:19:20Z

@namhyung It works great!

$ uftrace --nest-libcall a.out
# DURATION    TID     FUNCTION
            [195268] | main() {
            [195268] |   operator new() {
   0.943 us [195268] |     malloc();
   2.737 us [195268] |   } /* operator new */
            [195268] |   operator delete() {
   1.850 us [195268] |     free();
   4.870 us [195268] |   } /* operator delete */
   8.803 us [195268] | } /* main */

honggyukim · 2017-09-03T04:21:56Z

One more issue is that I want to see the arguments and retvals of internal library calls. But it crashes when I run the below command.

$ uftrace --nest-libcall -A malloc@libstdc++,arg1 a.out
*** buffer overflow detected ***: uftrace terminated
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7fd7483ff7e5]
/lib/x86_64-linux-gnu/libc.so.6(__fortify_fail+0x5c)[0x7fd7484a111c]
/lib/x86_64-linux-gnu/libc.so.6(+0x117120)[0x7fd74849f120]
uftrace[0x4187b6]
uftrace[0x414358]
uftrace[0x414e0d]
uftrace[0x41536e]
uftrace[0x404af7]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fd7483a8830]
uftrace[0x404bf9]
======= Memory map: ========
00400000-0044a000 r-xp 00000000 08:11 202117356                          /home/honggyu/usr/bin/uftrace
    ...

Even if I use the exact library name, the result is the same.

$ uftrace --nest-libcall -A malloc@libstdc++.so.6.0.21,arg1 a.out

namhyung · 2017-09-03T05:17:14Z

There was a bug on symbol handling. I pushed the fix into review/nest-libcall-v3.

root@ubuntu-1604:~# uftrace --nest-libcall -A malloc@libstdc++,arg1 a.out
# DURATION    TID     FUNCTION
            [ 2351] | main() {
            [ 2351] |   operator new() {
   1.152 us [ 2351] |     malloc(4);
   3.755 us [ 2351] |   } /* operator new */
            [ 2351] |   operator delete() {
   1.420 us [ 2351] |     free();
   2.638 us [ 2351] |   } /* operator delete */
   9.843 us [ 2351] | } /* main */

honggyukim · 2017-09-03T05:20:58Z

@namhyung Thanks! It works fine now.

$ uftrace --nest-libcall -A malloc@libstdc++,arg1 -R malloc@libstdc++,retval -A free@libstdc++,arg1  a.out
# DURATION    TID     FUNCTION
            [ 1221] | main() {
            [ 1221] |   operator new() {
   1.813 us [ 1221] |     malloc(4) = 0x1460ed0;
   4.300 us [ 1221] |   } /* operator new */
            [ 1221] |   operator delete() {
   1.997 us [ 1221] |     free(0x1460ed0);
   5.840 us [ 1221] |   } /* operator delete */
  12.010 us [ 1221] | } /* main */

But I think we need to think about another way rather than explicitly specifying the library name. If there's a lot of libraries, it may be annoying to specify all the libraries to just trace malloc or free in some cases.

namhyung · 2017-09-03T05:30:23Z

Yes, I feel the same but let's leave it for a different issue. I'll think about it more, thanks.

honggyukim · 2017-09-03T05:43:48Z

@namhyung Thanks a lot for this feature. I would like to suggest one more option with this. Why don't we add an option for tracing only libraries without mcounted functions even if the binary is built with -pg? Let's say --libcall-only similar to --kernel-only.

honggyukim · 2017-09-03T05:56:00Z

One more thing is that I have some symbol problems on the following case running clang distributed in official ubuntu package.

$ uftrace --nest-libcall -A malloc@libstdc++,arg1 -R malloc@libstdc++,retval -A free@libstdc++,arg1 -A malloc@arg1 -R malloc@retval -A free@arg1 --force --no-pager /usr/bin/clang | head -20
clang: error: no input files
# DURATION    TID     FUNCTION
   2.246 us [ 2221] | getenv();
            [ 2221] | llvm::sys::PrintStackTraceOnErrorSignal() {
   0.276 us [ 2221] |   <7f41704a9aa0>();
            [ 2221] |   <7f41704a98c0>() {
   1.846 us [ 2221] |     malloc(24) = 0x3295bf0;
   3.320 us [ 2221] |   } /* <7f41704a98c0> */
   0.177 us [ 2221] |   <7f41704a9a50>();
            [ 2221] |   <7f41704a98c0>() {
   0.327 us [ 2221] |     malloc(16) = 0x341d2e0;
   0.860 us [ 2221] |   } /* <7f41704a98c0> */
   0.156 us [ 2221] |   <7f41704a9aa0>();
            [ 2221] |   <7f41704a98c0>() {
   0.327 us [ 2221] |     malloc(16) = 0x341d300;
   0.880 us [ 2221] |   } /* <7f41704a98c0> */
   0.274 us [ 2221] |   <7f41704aa340>();
   0.183 us [ 2221] |   <7f41704aa7e0>();
   0.166 us [ 2221] |   <7f41704aa380>();
   0.327 us [ 2221] |   <7f41704a9c20>();
   0.133 us [ 2221] |   <7f41704a9a80>();

It doesn't have such problem without library names to print arguments and retval.

$ uftrace --nest-libcall --force --no-pager /usr/bin/clang | head -20
clang: error: no input files
# DURATION    TID     FUNCTION
   1.744 us [ 2306] | getenv();
            [ 2306] | llvm::sys::PrintStackTraceOnErrorSignal() {
   0.267 us [ 2306] |   pthread_mutex_lock();
            [ 2306] |   operator new() {
   0.543 us [ 2306] |     malloc();
   1.367 us [ 2306] |   } /* operator new */
   0.207 us [ 2306] |   pthread_mutex_unlock();
            [ 2306] |   operator new() {
   0.233 us [ 2306] |     malloc();
   0.586 us [ 2306] |   } /* operator new */
   0.153 us [ 2306] |   pthread_mutex_lock();
            [ 2306] |   operator new() {
   0.193 us [ 2306] |     malloc();
   0.490 us [ 2306] |   } /* operator new */
   0.160 us [ 2306] |   malloc();
   0.170 us [ 2306] |   pthread_mutexattr_init();
   0.130 us [ 2306] |   pthread_mutexattr_settype();
   0.290 us [ 2306] |   pthread_mutex_init();
   0.117 us [ 2306] |   pthread_mutexattr_destroy();

namhyung · 2017-09-03T06:01:30Z

Hmm.. what's the value of tracing library calls only? Anyway, I guess -F .@plt should do the job?

honggyukim · 2017-09-03T06:03:29Z

The value may be same as --kernel-only. I think -F .@plt doesn't look user-friendly.

honggyukim · 2017-09-03T06:44:44Z

Sorry for making you busy but there are two more strange things on my Ubuntu 17.04 machine that has gcc-6.3.0.
It shows operator delete() twice in the below example.

$ g++ new-delete.cc -O0 -pg
$ uftrace --nest-libcall a.out
# DURATION    TID     FUNCTION
            [16696] | main() {
            [16696] |   operator new() {
   0.726 us [16696] |     malloc();
   2.299 us [16696] |   } /* operator new */
            [16696] |   operator delete() {
            [16696] |     operator delete() {
   1.789 us [16696] |       free();
   5.295 us [16696] |     } /* operator delete */
   6.200 us [16696] |   } /* operator delete */
  10.012 us [16696] | } /* main */

And the other issue is demangling error.

$ uftrace --nest-libcall -vv a.out
symbol: check trace functions in a.out
uftrace: creating 2 thread(s) for recording
uftrace: start writer thread 0
uftrace: start writer thread 1
uftrace: using libmcount.so library for tracing
mcount: initializing mcount library
symbol: loading dynamic symbols from /home/honggyu/src/uftrace/git/uftrace/kim/a.out (offset: 0x559b028cd000)
symbol: load dynamic symbols for bind-now
symbol: loaded 5 symbols from .plt.got section
    ...
symbol: load module dynamic symbol: /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.22
symbol: loading dynamic symbols from /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.22 (offset: 0x7f888ac8d000)
demangle: simple demangle failed:
_ZGTtNSt11range_errorD1Ev
  ^
dd_special_name:1119: "valid special name" expected
demangle: current:  (pos: 2/25)
demangle:   [0] dd_encoding
demangle: simple demangle failed:
_ZGTtdlPv
  ^
dd_special_name:1119: "valid special name" expected
demangle: current:  (pos: 2/9)
demangle:   [0] dd_encoding
demangle: simple demangle failed:
_ZGTtNSt12length_errorD1Ev
  ^
dd_special_name:1119: "valid special name" expected
demangle: current:  (pos: 2/26)
demangle:   [0] dd_encoding
demangle: simple demangle failed:
_ZGTtNSt11logic_errorD1Ev
  ^
dd_special_name:1119: "valid special name" expected
demangle: current:  (pos: 2/25)
demangle:   [0] dd_encoding
demangle: simple demangle failed:
_ZGTtNSt16invalid_argumentD1Ev
    ...
fstack: ENTRY: [16763] stack: 2, depth: 2, disp: 2, I: 0, O: 0, D: 1022, flags = 0
   0.185 us [16763] |     malloc();
fstack: EXIT : [16763] stack: 2, depth: 1022, disp: 2, I: 0, O: 0, D: 1021, flags = 0
   0.876 us [16763] |   } /* operator new */
fstack: EXIT : [16763] stack: 1, depth: 1023, disp: 1, I: 0, O: 0, D: 1022, flags = 0
fstack: ENTRY: [16763] stack: 1, depth: 1, disp: 1, I: 0, O: 0, D: 1023, flags = 0
            [16763] |   operator delete() {
fstack: ENTRY: [16763] stack: 2, depth: 2, disp: 2, I: 0, O: 0, D: 1022, flags = 0
            [16763] |     operator delete() {
fstack: ENTRY: [16763] stack: 3, depth: 3, disp: 3, I: 0, O: 0, D: 1021, flags = 0
   0.582 us [16763] |       free();
fstack: EXIT : [16763] stack: 3, depth: 1021, disp: 3, I: 0, O: 0, D: 1020, flags = 0
   1.854 us [16763] |     } /* operator delete */
fstack: EXIT : [16763] stack: 2, depth: 1022, disp: 2, I: 0, O: 0, D: 1021, flags = 0
   2.133 us [16763] |   } /* operator delete */
fstack: EXIT : [16763] stack: 1, depth: 1023, disp: 1, I: 0, O: 0, D: 1022, flags = 0
   3.769 us [16763] | } /* main */
fstack: EXIT : [16763] stack: 0, depth: 1024, disp: 0, I: 0, O: 0, D: 1023, flags = 0
symbol: unload symbol tables

namhyung · 2017-09-03T08:21:22Z

I see the same issue - symbol resolution and demangle failure is fixed in review/nest-libcall-v4. But it seems libstdc++ call the operator delete through PLT - so it's shown twice (one from a.out and another from libstdc++ itself).

$ readelf --dyn-syms /usr/lib/libstdc++.so | c++filt | grep 'operator delete'
    50: 0000000000000000     0 NOTYPE  WEAK   DEFAULT  UND transaction clone for operator delete(void*)
  1313: 000000000008e350     5 FUNC    GLOBAL DEFAULT   13 operator delete(void*, unsigned long)@@CXXABI_1.3.9
  1742: 000000000008e390     5 FUNC    GLOBAL DEFAULT   13 operator delete[](void*, std::nothrow_t const&)@@GLIBCXX_3.4
  1933: 000000000008e360     5 FUNC    GLOBAL DEFAULT   13 operator delete(void*, std::nothrow_t const&)@@GLIBCXX_3.4
  2134: 00000000000905c0     8 FUNC    GLOBAL DEFAULT   13 operator delete(void*, unsigned long, std::align_val_t)@@CXXABI_1.3.11
  3015: 000000000008e340     5 FUNC    GLOBAL DEFAULT   13 operator delete(void*)@@GLIBCXX_3.4
  3793: 000000000008e370     5 FUNC    GLOBAL DEFAULT   13 operator delete[](void*)@@GLIBCXX_3.4
  4332: 00000000000905a0     5 FUNC    GLOBAL DEFAULT   13 operator delete(void*, std::align_val_t)@@CXXABI_1.3.11
  4374: 00000000000905d0     5 FUNC    GLOBAL DEFAULT   13 operator delete[](void*, std::align_val_t)@@CXXABI_1.3.11
  4536: 000000000008e380     5 FUNC    GLOBAL DEFAULT   13 operator delete[](void*, unsigned long)@@CXXABI_1.3.9
  4587: 00000000000905f0     8 FUNC    GLOBAL DEFAULT   13 operator delete[](void*, unsigned long, std::align_val_t)@@CXXABI_1.3.11

$ objdump -d /usr/lib/libstdc++.so | c++filt | grep 'operator delete.*@plt' | head
00000000000899c0 <operator delete(void*)@plt>:
0000000000089ef0 <transaction clone for operator delete(void*)@plt>:
000000000008a1a0 <operator delete(void*, std::align_val_t)@plt>:
000000000008b320 <operator delete[](void*, std::align_val_t)@plt>:
000000000008bcc0 <operator delete(void*, unsigned long)@plt>:
   8d78b:	e9 30 c2 ff ff       	jmpq   899c0 <operator delete(void*)@plt>
   8d8e7:	e9 d4 c0 ff ff       	jmpq   899c0 <operator delete(void*)@plt>
   8d917:	e9 a4 c0 ff ff       	jmpq   899c0 <operator delete(void*)@plt>
   8d92d:	e9 8e c0 ff ff       	jmpq   899c0 <operator delete(void*)@plt>
   8dc0d:	e9 ae bd ff ff       	jmpq   899c0 <operator delete(void*)@plt>

honggyukim · 2017-09-03T08:41:03Z

I see the same issue - demangle failure is fixed in review/nest-libcall-v4.

It works fine now. Thanks for the quick fix :)

But it seems libstdc++ call the operator delete through PLT - so it's shown in twice (one from a.out and another form libstdc++ itself).

Ah.. It's natural to see operator delete twice. Thanks for the confirmation.

honggyukim · 2017-09-03T08:44:26Z

It's great to see the library calls of prebuilt binaries in depth now. I would also like to see their call graph but it's not easy to see it because there are too many first level calls without main function.

Do you think it's okay to add a top level function such as _start to see it? Since _start is the entry point although we don't actually trace it, it may be good to be used as the first level function.

One more value of having _start is that we can easily see the total execution time from it. Otherwise, we have to see uftrace info output to see elapsed time.

namhyung · 2017-09-03T08:53:07Z

Do you mean adding a top-level function for the graph command? It's not possible to trace _start as it's in a prebuilt object.

honggyukim · 2017-09-03T08:54:03Z

I mean we could add _start function on our own just like we traced it. It may be useful when showing call graphs for multi-threaded programs.

namhyung · 2017-09-03T08:55:29Z

How would you like to do it? I think we can add an option to uftrace graph command.

honggyukim · 2017-09-07T00:59:31Z

How would you like to do it? I think we can add an option to uftrace graph command.

Do you think we better add an option to generate _start function for graph command at the top?

honggyukim · 2017-09-07T01:00:29Z

Anyway, adding _start is not related this issue, so I think we can merge this unless there's something you have to improve more.

namhyung added the review label Sep 2, 2017

namhyung closed this as completed in c618ccc Sep 7, 2017

honggyukim mentioned this issue Jul 23, 2023

uftrace 주요 개발 사항 링크들 kosslab-kr/uftrace#107

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

support nested library calls #141

support nested library calls #141

namhyung commented Sep 2, 2017

honggyukim commented Sep 3, 2017

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017

namhyung commented Sep 3, 2017 •

edited

Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017

namhyung commented Sep 3, 2017

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017 •

edited

Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017

honggyukim commented Sep 3, 2017 •

edited

Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading

namhyung commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017

honggyukim commented Sep 3, 2017 •

edited

Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017 •

edited

Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 7, 2017

honggyukim commented Sep 7, 2017

support nested library calls #141

support nested library calls #141

Comments

namhyung commented Sep 2, 2017

honggyukim commented Sep 3, 2017

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017

namhyung commented Sep 3, 2017 • edited Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017

honggyukim commented Sep 3, 2017 • edited Loading

honggyukim commented Sep 3, 2017

namhyung commented Sep 3, 2017

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017 • edited Loading

honggyukim commented Sep 3, 2017

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017 • edited Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017

honggyukim commented Sep 3, 2017 • edited Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017 • edited Loading

honggyukim commented Sep 3, 2017 • edited Loading

namhyung commented Sep 3, 2017 • edited Loading

honggyukim commented Sep 3, 2017

honggyukim commented Sep 3, 2017 • edited Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 3, 2017 • edited Loading

namhyung commented Sep 3, 2017

honggyukim commented Sep 7, 2017

honggyukim commented Sep 7, 2017

namhyung commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading

namhyung commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading

honggyukim commented Sep 3, 2017 •

edited

Loading