Better handling of arguments/literals from the command-line?

[Theodore Tso]

I was experimenting with Systemtap script that is "a better strace"
(i.e., one that doesn't perturb the targetted process quite so much),
via a script like this:

probe syscall.* {
        if (pid() == $1) {
                t = gettimeofday_ms();
                printf("%d:%03d:%s(%s)\n", t/1000, t%1000, name, argstr)
        }
}

probe syscall.*.return {
        if (pid() == $1) {
                t = gettimeofday_ms();
                printf("%d:%03d;%s returns %s\n", t/1000,t%1000, name, retstr)
        }
}

I discovered to my dismay that this script took a full 45 seconds before
it started, and consumed 100% of one CPU while it was compiling it.  I
further found that each time I gave this script a new pid on the command
line, it took another 45 seconds.  If I gave it a pid that it had seen
before, it only took 10 seconds.  Leaving aside why it took a full 10
seconds (which still seems too long) even when the scripts for a
particular pid was cached, it seems rather unfortunate that literals
such as $1 appear to be substituted in early in the compilation process
instead of being passed in when the module is loaded, as arguments to
the module.  

If the argument were passed into the kernel, then it would be posible to
cache the compiled "strace.stp" script once, instead of having to
re-evaluate it for every single process ID.  Is there a good reason it
isn't handle this way currently?

Thanks, regards,

                                                - Ted

[Mark Wielaard-4]

Hi Ted,

On Sun, 2008-10-05 at 00:21 -0400, Theodore Ts'o wrote:

> I discovered to my dismay that this script took a full 45 seconds before
> it started, and consumed 100% of one CPU while it was compiling it.  I
> further found that each time I gave this script a new pid on the command
> line, it took another 45 seconds.  If I gave it a pid that it had seen
> before, it only took 10 seconds.  Leaving aside why it took a full 10
> seconds (which still seems too long) even when the scripts for a
> particular pid was cached, it seems rather unfortunate that literals
> such as $1 appear to be substituted in early in the compilation process
> instead of being passed in when the module is loaded, as arguments to
> the module.  

It is less than 10 seconds on my machine, but still some seconds. Which
does indeed seem somewhat long if we can find the cached files
eventually.

> If the argument were passed into the kernel, then it would be posible to
> cache the compiled "strace.stp" script once, instead of having to
> re-evaluate it for every single process ID.  Is there a good reason it
> isn't handle this way currently?

You can get that effect by using the target() function.
And using stap -x pid or stap -c exe:

strace.stp:

        probe syscall.* {
            if (pid() == target()) {
                t = gettimeofday_ms();
                printf("%d:%03d:%s(%s)\n", t/1000, t%1000, name, argstr)
            }
        }
       
        probe syscall.*.return {
            if (pid() == target()) {
                t = gettimeofday_ms();
                printf("%d:%03d;%s returns %s\n", t/1000,t%1000, name, retstr)
            }
        }


$ stap strace.stp -x 12345
or
$ stap strace.stp -c /bin/ls

Cheers,

Mark

[Theodore Tso]

On Sun, Oct 05, 2008 at 10:47:09AM +0200, Mark Wielaard wrote:
>
> It is less than 10 seconds on my machine, but still some seconds. Which
> does indeed seem somewhat long if we can find the cached files
> eventually.
>

Really?  I wonder why it takes so long on my system.  (An X61s laptop,
with an 1.6Ghz Intel Core 2 Duo, 2gigs memory, 7200rpm hard drive)
What sort of system do you have?  Is there some way the initial
compilation can be sped up?  I considered it rather disturbing that it
was taking so long; at greater than 10-15 seconds, usability design
really demands a progress bar, and some indication of when the
systemtap script is actually executing as opposed to compiling.

> You can get that effect by using the target() function.
> And using stap -x pid or stap -c exe:

Thanks for the tip!  Yeah, that's a much more intelligent way of doing
things.

                                                - Ted

[Mark Wielaard-4]

Hi Ted,

On Sun, 2008-10-05 at 23:05 -0400, Theodore Tso wrote:
> On Sun, Oct 05, 2008 at 10:47:09AM +0200, Mark Wielaard wrote:
> >
> > It is less than 10 seconds on my machine, but still some seconds. Which
> > does indeed seem somewhat long if we can find the cached files
> > eventually.
>
> Really?  I wonder why it takes so long on my system.  (An X61s laptop,
> with an 1.6Ghz Intel Core 2 Duo, 2gigs memory, 7200rpm hard drive)
> What sort of system do you have?

Well, less than 10, but still 8 seconds (it felt less yesterday).
Workstation: 3.2Ghz, 2GB, 10.000rpm

>   Is there some way the initial
> compilation can be sped up?  I considered it rather disturbing that it
> was taking so long; at greater than 10-15 seconds, usability design
> really demands a progress bar, and some indication of when the
> systemtap script is actually executing as opposed to compiling.

stap -v gives you at least the timings of Pass 1-5. So you know where
the time is being spend.

This is almost completely Pass 2 ():
Pass 2: analyzed script: 792 probe(s), 118 function(s), 14 embed(s),
        1 global(s) in 7810usr/480sys/8309real ms.
Pass 3 and 4 used cached files after the first run and so don't take
much time.

The analyzing translates the syscall.*[.return] probes into almost 800
individual kernel.function("sys_*")[.return] probes (with -vv you can
see which). And then for all these individual probes it calculates how
to get the arguments from the dwarf info to create the argstr and
returnstr used in the script. I am somewhat surprised this takes so
long, but this seems indeed what it is mainly doing (opreport -l):

samples  %        image name           symbol name
41080    13.1230  stap                 query_module(Dwfl_Module*, void**, char const*, unsigned long, void*)
29392     9.3893  libdw.so.1           __libdw_find_attr
17950     5.7341  libdw.so.1           __libdw_form_val_len
17344     5.5406  libdw.so.1           lookup
11379     3.6350  libc-2.8.so          strlen
10429     3.3316  libstdc++.so.6.0.10  std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(std::string const&)
9987      3.1904  stap                 std::tr1::__detail::_Map_base<std::string, std::pair[.truncated.]>::operator[](std::string const&)
8064      2.5761  libc-2.8.so          _int_malloc
6993      2.2339  stap                 dwflpp::iterate_over_functions(int (*)(Dwarf_Die*, void*), void*)
6429      2.0538  libc-2.8.so          memcpy
6059      1.9356  libdw.so.1           dwarf_siblingof
5818      1.8586  libstdc++.so.6.0.10  std::string::assign(std::string const&)

One contributing factor here is that I have 1715 kernel modules
installed (standard Fedora it seems) and that for each probe point (800
in this script) query_module() is called for each of them (so that is
1.372.000 calls). Although query_module() does seem to cache its results
for each module, that is still a lot. Of course in this case all the
probes are for sys_* functions which are never in a module, but
systemtap doesn't know that.

It would be nice if we could simply cache the results of Pass 2 also
when the .stp and debuginfo files used haven't changed. Then rerunning a
script would be almost instant.

Cheers,

Mark

[Frank Ch. Eigler]

"Theodore Ts'o" <tytso@...> writes:

> [...]  If I gave it a pid that it had seen before, it only took 10
> seconds.  [...]

This is a bug related to bug #3498.  This should go back down to
near-second times.

- FChE

[Stone, Joshua I]

Theodore Ts'o wrote:
> If the argument were passed into the kernel, then it would be posible to
> cache the compiled "strace.stp" script once, instead of having to
> re-evaluate it for every single process ID.  Is there a good reason it
> isn't handle this way currently?

The arguments are handled almost like preprocessor tokens, so you can do
things like "probe kernel.function(@1), timer.sec($2) {}".  The timer
could easily resolve its parameter at runtime, but that's harder for the
function probe.

If you only care about a pid, then target() as Mark pointed out is
probably the best choice, but here's a more generalized mechanism.
There's a little-advertised feature that global strings and longs can be
initialized with module parameters to staprun.  Thus you can do this:

    $ stap -e 'global foo=0; probe begin { println(foo); exit() }' \
        -p4 -m printfoo
    printfoo.ko
    $ staprun printfoo.ko
    0
    $ staprun printfoo.ko foo=42
    42

For parameters that are only used as literals in function/probe bodies,
we could probably synthesize this global-as-parameter method implicitly.
We could internally translate this:

    probe begin { println(@1, $2) }

into this:

    global __string_arg1 = ""
    global __long_arg2 = 0
    probe begin { println(__string_arg1, __long_arg2) }

with a matching staprun call to pass the module parameters.  This would
avoid recompilation for a lot of parameter use-cases.

Josh

[Theodore Tso]

Another random thought; as people start creating more complicated (and
hopefully more useful) turn-key stap scripts, it would be nice to be
able to write scripts that have as their first line "#!/bin/stap" and
then let the user pass command-line options to the systemtap script
which can be parsed out by a simple in-module getopt function.

Has anything like that been considered?

                                                - Ted

[Frank Ch. Eigler]

"Stone, Joshua I" <joshua.i.stone@...> writes:

> [...]
> For parameters that are only used as literals in function/probe bodies,
> we could probably synthesize this global-as-parameter method implicitly.
> We could internally translate this:
>
>     probe begin { println(@1, $2) }
>
> into this:
>
>     global __string_arg1 = ""
>     global __long_arg2 = 0
>     probe begin { println(__string_arg1, __long_arg2) }

Not quite - the $num parameter series constitute pasted token
sequences, not simple numbers any more.


- FChE

[Frank Ch. Eigler]

Theodore Tso <tytso@...> writes:

> Another random thought; as people start creating more complicated (and
> hopefully more useful) turn-key stap scripts, it would be nice to be
> able to write scripts that have as their first line "#!/bin/stap"

That has been working fine.

> and then let the user pass command-line options to the systemtap
> script which can be parsed out by a simple in-module getopt
> function.

While we don't have getopt per se yet, a script-side accessible
argv[]/argc value pair is available.  See the "argv" tapset.


- FChE

[Stone, Joshua I]

Frank Ch. Eigler wrote:

> "Stone, Joshua I" <joshua.i.stone@...> writes:
> > For parameters that are only used as literals in function/probe bodies,
> > we could probably synthesize this global-as-parameter method implicitly.
> > We could internally translate this:
> >
> >     probe begin { println(@1, $2) }
> >
> > into this:
> >
> >     global __string_arg1 = ""
> >     global __long_arg2 = 0
> >     probe begin { println(__string_arg1, __long_arg2) }
>
> Not quite - the $num parameter series constitute pasted token
> sequences, not simple numbers any more.

Ah -- I didn't realize it was that flexible.  It's unfortunate that it
then limits ability to reuse.  You could still follow this idea for
strings though, and even convert the strings to numbers in a begin
probe for use elsewhere in the script.

Even just this would be an advantage -- for instance, someone using the
argv tapset wouldn't need any recompilation when the arguments change,
as long as the number of arguments stayed the same.

Josh