automatic argument for well-known functions #173

namhyung · 2017-10-11T08:35:50Z

While #158 and #171 from @honggyukim added support for automatic argument and return value record/display with --auto-args option, I'd like to suggest a different way to use it.

For me, argument is additional information takes some time and space when recording. So it needs to be controlled to reduce performance impact as long as possible. Instead of enabling all know arguments and return values for those functions, making it selectable with -A and -R option would be the way to go IMHO.

But I'm still open to other opinions. Please suggest if you could come up with a new idea.

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

namhyung · 2017-10-11T08:44:59Z

Pushed the PoC code to review/auto-args-v1.

It uses "auto-args.h" and the "gen-autoargs.py" from the code of @honggyukim. You can just give function name (or pattern) to the -A or -R option to use the auto-args. Specifing explicit argspec will override it.

$ uftrace -A . openclose
# DURATION    TID     FUNCTION
   1.192 us [ 6714] | __monstartup();
   0.783 us [ 6714] | __cxa_atexit();
            [ 6714] | main() {
   8.609 us [ 6714] |   open("/dev/null", 0);
   4.467 us [ 6714] |   close(3);
  15.012 us [ 6714] | } /* main */

$ uftrace -A open@arg1 -A close -R open openclose
# DURATION    TID     FUNCTION
   1.745 us [ 6963] | __monstartup();
   0.997 us [ 6963] | __cxa_atexit();
            [ 6963] | main() {
   9.473 us [ 6963] |   open(0x40078c) = 3;
   5.477 us [ 6963] |   close(3);
  17.376 us [ 6963] | } /* main */

honggyukim · 2017-10-16T01:38:07Z

Hi @namhyung,

As discussed on the last meeting, I'm okay on this interface also with --auto-args so if you agree on adding --auto-args, I will create another merged branch review/auto-args-v1.2 on my repo using some of your commits.

And one more thing I have to tell you is that, I've got the below warning messages when running gcc binary.

$ uftrace --force -A . -R . /usr/bin/gcc hello.c
WARN: argument data is too big
WARN: argument data is too big
WARN: argument data is too big
WARN: argument data is too big
WARN: argument data is too big
WARN: argument data is too big
WARN: argument data is too big
WARN: argument data is too big
    ...
   0.227 us [142437] | malloc(10) = 0x24fd510;
   0.253 us [142437] | memcpy(0x24fd510, 0x47e470, 4) = 0x24fd510;
   0.230 us [142437] | memcpy(0x24fd514, 0x24fd554, 5) = 0x24fd514;
   0.214 us [142437] | free(0x24fd550);
   0.313 us [142437] | strchr("/usr/lib/", '.') = NULL;
   0.250 us [142437] | strlen("/usr/lib/") = 9;
   0.220 us [142437] | malloc(32) = 0x24fd570;
   2.670 us [142437] | strncmp("mtune=generic", "E|M|MM:%(trad_capable_cpp) %(cpp_options) %(cpp_debug_options)}      %{!E:%{!M:%{!MM:          %{traditional:%eGNU C no longer supports -
traditional without -E}      %{save-temps*|traditional-cpp|no-integrated-cpp:%(trad_capable_cpp)          %(cpp_options) -o %{save-temps*:%b.i} %{!save-temps*:%g.i} 
            cc1 -fpreprocessed %{save-temps*:%b.i} %{!save-temps*:%g.i}           %(cc1_options) %(ssp_default)}      %{!save-temps*:%{!traditional-cpp:%{!no-integrated-cpp:     cc1 %(cp
p_unique_options) %(cc1_options) %(ssp_default)}}}      %{!fsyntax-only:%(invoke_as)}}}}", 1) = 40;
   1.516 us [142437] | strncmp("march=x86-64", "E|M|MM:%(trad_capable_cpp) %(cpp_options) %(cpp_debug_options)}      %{!E:%{!M:%{!MM:          %{traditional:%eGNU C no longer supports -t
raditional without -E}      %{save-temps*|traditional-cpp|no-integrated-cpp:%(trad_capable_cpp)           %(cpp_options) -o %{save-temps*:%b.i} %{!save-temps*:%g.i} 
            cc1 -fpreprocessed %{save-temps*:%b.i} %{!save-temps*:%g.i}           %(cc1_options) %(ssp_default)}      %{!save-temps*:%{!traditional-cpp:%{!no-integrated-cpp:     cc1 %(cp
p_unique_options) %(cc1_options) %(ssp_default)}}}      %{!fsyntax-only:%(invoke_as)}}}}", 1) = 40;
   1.514 us [142437] | strncmp("mtune=generic", "M|MM:%(trad_capable_cpp) %(cpp_options) %(cpp_debug_options)}      %{!E:%{!M:%{!MM:          %{traditional:%eGNU C no longer supports -tr
aditional without -E}      %{save-temps*|traditional-cpp|no-integrated-cpp:%(trad_capable_cpp)    %(cpp_options) -o %{save-temps*:%b.i} %{!save-temps*:%g.i} 
            cc1 -fpreprocessed %{save-temps*:%b.i} %{!save-temps*:%g.i}           %(cc1_options) %(ssp_default)}      %{!save-temps*:%{!traditional-cpp:%{!no-integrated-cpp:     cc1 %(cp
p_unique_options) %(cc1_options) %(ssp_default)}}}      %{!fsyntax-only:%(invoke_as)}}}}", 1) = 32;
    ...

