Closed namhyung closed 5 years ago
namhyung
commented
6 years ago Pushed an premature implementation to review/dwarf-argspec-v1.
Note:
-A option for now-finstrument-functions yet
honggyukim
commented
6 years ago 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
commented
6 years ago 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 */I've checked it again but found that I should have to run ./configure again before compilation.
It works fine now. :)
honggyukim
commented
6 years ago 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
commented
6 years ago 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: xenialAfter 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
commented
6 years ago @honggyukim retval is not supported yet, sorry.
@Taeung thanks for testing!
Taeung
commented
6 years ago @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
commented
6 years ago Hmm.. it should count floating-point argument separately. Will fix, thanks.
namhyung
commented
6 years ago Pushed review/dwarf-argspec-v2.
Changelog:
--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 */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
commented
6 years ago I want to test this feature. To fetch this,
$ cd uftrace
$ git fetch origin review/dwarf-argspec-v2
$ git checkout review/dwarf-argspec-v2Then recompile uftrace, go test right?
namhyung
commented
6 years ago I think you need to checkout origin/review/dwarf-argspec-v2
flavono123
commented
6 years ago 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
commented
6 years ago 🖐 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, 1e2dc9f5 and 0b29291d, 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
commented
6 years ago @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
commented
6 years ago And for your information, it needs a lot more testing for C++ programs which have many subtleties..
flavono123
commented
6 years ago @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
commented
6 years ago 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
commented
6 years ago @namhyung Is it possible to make it work for binaries compiled with -finstrument-functions?
namhyung
commented
6 years ago 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
commented
6 years ago Hmm.. I need to check how gdb handles the arguments of inline functions when the binary is compiled with -finstrument-functions later on.
namhyung
commented
6 years ago Pushed review/dwarf-argspec-v3.
Changelog:
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 */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 faultThe 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
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 faultThanks for testing, there were some bugs handling unnamed enums. I've updated the v3 branch with the fix.
honggyukim
commented
6 years ago 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
commented
6 years ago 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.
honggyukim
commented
6 years ago Sorry but, I have one more to talk to you. It seems that it doesn't understand the dwarf information inside shared library. Please check this.
namhyung
commented
6 years ago Yes, I'd like to keep --auto-args only for well-known functions. Currently I cannot guarantee the quality of the DWARF parser so it might misunderstand the location of arguments and return values. And it could result in segfault in case of invalid pointer dereference (for string).
Regarding the type info, I'm not sure what is good and how can implement. Basically more information is better but it also comes with overhead in both speed and space. Also I think the information should be used without DWARF but I have no idea how it can be done. Quality issue can be a problem as well - a type info can be very complex like C++ templates or so. And it might hurt readability if type name is very long and there are many arguments.
Lastly, current code only support the main executable only, I'll try to fix it in the next version.
honggyukim
commented
6 years ago Yes, I'd like to keep --auto-args only for well-known functions. Currently I cannot guarantee the quality of the DWARF parser so it might misunderstand the location of arguments and return values. And it could result in segfault in case of invalid pointer dereference (for string).
Understand that. Thanks!
Regarding the type info, I'm not sure what is good and how can implement. Basically more information is better but it also comes with overhead in both speed and space. Also I think the information should be used without DWARF but I have no idea how it can be done. Quality issue can be a problem as well - a type info can be very complex like C++ templates or so. And it might hurt readability if type name is very long and there are many arguments.
Yes, I know it's very difficult to implement in a correct way but I meant that it's from only user's perspective, not as a developer. Sorry :(
Lastly, current code only support the main executable only, I'll try to fix it in the next version.
Thanks. I think the current state is very good but it could be the next improvement point.
namhyung
commented
6 years ago Pushed review/dwarf-argspec-v4
Changelog:
honggyukim
commented
6 years ago @namhyung Thanks a lot for doing this work! It seems it works fine with libraries but I need more test. I will test this more with better examples later.
namhyung
commented
6 years ago namhyung
commented
6 years ago Pushed review/dwarf-argspec-v6
Changelog:
honggyukim
commented
6 years ago Sorry, I cannot fully review and test this feature as of now but found the below message from review/dwarf-argspec-v4 to the latest update.
$ ./configure --prefix=$HOME/usr
Package liblzma was not found in the pkg-config search path.
Perhaps you should add the directory containing `liblzma.pc'
to the PKG_CONFIG_PATH environment variable
Package 'liblzma', required by 'libdw', not foundThis message is shown although libdw-dev is already installed in the system. Do we need some more protection code for this?
honggyukim
commented
6 years ago It doesn't make any other problem when compiling and installing but looks like a noise.
$ make install
Package liblzma was not found in the pkg-config search path.
Perhaps you should add the directory containing `liblzma.pc'
to the PKG_CONFIG_PATH environment variable
Package 'liblzma', required by 'libdw', not found
INSTALL uftrace
INSTALL libmcount
INSTALL bash-completion
GEN uftrace.1
GEN uftrace-record.1
GEN uftrace-replay.1
GEN uftrace-live.1
GEN uftrace-report.1
GEN uftrace-recv.1
GEN uftrace-info.1
GEN uftrace-dump.1
GEN uftrace-graph.1
GEN uftrace-script.1
INSTALL man-pagesIt seems libdw-dev lacks a dependency to liblzma-dev in your system.
namhyung
commented
6 years ago Pushed review/dwarf-argspec-v7
Changelog:
honggyukim
commented
6 years ago Thanks for keep updating it. But I found some crash when I trace uftrace itself as follows:
$ uftrace -A. -R. ./uftrace replay
# DURATION TID FUNCTION
6.220 us [ 77009] | cap_get_proc();
0.937 us [ 77009] | cap_init();
0.803 us [ 77009] | cap_get_flag();
0.153 us [ 77009] | cap_get_flag();
3.264 us [ 77009] | cap_set_proc();
2.807 us [ 77009] | prctl();
1.304 us [ 77009] | getuid();
3.310 us [ 77009] | setuid();
0.887 us [ 77009] | prctl();
1.793 us [ 77009] | cap_free();
0.247 us [ 77009] | cap_free();
0.257 us [ 77009] | getuid();
1.084 us [ 77009] | geteuid();
0.846 us [ 77009] | cap_get_proc();
0.140 us [ 77009] | cap_get_flag();
0.214 us [ 77009] | cap_free();
7.007 us [ 77009] | socket();
1.214 us [ 77009] | __errno_location();
0.767 us [ 77009] | cap_get_proc();
0.167 us [ 77009] | cap_get_flag();
0.163 us [ 77009] | cap_free();
6.877 us [ 77009] | getopt();
1.304 us [ 77009] | strtol();
0.410 us [ 77009] | getopt();
5.887 us [ 77009] | inet_aton();
262.575 us [ 77009] | gethostbyname2();
2.070 us [ 77009] | strncpy();
5.243 us [ 77009] | socket();
12.190 us [ 77009] | connect();
2.710 us [ 77009] | getsockname();
6.370 us [ 77009] | close();
21.511 us [ 77009] | perror();
[ 77009] | exit() {
uftrace stopped tracing with remaining functions
================================================
task: 77009
[0] exit
WARN: invalid rstack read
uftrace: /home/honggyu/work/uftrace/git/uftrace/cmd-replay.c:478: get_argspec_string: Assertion `arg_list && !list_empty(arg_list)' failed.
# DURATION TID FUNCTION
Aborted (core dumped)The target uftrace is compiled with TRACE=1 build flag.
namhyung
commented
6 years ago Hmm.. I'm seeing following errors.. Now sure why they're used for arguments. Anyway it doesn't support such registers so they should be ignored IMO.
Usage: unknown register name: arg1%rax
Usage: unknown register name: arg1%r11
Usage: unknown register name: arg1%rax
Usage: unknown register name: arg1%rax
Usage: unknown register name: arg1%r11
Usage: unknown register name: arg1%rax
Usage: unknown register name: arg2%r14
Usage: unknown register name: arg2%r15Pushed review/dwarf-argspec-v8.
Changelog:
honggyukim
commented
6 years ago There's some tiny mistakes so have to be fixed as follows:
diff --git a/arch/x86_64/regs.c b/arch/x86_64/regs.c
index b3928ba..74ceb34 100644
--- a/arch/x86_64/regs.c
+++ b/arch/x86_64/regs.c
@@ -34,20 +34,20 @@ int arch_register_index(char *reg_name)
static const struct x86_reg_table dwarf_table[] = {
/* support registers used for arguments */
- { "rdx", DW_OP_reg1, },
- { "rcx", DW_OP_reg2, },
- { "rsi", DW_OP_reg4, },
- { "rdi", DW_OP_reg5, },
- { "r8", DW_OP_reg8, },
- { "r9", DW_OP_reg9, },
- { "xmm0", DW_OP_reg17, }
- { "xmm1", DW_OP_reg18, }
- { "xmm2", DW_OP_reg19, }
- { "xmm3", DW_OP_reg20, }
- { "xmm4", DW_OP_reg21, }
- { "xmm5", DW_OP_reg22, }
- { "xmm6", DW_OP_reg23, }
- { "xmm7", DW_OP_reg24, }
+ { "rdx", DW_OP_reg1 },
+ { "rcx", DW_OP_reg2 },
+ { "rsi", DW_OP_reg4 },
+ { "rdi", DW_OP_reg5 },
+ { "r8", DW_OP_reg8 },
+ { "r9", DW_OP_reg9 },
+ { "xmm0", DW_OP_reg17 },
+ { "xmm1", DW_OP_reg18 },
+ { "xmm2", DW_OP_reg19 },
+ { "xmm3", DW_OP_reg20 },
+ { "xmm4", DW_OP_reg21 },
+ { "xmm5", DW_OP_reg22 },
+ { "xmm6", DW_OP_reg23 },
+ { "xmm7", DW_OP_reg24 },
};
const char * arch_register_dwarf_name(int dwarf_reg)And I've tested it tracing uftrace itself, but it also gets crashed.
$ uftrace -t 10ms -A. -R. --no-pager ./uftrace --no-pager replay
# DURATION TID FUNCTION
1.254 us [ 88797] | __monstartup();
0.994 us [ 88797] | __cxa_atexit();
[ 88797] | main() {
13.597 us [ 88797] | puts();
1.580 us [ 88797] | fflush();
10.500 us [ 88797] | malloc();
[ 88797] | foo() {
8.656 us [ 88797] | fprintf();
4.254 us [ 88797] | malloc();
1.834 us [ 88797] | free();
17.724 us [ 88797] | } /* foo */
4.713 us [ 88797] | puts();
0.556 us [ 88797] | malloc();
15.564 us [ 88797] | memcpy();
0.450 us [ 88797] | free();
9.563 us [ 88797] | free();
81.490 us [ 88797] | } /* main */
WARN: invalid rstack read
# DURATION TID FUNCTION
uftrace: /home/honggyu/work/uftrace/git/uftrace/cmd-replay.c:478: get_argspec_string: Assertion `arg_list && !list_empty(arg_list)' failed.
Aborted (core dumped)$ cgdb uftrace core
...
439│ void get_argspec_string(struct ftrace_task_handle *task,
440│ char *args, size_t len,
441│ enum argspec_string_bits str_mode)
442│ {
443│ int i = 0, n = 0;
444│ char *str = NULL;
...
467│ if (!has_more) {
468│ if (needs_paren)
469│ strcpy(args, "()");
470│ else {
471│ if (is_retval && needs_semi_colon)
472│ args[n++] = ';';
473│ args[n] = '\0';
474│ }
475│ return;
476│ }
477│
478├───────> assert(arg_list && !list_empty(arg_list));
(gdb) bt
#0 0x00007f239d653428 in raise () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007f239d65502a in abort () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x00007f239d64bbd7 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#3 0x00007f239d64bc82 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#4 0x00000000004169c2 in get_argspec_string (task=0x2349660, args=0x7fffd21f5ea0 "a?F", len=1024, str_mode=NEEDS_ESCAPE_BIT) at /home/honggyu/work/uftrace/git/uftrace/cmd-replay.c:478
#5 0x000000000041792e in print_graph_rstack (handle=0x7fffd21f6710, task=0x2349660, opts=0x7fffd21f6a50) at /home/honggyu/work/uftrace/git/uftrace/cmd-replay.c:749
#6 0x00000000004189cc in command_replay (argc=7, argv=0x7fffd21f6c78, opts=0x7fffd21f6a50) at /home/honggyu/work/uftrace/git/uftrace/cmd-replay.c:1081
#7 0x00000000004099b3 in command_live (argc=7, argv=0x7fffd21f6c78, opts=0x7fffd21f6a50) at /home/honggyu/work/uftrace/git/uftrace/cmd-live.c:179
#8 0x0000000000406a53 in main (argc=7, argv=0x7fffd21f6c78) at /home/honggyu/work/uftrace/git/uftrace/uftrace.c:1021
(gdb) p arg_list
$1 = (struct list_head *) 0x0
(gdb) p task
$2 = (struct ftrace_task_handle *) 0x2349660
(gdb) p task->args
$3 = {
args = 0x0,
len = 0,
data = 0x234e120
}
(gdb) p str_mode
$4 = NEEDS_ESCAPE_BITHmm.. it seems that libdw-dev package doesn't properly install .pc its file.
$ make clean
CLEAN uftrace
CLEAN test
CLEAN man-pages
CLEAN libtraceevent
$ sudo apt-get install libdw-dev
Reading package lists... Done
Building dependency tree
Reading state information... Done
libdw-dev is already the newest version.
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
$ git branch
master
* review/dwarf-argspec-v7
$ ./configure
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
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@honggyukim sorry for delay. I don't understand how I missed the compile error at the time. Anyway I'll try to investigate the crash.
honggyukim
commented
6 years ago @namhyung I appreciate your constant effort for this work. Thank you very much!
namhyung
commented
6 years ago I found that there's a bug during record. It didn't save dwarf information to .dbg files for the main executable due to mismatch in symbol addresses. My system produces PIE by default so I missed it has a problem in non-PIE binaries. I guess others (libraries) are fine since they always use PC-relative address.
Pushed to review/dwarf-argspec-v9
Changelog:
honggyukim
commented
6 years ago Thanks for the update. It works fine for tracing uftrace itself now but I have another problem on tracing telegram program.
Please follow the sequence below: 1. build
$ git clone --recursive https://github.com/vysheng/tg.git && cd tg
$ ./configure --disable-liblua
$ make CFLAGS="-pg -g" CXXFLAGS="-pg -g" -j9
$ cd bin2. run with uftrace
$ uftrace ./telegram-cli --help # it works fine
$ uftrace record -A. -R. ./telegram-cli --help
$ uftrace replay
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
Aborted (core dumped)Here is the backtrace info.
$ gdb --args uftrace replay --no-pager
...
(gdb) bt
#0 0x00007ffff67d8428 in raise () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff67da02a in abort () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x00007ffff67d0bd7 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#3 0x00007ffff67d0c82 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#4 0x0000000000416d50 in get_argspec_string (task=task@entry=0x7e8c80, args=args@entry=0x7fffffffd820 "", len=len@entry=1024, str_mode=<optimized out>) at /h
ome/honggyu/work/uftrace/git/uftrace/cmds/replay.c:478
#5 0x0000000000417500 in print_graph_rstack (opts=<optimized out>, task=0x7e8c80, handle=0x7fffffffd660) at /home/honggyu/work/uftrace/git/uftrace/cmds
/replay.c:749
#6 command_replay (argc=<optimized out>, argv=argv@entry=0x7fffffffe400, opts=opts@entry=0x7fffffffe100) at /home/honggyu/work/uftrace/git/uftrace/cmds
/replay.c:1068
#7 0x0000000000405822 in main (argc=0, argv=0x7fffffffe400) at /home/honggyu/work/uftrace/git/uftrace/uftrace.c:1034
(gdb) frame 4
#4 0x0000000000423a2e in get_argspec_string (task=0x802c80, args=0x7fffffffd710 "\241\203F", len=1024, str_mode=NEEDS_ESCAPE_BIT) at /home/honggyu/work/uftra
ce/git/uftrace/cmds/replay.c:478
(gdb) list
473 args[n] = '\0';
474 }
475 return;
476 }
477
478 assert(arg_list && !list_empty(arg_list));
479
480 if (needs_paren)
481 args[n++] = '(';
482 else if (needs_assignment) {
(gdb) p arg_list
$2 = (struct list_head *) 0x0Please take a look at it. Thanks!
honggyukim
commented
6 years ago It shows the similar problem when tracing python interpreter.
$ uftrace record -A. -R. ./python3.7 -c 'print("hello python")'
hello python
$ uftrace replay
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
Aborted (core dumped)Does the data have .dbg files?
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
-Aor-Roption 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:
With DWARF support, it should work like below: