[Bug dyninst/23511] New: Weird slowness in the dyninst runtime when tracing simplest C programs

[Bug dyninst/23511] New: Weird slowness in the dyninst runtime when tracing simplest C programs

[agentzh at gmail dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=23511

            Bug ID: 23511
           Summary: Weird slowness in the dyninst runtime when tracing
                    simplest C programs
           Product: systemtap
           Version: unspecified
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: dyninst
          Assignee: systemtap at sourceware dot org
          Reporter: agentzh at gmail dot com
  Target Milestone: ---

Consider the simplest C program below:

```C
int main(void) {
    return 0;
}
```

And then probing the `main()` function with the dyninst runtime would take more
than 3 sec on my fast MBP machine:

```
$ time stap -e 'probe begin { println("hello") exit() }' -c ./a.out -v
--dyninst
Pass 1: parsed user script and 52 library scripts using
163204virt/10072res/7120shr/3216data kb, in 30usr/0sys/35real ms.
Pass 2: analyzed script: 1 probe, 1 function, 0 embeds, 0 globals using
163204virt/10072res/7120shr/3216data kb, in 0usr/0sys/0real ms.
Pass 3: using cached
/home/agentzh/.systemtap/cache/36/stap_3697a0afe348f5225015cad94941fe91_1087.c
Pass 4: using cached
/home/agentzh/.systemtap/cache/36/stap_3697a0afe348f5225015cad94941fe91_1087.so
Pass 5: starting run.
hello
Pass 5: run completed in 3120usr/90sys/3225real ms.

real    0m3.269s
user    0m3.158s
sys     0m0.104s
```

Even when the compiled `.so` file is hitting the cache!

Most of the time is spent on Pass 5 (3225ms).

I'm using the latest master branch of systemtap on Fedora 27 x86_64 (kernel
4.16.16).

If I understand it correctly, dyninst uses ptrace() to probe the target
process, just like GDB. But GDB works much faster in batch mode probing the
same C program:

```
$ time gdb -batch -ex 'b main' -ex r -ex c --args ./a.out
Breakpoint 1 at 0x40048b: file a.c, line 2.

Breakpoint 1, main () at a.c:2
2       #define mref(r, t)  ((t *)(void *)(uintptr_t)(r).ptr32)
[Inferior 1 (process 22157) exited normally]

Press ENTER or type command to continue
Breakpoint 1 at 0x40048b: file a.c, line 2.

Breakpoint 1, main () at a.c:2
2       #define mref(r, t)  ((t *)(void *)(uintptr_t)(r).ptr32)
[Inferior 1 (process 22177) exited normally]

real    0m0.206s
user    0m0.175s
sys     0m0.046s
```

Only 206ms is needed. My hunch is that stap dyninst should be even faster than
GDB since it looks more light weight.

Is it a known issue? Any easy fix or workaround here? Thanks!

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug dyninst/23511] Weird slowness in the dyninst runtime when tracing simplest C programs

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=23511

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|UNCONFIRMED                 |RESOLVED
                 CC|                            |fche at redhat dot com
         Resolution|---                         |INVALID

--- Comment #1 from Frank Ch. Eigler <fche at redhat dot com> ---
The dyninst runtime is very fast, once it gets going.  But when it starts, it
runs its own decompilation analysis of the target binary, which can take time. 
I am not aware of any caching or configurable reduction of this startup effort.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug dyninst/23511] Weird slowness in the dyninst runtime when tracing simplest C programs

[agentzh at gmail dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=23511

--- Comment #2 from agentzh <agentzh at gmail dot com> ---
I think it's still a real issue to be resolved? Via caching or whatever. The
slowness is real and it hurts a lot when running many tests involved with the
dyninst runtime mode (it is even slower than the kernel mode, ouch!) :)

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug dyninst/23511] Weird slowness in the dyninst runtime when tracing simplest C programs

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=23511

--- Comment #3 from Frank Ch. Eigler <fche at redhat dot com> ---
The tests are generally short-lived, trivial programs, so it is natural that
the dyninst analysis costs overwhelm.  Dyninst performs well on long-running
scripts - which are not in the testsuite.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug dyninst/23511] Weird slowness in the dyninst runtime when tracing simplest C programs

[agentzh at gmail dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=23511

--- Comment #4 from agentzh <agentzh at gmail dot com> ---
But even for long running process, it is not uncommon to run the same tool for
multiple times or run multiple different tools against the same target process.
And every time we run a tool, it costs more than 3 seconds of precious CPU time
(100% on a CPU core), which looks very unreasonable, which may well outweigh
the overhead of the real useful work of the tool itself. (I'd rather it sleeps
for 3 seconds without using so much CPU resources.)

Also, it looks unreasonable to have to do such expensive analyses on an *empty*
C program since there's really nothing worth analyzing.

Is it technically possible to cache and reuse the result of the "decompilation
analysis" thing?

-- 
You are receiving this mail because:
You are the assignee for the bug.