We have to limit the length of string or change the buffer to be allocated on heap. I've limitted the length of string to 48 in 0df48da but we can also change the length limit to 64 or more.

namhyung · 2017-10-16T04:48:45Z

@honggyukim I'm ok with the --auto-args option as long as there's a way to specify each function independently. I also agree with you that we needs to limit the length of string arguments. I suggest using 100 to allow up to 10 string aruments at once.

namhyung · 2017-10-18T08:42:32Z

Pushed review/auto-args-v2.

Changelog:

limit max length of a string argument
add --auto-args option (internally converted to -A . -R .)
add test case

honggyukim · 2017-10-18T14:12:16Z

@namhyung I'm very happy with review/auto-args-v2. :)
Thanks for doing this work!

Taeung · 2017-10-18T16:04:03Z

@namhyung , Thanks for doing this work!

I tested v2 branch and I found a trivial thing.

The below return string values of strncpy() are printed as
"/home/taeung/git/opensource/nmap<FF><FF><FF><FF><FF><FF><FF><FF>A<DB>^A"
and "/home/taeung/git/opensource/nmap/opensou<81><DB>^A".

But, I expected a string "/home/taeung/git/opensource/nmap".

Is it a bug ?

$ uftrace record --auto-args --nest-libcall ./nmap 127.0.0.1

