extract argspec from DWARF debug info

[namhyung]

In addition to auto-args (#173), it could look at the DWARF and identify information regarding argument and return value. The usage is same as auto-args using -A or -R option with no explicit argspec. An explicit argspec suppresses DWARF (and auto-args) argspec. It seems DWARF only creates debug info for user-defined functions, so library calls still needs the auto-args facility.

Let's look at the following example:

$ cat args.c
#include <stdio.h>

int foo(int a, long b)
{
  return a + b;
}

float bar(char *s, char c, double d)
{
  return -1.0;
}

void null(char *s)
{
}

int main(int argc, char *argv[])
{
  foo(-1, 32768);
  bar("string argument", 'c', 0.00001);
  null(NULL);
  return 0;
}

$ gcc -pg -g -o args args.c

With DWARF support, it should work like below:

$ uftrace -A foo args
# DURATION    TID     FUNCTION
            [ 7798] | main() {
   1.039 us [ 7798] |   foo(-1, 32768);
   0.065 us [ 7798] |   bar();
   0.050 us [ 7798] |   null();
   2.966 us [ 7798] | } /* main */

$ uftrace -A . args
# DURATION    TID     FUNCTION
            [ 7804] | main(1, 0x7ffc06a3add8) {
   0.248 us [ 7804] |   foo(-1, 32768);
   0.333 us [ 7804] |   bar("string argument", 'c', 0.000010);
   0.115 us [ 7804] |   null(NULL);
   3.248 us [ 7804] | } /* main */

[namhyung]

Pushed an premature implementation to review/dwarf-argspec-v1.

Note:

• it only support -A option for now
• it only searches debug info in the main executable for now
• it doesn't support -finstrument-functions yet
• the binary should be accessable at replay time too
• the last patch is needed only to workaround a problem in my box (Archlinux).

[honggyukim]

Thanks for doing this work but I've got the below message if I don't install libdw-dev.

$ make
  GEN      .config
Package libdw was not found in the pkg-config search path.
Perhaps you should add the directory containing `libdw.pc'
to the PKG_CONFIG_PATH environment variable
No package 'libdw' found
  CC       cmd-dump.o
    ...

We may be able to provide better message when libdw-dev is not installed on system.

[honggyukim]

Hm.. It doesn't seem to be working on my system.

$ cd uftrace

$ uftrace --version
uftrace v0.8-33-g6467

$ git log --oneline --no-decorate -1
64672bd build: [XXX] fixup to use -I/usr/include/elfutils

$ gcc -pg -g -o args args.c

$ uftrace -A foo args
# DURATION    TID     FUNCTION
   1.730 us [59192] | __monstartup();
   0.900 us [59192] | __cxa_atexit();
            [59192] | main() {
   0.163 us [59192] |   foo();
   0.130 us [59192] |   bar();
   0.130 us [59192] |   null();
   1.877 us [59192] | } /* main */

$ uftrace -A . args
# DURATION    TID     FUNCTION
   1.386 us [59206] | __monstartup();
   0.983 us [59206] | __cxa_atexit();
            [59206] | main() {
   0.173 us [59206] |   foo();
   0.110 us [59206] |   bar();
   0.127 us [59206] |   null();
   1.800 us [59206] | } /* main */

[honggyukim]

I've checked it again but found that I should have to run ./configure again before compilation.
It works fine now. :)

[honggyukim]

It shows strange output for return value display:

$ uftrace -A . -R foo args                                                                   
# DURATION    TID     FUNCTION
   1.860 us [62994] | __monstartup();
   0.817 us [62994] | __cxa_atexit();
            [62994] | main(1, 0x7ffe8c496398) {
   0.400 us [62994] |   foo(-1, 32768) = ;
   0.737 us [62994] |   bar("string argument", 'c', 0.000010);
   0.273 us [62994] |   null(NULL);
   4.790 us [62994] | } /* main */

And it crashes if I run it as follows:

$ uftrace -A . -R . args
uftrace: /home/honggyu/work/uftrace/cmd-replay.c:463: get_argspec_string: Assertion `arg_list && !list_empty(arg_list)' failed.
# DURATION    TID     FUNCTION
Aborted (core dumped)

[Taeung]

For your reference, this feature also works in my system.

$ dpkg -l | grep libdw
ii  libdw-dev:amd64                             0.165-3ubuntu1                               amd64        libdw1 development libraries and header files
ii  libdw1:amd64                                0.165-3ubuntu1                               amd64        library that provides access to the DWARF debug information

$ gcc -dumpversion
7.0.1

$ lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 16.04.3 LTS
Release:	16.04
Codename:	xenial

After setting the test environment,

$ uftrace -A main args
# DURATION    TID     FUNCTION
   0.973 us [28604] | __monstartup();
   0.668 us [28604] | __cxa_atexit();
            [28604] | main(1, 0x7fff2666de88) {
   0.094 us [28604] |   foo();
   0.082 us [28604] |   bar();
   0.080 us [28604] |   null();
   1.786 us [28604] | } /* main */


$ uftrace -A . args
# DURATION    TID     FUNCTION
   0.669 us [28611] | __monstartup();
   0.484 us [28611] | __cxa_atexit();
            [28611] | main(1, 0x7ffeed83c548) {
   0.124 us [28611] |   foo(-1, 32768);
   0.280 us [28611] |   bar("string argument", 'c', 0.000010);
   0.079 us [28611] |   null(NULL);
   1.726 us [28611] | } /* main */

If I find some problems from other test cases, I'll report it 😄

[namhyung]

@honggyukim retval is not supported yet, sorry.

@Taeung thanks for testing!

[Taeung]

@namhyung I found the case that segfault occurs like below:
(too many arguments case)

$ diff ~/args.c changed_args.c 
--- /home/taeung/args.c	2017-10-13 18:58:20.473680303 +0900
+++ changed_args.c	2017-10-13 18:56:15.018637893 +0900
@@ -5,7 +5,7 @@
 	return a + b;
 }
 
