argument/return value support for (python) script

[namhyung]

It currently lacks the argument/return value info from script. I pushed a code to support them in review/script-args-v1.

I used following test script:

$ cat dump.py
def uftrace_begin():
    pass

def uftrace_entry(ctx):
    if "args" in ctx:
        print("%s has argument" % ctx["symname"])
        for item in ctx["args"]:
            print("  arg: %r" % item)

def uftrace_exit(ctx):
    if "retval" in ctx:
        print("%s has return value" % ctx["symname"])
        print(" retval: %r" % ctx["retval"])

def uftrace_end():
    pass

The result is below - I know there're some issues but want to share the current status first.

$ uftrace -A main@arg1 -A printf@arg1/s -R printf@retval -S dump.py hello-pg
main has argument
  arg: 1L
printf has argument
  arg: 'hello %s\\n'
hello world
printf has return value
 retval: 12L
# DURATION    TID     FUNCTION
  15.020 us [ 1854] | __monstartup();
   5.210 us [ 1854] | __cxa_atexit();
            [ 1854] | main(1) {
  16.094 us [ 1854] |   printf("hello %s\n") = 12;
  71.361 us [ 1854] | } /* main */

[honggyukim]

@namhyung Superb! It works fine for me and the code quality is a lot better now.

[namhyung]

Pushed review/script-args-v2.

Changelog:

• fix some bugs
• support floating-point args properly (by saving/restoring FP registers for script execution)
• add basic filter support (using "uftrace_funcs" list in script file)

For example, the following script has a filter for function a and b.

$ cat filter.py
uftrace_funcs = ["a", "b"]

def uftrace_begin():
    pass

def uftrace_entry(ctx):
    print("entry : " + ctx["symname"] + "()")

def uftrace_exit(ctx):
    print("exit  : " + ctx["symname"] + "()")

def uftrace_end():
    pass

And then script now runs only for a and b.

$ uftrace -S filter.py t-abc
entry : a()
entry : b()
exit  : b()
exit  : a()
# DURATION    TID     FUNCTION
   1.752 us [ 3794] | __monstartup();
   1.177 us [ 3794] | __cxa_atexit();
            [ 3794] | main() {
            [ 3794] |   a() {
            [ 3794] |     b() {
            [ 3794] |       c() {
   1.027 us [ 3794] |         getpid();
   1.920 us [ 3794] |       } /* c */
   4.959 us [ 3794] |     } /* b */
  16.886 us [ 3794] |   } /* a */
  48.647 us [ 3794] | } /* main */

[honggyukim]

@namhyung Having uftrace_funcs inside the script looks great! I've tested it and works fine so please rebase and merge it. :)

[namhyung]

It'd be nice to support regex too. Also I guess using capical letters like "UFTRACE_FUNCS" seems better, thoughts?

[honggyukim]

It'd be nice to support regex too.

I agree.

Also I guess using capical letters like "UFTRACE_FUNCS" seems better, thoughts?

Hm.. naming is always difficult but it seems that it requires uncomfortable typing with capital letters.

Besides that, can you please rebase and update it first before making more changes?

[honggyukim]

What about script_funcs so that it shows that the script only processes the given functions?

[namhyung]

Besides that, can you please rebase and update it first before making more changes?

Sure.

What about script_funcs so that it shows that the script only processes the given functions?

That would work too. I cared about a possible name clash with system or user scripts so wanted to have the "uftrace" prefix somehow. Also it's a kind of configuration or setting so it seems natural to use capital letters IMHO.

[honggyukim]

That would work too. I cared about a possible name clash with system or user scripts so wanted to have the "uftrace" prefix somehow. Also it's a kind of configuration or setting so it seems natural to use capital letters IMHO.

I see. I was just trying to find a more intuitive name but UFTRACE_FUNCS is also fine for me.

[namhyung]

Just pushed review/script-args-v3.

Changelog:

• change filter name to UFTRACE_FUNCS

[honggyukim]

It seems that retval is also tuple so I have to get the value ctx["retval"][0].
Why don't we just use it as ctx["retval"]?

[namhyung]

Pushed review/script-args-v4.

Changelog:

• change to return (single) value not tuple for ctx["retval"]
• support regex matching for UFTRACE_FUNCS

With above "filter.py" script, changed "UFTRACE_FUNCS" to "^.$" in order to match functions with single letter name:

$ head -1 filter.py
UFTRACE_FUNCS = [ "^.$" ]

$ uftrace -S filter.py t-abc
entry : a()
entry : b()
entry : c()
exit  : c()
exit  : b()
exit  : a()
# DURATION    TID     FUNCTION
   8.038 us [27045] | __monstartup();
   0.631 us [27045] | __cxa_atexit();
            [27045] | main() {
            [27045] |   a() {
            [27045] |     b() {
            [27045] |       c() {
   1.126 us [27045] |         getpid();
   3.669 us [27045] |       } /* c */
   9.513 us [27045] |     } /* b */
  19.467 us [27045] |   } /* a */
  43.082 us [27045] | } /* main */

[honggyukim]

I think it's good for me. Thanks!

[namhyung]

Pushed review/script-args-v5.

Changelog:

• allow to specify record options using # uftrace-option: <options here> in script file
• rename 'symname' to 'name' in script context
• update docuementation

For example, following script has its record options to set argument and return value.

$ cat arg.py
#
# uftrace-option: -A a@arg1 -R b@retval
#
def uftrace_entry(ctx):
    if "args" in ctx:
        print(ctx["name"] + " has args")
def uftrace_exit(ctx):
    if "retval" in ctx:
        print(ctx["name"] + " has retval")

Running uftrace record with the script will add those options to the command line.

$ uftrace record -S arg.py t-abc
a has args
b has retval

[honggyukim]

@namhyung Thanks! But it seems that it doesn't parse some options such as --nest-libcall.

[namhyung]

Yes, it does miss a few of options but --nest-libcall seems to work.

$ cat nest.py
#uftrace-option: --nest-libcall

def uftrace_entry(ctx):
    print("enter: " + ctx["name"])
def uftrace_exit(ctx):
    print("exit : " + ctx["name"])

Without the script:

$ uftrace dummy
# DURATION    TID     FUNCTION
            [ 5584] | main() {
   1.004 us [ 5584] |   operator new();
   1.854 us [ 5584] |   operator delete();
   5.847 us [ 5584] | } /* main */

With the script:

$ uftrace -S nest.py dummy
enter: main
enter: operator new
enter: malloc
exit : malloc
exit : operator new
enter: operator delete
enter: operator delete
enter: free
exit : free
exit : operator delete
exit : operator delete
exit : main
# DURATION    TID     FUNCTION
            [ 5616] | main() {
            [ 5616] |   operator new() {
   3.259 us [ 5616] |     malloc();
  12.923 us [ 5616] |   } /* operator new */
            [ 5616] |   operator delete() {
            [ 5616] |     operator delete() {
   3.179 us [ 5616] |       free();
   8.517 us [ 5616] |     } /* operator delete */
  13.508 us [ 5616] |   } /* operator delete */
  82.662 us [ 5616] | } /* main */

[honggyukim]

@namhyung Ah.. you're right. sorry for making confusion. But it would be better to show which option is applied in uftrace info. If we use in-script option, there's no way to know it from the record except for arguments and retvals.
For example,

$ uftrace info --no-pager
# system information
# ==================
# program version     : uftrace v0.7-309-g98fb
# recorded on         : Sat Sep  9 14:51:34 2017
# cmdline             : uftrace record -S malloc-free.py --force /usr/bin/gcc /home/honggyu/hello.c
# cpu info            : Intel(R) Core(TM) i7-4790K CPU @ 4.00GHz
# number of cpus      : 8 / 8 (online / possible)
# memory info         : 0.6 / 15.5 GB (free / total)
# system load         : 0.16 / 0.23 / 0.31 (1 / 5 / 15 min)
# kernel version      : Linux 4.10.0-30-generic
# hostname            : kvt
# distro              : "Ubuntu 17.04"
#
# process information
# ===================
# number of tasks     : 5
# task list           : 15781, 15780, 15779, 15778, 15775
# exe image           : /usr/bin/x86_64-linux-gnu-gcc-6
# build id            : 80c128930800a9fb4d6d9bd25cd4b954b7fbf412
# arguments/retval    : malloc@arg1;free@arg1;calloc@arg1,arg2;realloc@arg1,arg2;memalign@arg1,arg2;malloc@libstdc++,arg1;free@libstdc++,arg1;calloc@libstdc++,arg1,arg2;realloc@libstdc++,arg1,arg2;memalign@libstdc++,arg1,arg2;malloc@retval;calloc@retval;realloc@retval;memalign@retval;malloc@libstdc++,retval;calloc@libstdc++,retval;realloc@libstdc++,retval;memalign@libstdc++,retval;
# exit status         : exited with code: 0
# elapsed time        : 0.136612302 sec
# cpu time            : 0.004 / 0.124 sec (sys / user)
# context switch      : 12 / 3 (voluntary / involuntary)
# max rss             : 22908 KB
# page fault          : 0 / 7696 (major / minor)
# disk iops           : 0 / 128 (read / write)

[namhyung]

Hmm.. does it really necessary? I think one can easily see the script to check the additional options when needed..

[honggyukim]

It's not urgent but it's just to make uftrace.data self-contained all the information. Otherwise, copying the script into uftrace.data can make it.

[honggyukim]

It's not urgent at all so better to ignore it as of now.

[namhyung]

Pushed review/script-args-v6.

Changelog:

• change "symname" to "name".
• separate debug domain for script
• show script error message when -v is given

I'm gonna push this into master soon unless some serious issue arises. Please tell me if you find something, thanks!

[honggyukim]

Thanks. I think it's good to me. I appreciate your effort!