Starting Nmap 7.60SVN ( https://nmap.org ) at 2017-10-19 00:56 KST
Nmap scan report for localhost (127.0.0.1)
Host is up (0.00000s latency).
Not shown: 994 closed ports
PORT     STATE SERVICE
25/tcp   open  smtp
80/tcp   open  http
443/tcp  open  https
631/tcp  open  ipp
902/tcp  open  iss-realsecure
3306/tcp open  mysql

Nmap done: 1 IP address (1 host up) scanned in 0.39 seconds


$ uftrace replay
...
   0.108 us [11782] |               strchr("/", '/') = "/";
   0.197 us [11782] |               malloc(33) = 0x23f14a0;
   0.494 us [11782] |               strncpy(NULL, "/home/taeung/git/opensource/nmap/nmap", 32) = "/home/taeung/git/opensource/nmap<FF><FF><FF><FF><FF><FF><FF><FF>A<DB>^A";
   0.241 us [11782] |               free(0x23f1470);
   0.651 us [11782] |               __vsnprintf_chk();
...
   0.137 us [12184] |               malloc(33) = 0x1dac460;
   0.297 us [12184] |               strncpy("", "/home/taeung/git/opensource/nmap/nmap", 32) = "/home/taeung/git/opensource/nmap/opensou<81><DB>^A";
   0.120 us [12184] |               free(0x1dac430);
...

honggyukim · 2017-10-19T02:36:29Z

Hi @Taeung,

You can see the below example:

#include <stdio.h>
#include <string.h>
#include <stdlib.h>

int main()
{
  char msg[] = "/home/taeung/git/opensource/nmap/nmap";
  char *n = (char*)malloc(33);
  int i;
  for (i = 0; i < 32; i++)
    n[i] = 0;   /* doesn't set the last element to 0 */
  strncpy(n, msg, 32);
  free(n);
  return 0;
}

If you compile and run it.

$ gcc -pg test.c

$ uftrace -A . -R . a.out 
# DURATION    TID     FUNCTION
   1.560 us [82405] | __monstartup();
   0.917 us [82405] | __cxa_atexit();
            [82405] | main() {
   2.060 us [82405] |   malloc(33) = 0x259b980;
   2.077 us [82405] |   strncpy("", "/home/taeung/git/opensource/nmap/nmap", 32) = "/home/taeung/git/opensource/nmap^A";
   1.270 us [82405] |   free(0x259b980);
   8.877 us [82405] | } = 0; /* main */

As you can see the return value of strncpy, it contains garbage letter ^A at the end.
If the dest buffer is not properly cleaned and doesn't copy the last NULL character, you can see such output. So it doesn't seem to be a bug in uftrace.

Taeung · 2017-10-19T02:39:33Z

@honggyukim , Thank you for detailed explanation, Understood ! 😄

honggyukim · 2017-10-19T02:45:40Z

But strange thing is in the your output log below:

strncpy(NULL, "/home/taeung/git/opensource/nmap/nmap", 32) = 
    "/home/taeung/git/opensource/nmap<FF><FF><FF><FF><FF><FF><FF><FF>A<DB>^A";

It's strange that how come the dest of strncpy is NULL and it's not crashed.

namhyung · 2017-10-19T05:33:43Z

@honggyukim that's because of internal encoding for NULL string (0xffffffff). If the buffer was filled with same value, it shows NULL. Maybe it'd be better using a different encoding as it's too common.

honggyukim · 2017-10-19T05:56:24Z

@namhyung Oh.. I see. Thanks for the info.

honggyukim · 2017-10-21T08:55:30Z

Hi @namhyung, is there any other issue for this feature?

namhyung · 2017-10-21T15:09:16Z

It needs to save the auto argspec in a data file so that it can be parsed later without a problem (even in a different version of uftrace).

namhyung · 2017-11-09T11:06:31Z

Pushed to review/auto-args-v3.

Changelog:

save auto-args argspec and retspec in the info file
update prototypes.h to add more functions and to support function pointers
now --auto-args is not same as -A . -R . - it only adds argspec of well-known functions. I'm worrying about the quality of dwarf argspec (will be added later)
add unit tests and some cleanups

namhyung · 2017-11-09T16:42:57Z

Pushed to review/auto-args-v4.

Changelog:

override auto-args if user gives an argspec explicitly
add more tests for overriding

The following example override pthread_create to show function pointer (3rd arg) only.

$ uftrace -A pthread_create@arg3/p --auto-args foobar
# DURATION    TID     FUNCTION
   1.185 us [ 1045] | __monstartup();
   0.824 us [ 1045] | __cxa_atexit();
            [ 1045] | main() {
            [ 1045] |   foo() {
   0.097 us [ 1045] |     bar();
   0.458 us [ 1045] |   } /* foo */
  33.292 us [ 1045] |   pthread_create(&foo) = 0;
            [ 1045] |   pthread_join(0x7fe46361c700, 0) {
            [ 1047] | foo() {
   0.132 us [ 1047] |   bar();
   1.451 us [ 1047] | } /* foo */
 179.350 us [ 1045] |   } = 0; /* pthread_join */
 216.944 us [ 1045] | } /* main */

honggyukim · 2017-11-10T04:55:35Z

Thanks for doing this! I think it's very good to me but I'm just wondering why you included utils/auto-args.h in the repository rather than generating it during build time.

namhyung · 2017-11-10T05:48:05Z

I don't want to build it unnecessarily. Some (old/small) system might lack python runtime as well.

honggyukim · 2017-11-10T05:51:12Z

Some (old/small) system might lacks python runtime as well.

Right, understood it. I'm fine with it then. Thanks a lot! :)

namhyung added the review label Oct 11, 2017

namhyung mentioned this issue Oct 11, 2017

extract argspec from DWARF debug info #174

Closed

namhyung closed this as completed in aeeb2b3 Nov 12, 2017

honggyukim added the args label May 10, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

automatic argument for well-known functions #173

automatic argument for well-known functions #173

namhyung commented Oct 11, 2017

namhyung commented Oct 11, 2017

honggyukim commented Oct 16, 2017

namhyung commented Oct 16, 2017

namhyung commented Oct 18, 2017

honggyukim commented Oct 18, 2017

Taeung commented Oct 18, 2017

honggyukim commented Oct 19, 2017 •

edited

Loading

Taeung commented Oct 19, 2017

honggyukim commented Oct 19, 2017 •

edited

Loading

namhyung commented Oct 19, 2017

honggyukim commented Oct 19, 2017

honggyukim commented Oct 21, 2017

namhyung commented Oct 21, 2017

namhyung commented Nov 9, 2017 •

edited

Loading

namhyung commented Nov 9, 2017

honggyukim commented Nov 10, 2017

namhyung commented Nov 10, 2017 •

edited

Loading

honggyukim commented Nov 10, 2017

automatic argument for well-known functions #173

automatic argument for well-known functions #173

Comments

namhyung commented Oct 11, 2017

namhyung commented Oct 11, 2017

honggyukim commented Oct 16, 2017

namhyung commented Oct 16, 2017

namhyung commented Oct 18, 2017

honggyukim commented Oct 18, 2017

Taeung commented Oct 18, 2017

honggyukim commented Oct 19, 2017 • edited Loading

Taeung commented Oct 19, 2017

honggyukim commented Oct 19, 2017 • edited Loading

namhyung commented Oct 19, 2017

honggyukim commented Oct 19, 2017

honggyukim commented Oct 21, 2017

namhyung commented Oct 21, 2017

namhyung commented Nov 9, 2017 • edited Loading

namhyung commented Nov 9, 2017

honggyukim commented Nov 10, 2017

namhyung commented Nov 10, 2017 • edited Loading

honggyukim commented Nov 10, 2017

honggyukim commented Oct 19, 2017 •

edited

Loading

honggyukim commented Oct 19, 2017 •

edited

Loading

namhyung commented Nov 9, 2017 •

edited

Loading

namhyung commented Nov 10, 2017 •

edited

Loading