-float bar(char *s, char c, double d)
+float bar(char *s, char c, double d,char *s1, char c1, double d1,char *s2, char c2, double d2,char *s3, char c3, double d3,char *s4, char c4, double d4)
 {
 	return -1.0;
 }
@@ -17,7 +17,7 @@
 int main(int argc, char *argv[])
 {
 	foo(-1, 32768);
-	bar("string argument", 'c', 0.00001);
+	bar("string argument", 'c', 0.00001,"string argument", 'c', 0.00001,"string argument", 'c', 0.00001,"string argument", 'c', 0.00001,"string argument", 'c', 0.00001);
 	null(NULL);
 	return 0;
 }

$ gcc -pg -g -o args changed_args.c

$ uftrace -A . args
process crashed by signal 11: Segmentation fault (si_code: 1)
child terminated by signal: 11: Segmentation fault
# DURATION    TID     FUNCTION
   0.916 us [29567] | __monstartup();
   0.666 us [29567] | __cxa_atexit();
            [29567] | main(1, 0x7ffc70680348) {
   0.198 us [29567] |   foo(-1, 32768);
            [29567] |   bar() {

uftrace stopped tracing with remaining functions
================================================
task: 29567
[1] bar
[0] main


$ uftrace -A main args
# DURATION    TID     FUNCTION
   0.758 us [29573] | __monstartup();
   0.475 us [29573] | __cxa_atexit();
            [29573] | main(1, 0x7ffef5e448e8) {
   0.075 us [29573] |   foo();
   0.059 us [29573] |   bar();
   0.049 us [29573] |   null();
   1.335 us [29573] | } /* main */


$ uftrace -A foo args
# DURATION    TID     FUNCTION
   2.017 us [29578] | __monstartup();
   1.544 us [29578] | __cxa_atexit();
            [29578] | main() {
   1.462 us [29578] |   foo(-1, 32768);
   0.213 us [29578] |   bar();
   0.165 us [29578] |   null();
   4.017 us [29578] | } /* main */


$ uftrace -A bar args
process crashed by signal 11: Segmentation fault (si_code: 1)
child terminated by signal: 11: Segmentation fault
# DURATION    TID     FUNCTION
   1.401 us [29583] | __monstartup();
   1.140 us [29583] | __cxa_atexit();
            [29583] | main() {
   0.144 us [29583] |   foo();
            [29583] |   bar() {

uftrace stopped tracing with remaining functions
================================================
task: 29583
[1] bar
[0] main

So, I retest it with uftrace record -vv

$ uftrace record -vv -A bar args 2> error.log

You can download the error.log file.

[namhyung]

Hmm.. it should count floating-point argument separately. Will fix, thanks.

[namhyung]

Pushed review/dwarf-argspec-v2.

Changelog:

• fix floating-point argument handling
• support return value
• integrated with --auto-args option. (But I'm not sure it's better limiting to well-known functions onlly)

$ uftrace --auto-args args
# DURATION    TID     FUNCTION
            [17293] | main(1, 0x7ffee8a7cd58) {
   0.258 us [17293] |   foo(-1, 32768) = 32767;
   0.613 us [17293] |   bar("string argument", 'c', 0.000010) = -1.000000;
   0.153 us [17293] |   null(NULL);
   4.443 us [17293] | } = 0; /* main */

[honggyukim]

It's working fine even for python interpreter as follows:

$ uftrace --auto-args python3.7 -c 'print("Hello Python")'
Hello Python
# DURATION    TID     FUNCTION
            [47039] | main(3, 0x7fffe8ae9d68) {
   0.652 us [47039] |   _PyMem_SetupAllocators("malloc") = 0;
            [47039] |   PyMem_RawMalloc(32) {
            [47039] |     _PyMem_RawMalloc(0, 32) {
   0.505 us [47039] |       malloc(32) = 0xe145d0;
   1.440 us [47039] |     } = 0xe145d0; /* _PyMem_RawMalloc */
   2.126 us [47039] |   } = 0xe145d0; /* PyMem_RawMalloc */
            [47039] |   PyMem_RawMalloc(32) {
            [47039] |     _PyMem_RawMalloc(0, 32) {
   0.140 us [47039] |       malloc(32) = 0xe14600;
   0.516 us [47039] |     } = 0xe14600; /* _PyMem_RawMalloc */
   0.769 us [47039] |   } = 0xe14600; /* PyMem_RawMalloc */
   1.163 us [47039] |   setlocale();
            [47039] |   _PyMem_RawStrdup("C") {
   0.865 us [47039] |     strlen("C") = 1;
            [47039] |     _PyMem_RawMalloc(0, 2) {
   0.208 us [47039] |       malloc(2) = 0xe14630;
   0.600 us [47039] |     } = 0xe14630; /* _PyMem_RawMalloc */
   0.913 us [47039] |     memcpy(0xe14630, 0x7f120aa7e957, 2) = 0xe14630;
   4.145 us [47039] |   } = "C"; /* _PyMem_RawStrdup */
    ...
            [47039] |           PyDict_New() {
            [47039] |             PyObject_Malloc(168) {
   1.902 us [47039] |               _PyObject_Malloc(0, 168) = 0x7f120b880030;
   2.340 us [47039] |             } = 0x7f120b880030; /* PyObject_Malloc */
            [47039] |             _PyObject_GC_New(0x88d700) {
            [47039] |               PyObject_Malloc(72) {
   1.947 us [47039] |                 _PyObject_Malloc(0, 72) = 0x7f120b881030;
   2.311 us [47039] |               } = 0x7f120b881030; /* PyObject_Malloc */
   7.649 us [47039] |             } = 0x7f120b881048; /* _PyObject_GC_New */
  11.676 us [47039] |           } = 0x7f120b881048; /* PyDict_New */
            [47039] |           PyUnicode_InternFromString("__getattribute__") {
   0.229 us [47039] |             strlen("__getattribute__") = 16;
            [47039] |             PyUnicode_DecodeUTF8Stateful("__getattribute__", 16, NULL, 0) {
            [47039] |               _PyUnicodeWriter_PrepareInternal(0x7fffe8ae9940, 16, 127) {
            [47039] |                 PyUnicode_New.part.34() {
            [47039] |                   PyObject_Malloc(65) {
   0.158 us [47039] |                     _PyObject_Malloc(0, 65) = 0x7f120b881078;
   0.700 us [47039] |                   } = 0x7f120b881078; /* PyObject_Malloc */
   1.041 us [47039] |                 } /* PyUnicode_New.part.34 */
   6.437 us [47039] |               } = 0; /* _PyUnicodeWriter_PrepareInternal */
            [47039] |               ascii_decode("__getattribute__", "", 0x7f120b8810a8) {
   0.263 us [47039] |                 memcpy(0x7f120b8810a8, 0x5f47db, 16) = 0x7f120b8810a8;
   1.021 us [47039] |               } = 16; /* ascii_decode */
   0.126 us [47039] |               _PyUnicodeWriter_Finish(0x7fffe8ae9940) = 0x7f120b881078;
   9.830 us [47039] |             } = 0x7f120b881078; /* PyUnicode_DecodeUTF8Stateful */
    ...

integrated with --auto-args option. (But I'm not sure it's better limiting to well-known functions onlly)

I think we need to change the description from well-known functions to just known funtions by builtin-prototypes or dwarf information.

[flavono123]

I want to test this feature.
To fetch this,

$ cd uftrace
$ git fetch origin review/dwarf-argspec-v2
$ git checkout review/dwarf-argspec-v2

Then recompile uftrace, go test right?

[namhyung]

I think you need to checkout origin/review/dwarf-argspec-v2

[flavono123]

I'm interesting in this issue and want to know more about libdw APIs.

Is there any references or libdw(DWARF) APIs doxygen?
Or looking for source codes is the best? 😱

[flavono123]

🖐 I tried a few set of patches, also a name of a function pointer can be traced with -A option:

$ cat funcp.c
#include <stdio.h>

void foo() {
	printf("foo\n");
}

void bar(void (*fp)()) {
	fp();
}
int main () {
	bar(foo);
	return 0;
}
$ gcc -pg -g -o funcp funcp.c
$ uftrace -A . funcp # before patch
foo
# DURATION    TID     FUNCTION
            [23290] | main() {
            [23290] |   bar(0x56425024076a) {
            [23290] |     foo() {
  40.785 us [23290] |       puts("foo");
  44.006 us [23290] |     } /* foo */
  45.392 us [23290] |   } /* bar */
  46.425 us [23290] | } /* main */
  
$ uftrace -A . funcp  # after patched
foo
# DURATION    TID     FUNCTION
            [23484] | main() {
            [23484] |   bar(&foo) {   # print function's name
            [23484] |     foo() {
  34.279 us [23484] |       puts("foo");
  37.320 us [23484] |     } /* foo */
  38.791 us [23484] |   } /* bar */
  39.730 us [23484] | } /* main */

It is original feature of uftrace in master branch, I just patched to generate the argspec for that automatically in util/dwarf.c:

...
static int arg_type_cb(Dwarf_Attribute *attr, void *arg)
...
          case DW_TAG_pointer_type:
               td->fmt = ARG_FMT_FUNC_PTR;
               done = true;
               continue;
...
static void add_type_info(char *spec, size_t len, Dwarf_Die *die, void *arg)
...
       case ARG_FMT_FUNC_PTR:
               strcat(spec, "/p");
...

But for this, I picked only 2 commits, 1e2dc9f and 0b29291, involved with ARG_FMR_FUNC_PTR:

### from the `origin/review/dwarf-argspec-v2` branch ###
$ git cherry-pick 1e2dc9f5
$ git cherry-pick 0b29291d
### ... do my patches ... ###

I cannot resolve the conflicts..
Here are patchfile and Compare Changes

[namhyung]

@flavono123 thanks for working on this. I need to rebase this branch on top of the current master (with auto-args merged). But I have some more work before doing that.

Did you make all pointers to function pointer? It works for the current implementation but not sure it's the right thing as it involves unnecessary symbol resolution for other type of characters.

[namhyung]

And for your information, it needs a lot more testing for C++ programs which have many subtleties..

[flavono123]

@namhyung Right. I do that following the current implementation(commits i picked).

You mean more work gonna be on the cmd-replay.c and/or the filter part?, not the dwarf?
(Add another arg format and how to print it ... ?)

It is sorry for that I have no idea about C++ now 😅

[namhyung]

No need to be sorry. :) I'm working on 'enum' type support for auto-args. After that DWARF can generate more detailed arg info automatically.

[honggyukim]

@namhyung Is it possible to make it work for binaries compiled with -finstrument-functions?

[namhyung]

I'm not sure. As cygprof_entry/exit can be called for inlined functions, the filter could not identify which one is normal or inlined. That would break the assumption of stack base offset IMO.

[honggyukim]

Hmm.. I need to check how gdb handles the arguments of inline functions when the binary is compiled with -finstrument-functions later on.

[namhyung]

Pushed review/dwarf-argspec-v3.

Changelog:

• support enum type

Example:

$ cat enum.c
enum xx { ONE = 1, TWO, };
void foo(enum xx x) {}
    
int main(void)
{
  foo(ONE);
  return 0;
}
    
$ gcc -g -pg -o enum enum.c
    
$ uftrace -A foo enum
# DURATION     TID     FUNCTION
            [ 17856] | main() {
   0.914 us [ 17856] |   foo(ONE);
   2.387 us [ 17856] | } /* main */

[honggyukim]

I've tested it using custom built cpython as follows:

$ uftrace -A . ./python -c 'print("hi")'
WARN: no trace data found
child terminated by signal: 11: Segmentation fault

The cpython is compiled with -pg -g flags. Here is the verbose error log.

$ uftrace -A -v ./python -c 'print("hi")'
    ...
filter: add filter for _PyGILState_GetInterpreterStateUnsafe
uftrace: found '_PyGILState_Fini' function for retspec
uftrace: found '_PyGILState_Reinit' function for retspec
uftrace: found 'PyGILState_GetThisThreadState' function for retspec
filter: add filter for PyGILState_GetThisThreadState
uftrace: found 'PyGILState_Check' function for retspec
filter: add filter for PyGILState_Check
uftrace: found 'PyGILState_Ensure' function for retspec
uftrace: all process/thread exited
child terminated by signal: 11: Segmentation fault
uftrace: stop writer thread 0
uftrace: stop writer thread 1
uftrace: reading symbols for session 38da7f6f8f9ef05a
symbol: loading symbols from /home/honggyu/src/python/git/cpython/python (offset: 0)
symbol: loaded 4155 symbols
    ...
symbol: saving symbols to /tmp/uftrace-live-NICDVz/ld-2.24.so.sym
symbol: unload symbol tables
uftrace: live-record finished.. 
uftrace: start live-replaying...
WARN: no trace data found
filter: parse enum uft_mmap_prot
filter: add enum definition for uft_mmap_prot
    ...
filter: add auto-argument for syscall
filter: add auto-argument for ioctl
fstack: setup argspec and/or retspec

[honggyukim]

Here is the steps to reproduce.

$ git clone https://github.com/python/cpython.git
$ cd cpython
$ ./configure --prefix=`pwd`/build.pg CFLAGS="-pg -g" CXXFLAGS="-pg -g"
$ ./python -c 'print("hi")'
hi

$ uftrace -A . ./python -c 'print("hi")'
WARN: no trace data found
child terminated by signal: 11: Segmentation fault

[namhyung]

Thanks for testing, there were some bugs handling unnamed enums. I've updated the v3 branch with the fix.

[honggyukim]

Thanks a lot for the fix. It works great!

$ uftrace -A . -R . -t 43ms ./python -c 'print("hi")'
hi
# DURATION     TID     FUNCTION
            [ 14017] | main(3, 0x7fffd3ec1ac8) {
            [ 14017] |   Py_Main(3, 0x55b6741fdf40) {
            [ 14017] |     _Py_InitializeMainInterpreter(0x7fffd3ec188c) {
            [ 14017] |       PyImport_ImportModule("site") {
            [ 14017] |         PyImport_Import(0x7f96d64e0d18) {
            [ 14017] |           PyObject_CallFunction(0x7f96d8cc8750, "OOOOi") {
            [ 14017] |             _PyObject_CallFunctionVa.part.2() {
            [ 14017] |               _PyObject_FastCallDict.constprop.6() {
            [ 14017] |                 _PyMethodDef_RawFastCallDict(0x55b67220dd00, 0x7f96d8d3dbd8, 0x7fffd3ec1630, 5, 0) {
            [ 14017] |                   builtin___import__(0x7f96d8d3dbd8, 0x7f96d65280a0, 0) {
            [ 14017] |                     PyImport_ImportModuleLevelObject(0x7f96d64e0d18, 0x7f96d64e3948, 0x7f96d64e3948, 0x7f96d8d0bec8, 0) {
            [ 14017] |                       _PyObject_CallMethodIdObjArgs(0x7f96d8cecf48, 0x55b6722158c0) {
            [ 14017] |                         object_vacall(0x7f96d8cfdd08, 0x7fffd3ec13a0) {
            [ 14017] |                           _PyObject_FastCallDict.constprop.6() {
            [ 14017] |                             _PyFunction_FastCallDict(0x7f96d8cfdd08, 0x7fffd3ec1330, 2, 0) {
            [ 14017] |                               function_code_fastcall(0x7f96d8cf4270, 0x7fffd3ec1330, 2, 0x7f96d8ce9ee8) {
            [ 14017] |                                 PyEval_EvalFrameEx(0x7f96d8d1c448, 0) {
  43.077 ms [ 14017] |                                   _PyEval_EvalFrameDefault(0x7f96d8d1c448, 0) = 0x7f96d64e4e08;
  43.078 ms [ 14017] |                                 } = 0x7f96d64e4e08; /* PyEval_EvalFrameEx */
  43.079 ms [ 14017] |                               } = 0x7f96d64e4e08; /* function_code_fastcall */
  43.080 ms [ 14017] |                             } = 0x7f96d64e4e08; /* _PyFunction_FastCallDict */
  43.080 ms [ 14017] |                           } /* _PyObject_FastCallDict.constprop.6 */
  43.080 ms [ 14017] |                         } = 0x7f96d64e4e08; /* object_vacall */
  43.081 ms [ 14017] |                       } = 0x7f96d64e4e08; /* _PyObject_CallMethodIdObjArgs */
  43.086 ms [ 14017] |                     } = 0x7f96d64e4e08; /* PyImport_ImportModuleLevelObject */
  43.088 ms [ 14017] |                   } = 0x7f96d64e4e08; /* builtin___import__ */
  43.090 ms [ 14017] |                 } = 0x7f96d64e4e08; /* _PyMethodDef_RawFastCallDict */
  43.090 ms [ 14017] |               } /* _PyObject_FastCallDict.constprop.6 */
  43.092 ms [ 14017] |             } /* _PyObject_CallFunctionVa.part.2 */
  43.092 ms [ 14017] |           } = 0x7f96d64e4e08; /* PyObject_CallFunction */
  43.109 ms [ 14017] |         } = 0x7f96d64e4e08; /* PyImport_Import */
  43.111 ms [ 14017] |       } = 0x7f96d64e4e08; /* PyImport_ImportModule */
  73.961 ms [ 14017] |     } = 0; /* _Py_InitializeMainInterpreter */
 126.808 ms [ 14017] |   } = 0; /* Py_Main */
 126.868 ms [ 14017] | } = 0; /* main */

By the way, do you want to use --auto-args only for library function calls? I think it needs to be clear between -A . -R . and --auto-args.

[honggyukim]

I have one more idea to ask you. There are so many address values in the argument display, but it'd be better to have its struct or pointer type name to give better idea to users. For example, instead of the below output,

PyObject_CallFunction(0x7f96d8cc8750, "OOOOi") {
    ...
} = 0x7f96d64e4e08; /* PyObject_CallFunction */

It could be more informative with type information as follows:

PyObject_CallFunction((Py_Object*)0x7f96d8cc8750, "OOOOi") {
    ...
} = (PyObject*)0x7f96d64e4e08; /* PyObject_CallFunction */

Or, it could also show the variable name as well.

PyObject_CallFunction((Py_Object* callable)0x7f96d8cc8750, "OOOOi") {
    ...
} = (PyObject*)0x7f96d64e4e08; /* PyObject_CallFunction */

I'm just telling you the basic idea, so please let me know any kind of your thought about it.

[namhyung]

I think it's possible to get type info of library functions (if it's #included in the header file). But I'd like to leave it as a next step.

What do you mean by "assertion like dump"?

[honggyukim]

I think it's possible to get type info of library functions (if it's #included in the header file). But I'd like to leave it as a next step.

I'm okay with it.

What do you mean by "assertion like dump"?

I don't remember exactly but if str is NULL, I mean we can add protection code rather than just showing segfault. If it's not NULL but just invalid address, then it may not be possible though.

[namhyung]

It already checks NULL - all failure cases I saw had invalid addresses, thanks.

[honggyukim]

I see. Thanks for the explanation.

[honggyukim]

It seems that dwarf info is not made for functions that are marked as small t rather than T. I tested it for std::sort but the function args info is not made in .dbg file.

Here is the symbol field for std::sort after demangling.

00000000000009ca t void std::sort<int*, main::{lambda(int, int)#1}>(int*, main::{lambda(int, int)#1}, main::{lambda(int, int)#1})

But I don't find any info in .dbg file for that function so it doesn't record args/retval for std::sort.

[honggyukim]

You can test it with the below example:

#include <iostream>
#include <algorithm>

bool cmp_less(int a, int b)
{
    return a < b;
}

int main()
{
    int x[5] = { 1, 3, 5, 7, 9 };
    std::sort(x, x + 5, cmp_less);
    std::sort(x, x + 5, [](int a, int b) { return a < b; });
}

$ g++ -std=c++11 -pg -g sort.cc
$ uftrace -A. -R. a.out
        ...
            [120954] | main() {
            [120954] |   std::sort() {
            [120954] |     __gnu_cxx::__ops::__iter_comp_iter() {
   0.380 us [120954] |       __gnu_cxx::__ops::_Iter_comp_iter::_Iter_comp_iter(0x7ffef7ebad90, 0x4008a6);
   1.340 us [120954] |     } = 0x4008a6; /* __gnu_cxx::__ops::__iter_comp_iter */
            [120954] |     std::__sort() {
   0.330 us [120954] |       std::__lg(5) = 2;
        ...

[namhyung]

It seems DWARF doesn't have linkage name for some entries and it makes fail to match.

[namhyung]

Pushed review/dwarf-argspec-v17

Changelog:

• fix NULL dereference resolve_type_info() (thanks Honggyu!)
• improve C++ dwarf parsing (iterator all children of subprogram)
• match last component if DIE doesn't have linkage name for C++
• support function pointer type

$ uftrace -A. -R. -D3 a.out
# DURATION     TID     FUNCTION
            [ 21338] | _GLOBAL__sub_I__Z8cmp_lessii() {
            [ 21338] |   __static_initialization_and_destruction_0(1, 65535) {
 132.674 us [ 21338] |     std::ios_base::Init::Init();
 143.191 us [ 21338] |   } /* __static_initialization_and_destruction_0 */
 145.048 us [ 21338] | } /* _GLOBAL__sub_I__Z8cmp_lessii */
            [ 21338] | main() {
            [ 21338] |   std::sort(0x7ffd00d074d0, 0x7ffd00d074e4, &cmp_less) {
   1.186 us [ 21338] |     __gnu_cxx::__ops::__iter_comp_iter(&cmp_less) = 0x55e0b7ec88e6;
   7.360 us [ 21338] |     std::__sort(0x7ffd00d074d0, 0x7ffd00d074e4, 0x55e0b7ec88e6);
  11.066 us [ 21338] |   } /* std::sort */
            [ 21338] |   std::sort(0x7ffd00d074d0, 0x7ffd00d074e4) {
   0.911 us [ 21338] |     __gnu_cxx::__ops::__iter_comp_iter() = 0;
   7.098 us [ 21338] |     std::__sort(0x7ffd00d074d0, 0x7ffd00d074e4, 0x7ffd00d074e4);
   9.512 us [ 21338] |   } /* std::sort */
  21.776 us [ 21338] | } = 0; /* main */

[honggyukim]

Thanks a lot. It looks good but I have two more comments.

• The second sort doesn't show lambda function pointer at the 3rd parameter.
• It still gets segfault at v8::internal::ConstructEntryFrame::type() when running it for lld linked v8 binary.

[honggyukim]

And could you please check the test in #79?

$ uftrace -A . -R. -D 2 a.out
# DURATION     TID     FUNCTION
            [127061] | main() {
   2.207 us [127061] |   foo(10) = 11;
  21.607 us [127061] |   bar(0x7ffe3241a810) = 0x7ffe3241a810;
   6.320 us [127061] |   std::vector::~vector(0x7ffe3241a810);
  34.054 us [127061] | } = 0; /* main */

[namhyung]

It seems lambda function is passed as an empty struct, so it got ignored. I'll add a check.

[honggyukim]

Right. lambda function is not an empty struct only when it captures some variables. It's usually an empty struct that has only operator() function otherwise.

[honggyukim]

There can be one more example, please test it with the below example.

#include <iostream>
#include <algorithm>

bool cmp_less(int a, int b)
{
    return a < b;
}

int main()
{
    int x[5] = { 1, 3, 5, 7, 9 };
    std::sort(x, x + 5, cmp_less);
    std::sort(x, x + 5, [](int a, int b) { return a < b; });
    std::sort(x, x + 5, std::less<int>());
}

std::less<int>() is a temporary object and it's also an empty struct.

[honggyukim]

FYI, std::less looks like below:

  /// One of the @link comparison_functors comparison functors@endlink.
  template<typename _Tp>
    struct less : public binary_function<_Tp, _Tp, bool>
    {
      _GLIBCXX14_CONSTEXPR
      bool
      operator()(const _Tp& __x, const _Tp& __y) const
      { return __x < __y; }
    };

  /**
   *  This is one of the @link functors functor base classes@endlink.
   */
  template<typename _Arg1, typename _Arg2, typename _Result>
    struct binary_function
    {
      /// @c first_argument_type is the type of the first argument
      typedef _Arg1     first_argument_type;

      /// @c second_argument_type is the type of the second argument
      typedef _Arg2     second_argument_type;

      /// @c result_type is the return type
      typedef _Result   result_type;
    };

[namhyung]

It seems clang puts invalid DWARF info for the function.. sigh..

[namhyung]

Pushed review/dwarf-argspec-v18

Changelog:

• show empty lambda struct again
• check broken return value first
• ignore conflicted debug info
• check memory region before string dereference

[honggyukim]

Thanks a lot for the update! It works fine with lld linked V8 binary.

I have one more thing to discuss. We use -A . and -R . to record args/retvals for every functions, but I think we better have a new option for that as well. So what about adding --dwarf-args or --debug-args for that? I think --debug-args is more general name.

[honggyukim]

One more issue is that old uftrace cannot read uftrace data that is recorded by this dwarf supported version. It currently shows error messages as follows:

$ uftrace replay
WARN: invalid rstack read
WARN: invalid rstack read
WARN: invalid rstack read
WARN: invalid rstack read
WARN: invalid rstack read
WARN: invalid rstack read
WARN: invalid rstack read
WARN: invalid rstack read
uftrace: /home/honggyu/work/uftrace/git/uftrace/cmds/replay.c:478: get_argspec_string: Assertion `arg_list && !list_empty(arg_list)' failed.
# DURATION     TID     FUNCTION
            [ 21969] | _GLOBAL__sub_I_d8.cc() {
   0.378 us [ 21969] |   __cxa_atexit();
            [ 21969] |   v8::base::TimeTicks::HighResolutionNow() {
   0.154 us [ 21969] |     clock_gettime();
Aborted (core dumped)

Would it be possible to show better error message? I think we better suggest to use higher version of uftrace.

[honggyukim]

I have one more question. Is it possible to get dwarf info for std::string?
It currently shows only the address, but we can do better if we can get dwarf info for std::string.

$ uftrace -A. -R. test/t-std-string
        ...
            [ 12915] | main() {
            [ 12915] |   std_string_arg(0x6020a0) {
   1.846 us [ 12915] |     std::basic_string<>::operator=();
   2.832 us [ 12915] |   } /* std_string_arg */
            [ 12915] |   std_string_arg(0x6020a8) {
   0.200 us [ 12915] |     std::basic_string<>::operator=();
   0.894 us [ 12915] |   } /* std_string_arg */
            [ 12915] |   std_string_arg(0x6020b0) {
   0.140 us [ 12915] |     std::basic_string<>::operator=();
   0.714 us [ 12915] |   } /* std_string_arg */
            [ 12915] |   std_string_ret(0x7fff6e092240) {
   0.838 us [ 12915] |     std::basic_string<>::basic_string<>();
   1.602 us [ 12915] |   } = 0x7fff6e092240; /* std_string_ret */
   1.238 us [ 12915] |   std::basic_string<>::~basic_string<>();
            [ 12915] |   std_string_ret(0x7fff6e092240) {
   0.175 us [ 12915] |     std::basic_string<>::basic_string<>();
   0.824 us [ 12915] |   } = 0x7fff6e092240; /* std_string_ret */
   0.209 us [ 12915] |   std::basic_string<>::~basic_string<>();
            [ 12915] |   std_string_ret(0x7fff6e092240) {
   0.166 us [ 12915] |     std::basic_string<>::basic_string<>();
   0.702 us [ 12915] |   } = 0x7fff6e092240; /* std_string_ret */
   0.168 us [ 12915] |   std::basic_string<>::~basic_string<>();
  12.935 us [ 12915] | } = 0; /* main */
        ...

[honggyukim]

Thinking again, it'd be better not to cover std::string yet because it may sometimes be unsafe to read string. So let's leave it now. Thanks.

[namhyung]

Right, I'd like to leave it for now, it can be added later..

Regarding to the old versions, it's hard since we cannot change released version. One thing I can think of is adding a new feature bit so that users can notice there's an unsupported feature.

[honggyukim]

Regarding to the old versions, it's hard since we cannot change released version. One thing I can think of is adding a new feature bit so that users can notice there's an unsupported feature.

Right. I understand that. I just hoped as general users' point of view.

[namhyung]

Pushed review/dwarf-argspec-v19

Changelog:

• do not call sscanf() in update_mem_regions() due to crash
• add a few of test cases
• add DEBUG_INFO feature bit
• save and restore arch-context (FP registers) around update_mem_regions().
• ensure proper alignment of argument context location
• don't change argument ordering

[honggyukim]

Thanks for the update. I have only trivial comments for v19.

• better to remove trailing whitespace at tests/s-dwarf1.c:30
• better to be rebased once again.
• t202_dwarf2.py has to provide -std=c++11 flag to avoid a build error in old compilers.
• t203_dwarf3.py fails for -O2, -O3, -Os.

t203_dwarf3: diff result of -pg -Os
--- expect      2018-07-05 22:30:15.704487042 +0900
+++ result      2018-07-05 22:30:15.704487042 +0900
@@ -2,6 +2,6 @@
    C::C(0xADDR, 1, "debug info") {
-     C::construct(0xADDR, 1, "debug info");
+     C::copy(0xADDR, 1, "debug info");
    } /* C::C */
    C::C(0xADDR, 2, "<0xADDR>") {
-     C::construct(0xADDR, 2, "<0xADDR>");
+     C::copy(0xADDR, 2, "<0xADDR>");
    } /* C::C */
@@ -10,7 +10,7 @@
    } /* C::C */
-   foo(0xADDR, 0xADDR, 0xADDR, 0.001000) {
+   foo(0xADDR, 1, 0.000000, 2) {
      C::C(0xADDR, 3, "passed by value") {
-       C::construct(0xADDR, 3, "passed by value");
+       C::copy(0xADDR, 3, "passed by value");
      } /* C::C */
-   } = 0xADDR; /* foo */
+   } /* foo */
  } = 0; /* main */

203 dwarf3              : OK OK NG NG NG

[namhyung]

Pushed review/dwarf-argspec-v20. The dwarf3 test still fails ...

Changelog:

• fix issues reported by Honggyu (thanks!)
• add documentation
• merge independent fixes separately