Re: Some newbie questions

[David Smith <dsmith at redhat dot com>]

On 08/07/2016 03:07 AM, Avi Kivity wrote:
> Hello,
> 
> A few newbie questions.
> 
> 1.  Static library support
> 
> I am writing a static library, and would like to ship some scripts with
> the library for its consumers.  The library is named "seastar" and one
> of the consumers is named "scylla".
> 
> What should I write as the process name in the script?  As the writer of
> the library, I don't know the name of the process that will be consuming
> the library.  The consumer shouldn't have to write those scripts.  I
> could play sed games to adjust the scripts, but it's very sad to have to
> do this.

The tricky part here is that your library is static. With a shared
library, you could do something like:

   probe process.library("libseastar.so").function("FOO") { }

which would get probe hits for any process that uses that shared library.

For a statically linked library, you can't do that.

Off the top of my head, I don't see any solution other than your '@1'
parameter idea.


> 2. Inlined functions
> 
> From the manual pages, it seems that inlined functions can be probed
> (minus the .return probe), but I just get an error:
> 
> semantic error: while resolving probe point: identifier 'process' at
> script/home/avi/seastar/debug/task-latency.stap:3:7
>         source: probe process("scylla").function("reactor::run_tasks()") {
>                       ^
> 
> semantic error: no match (similar functions:
> _ZN7reactor14run_exit_tasksEv, statfs, dup, mkdir, ntohs)

We're at the mercy of the compiler and the quality of the debuginfo it
produces here when looking for inlined functions.

If you want to investigate further here, you'll need to do the following:

# eu-readelf -N --debug-dump=info scylla > scylla.log

In scylla.log, look and see if you can find a subprogram with the name
of the function you are interested in.

> I will note that "mkdir" does not sound very similar to
> "reactor::run_tasks()" (but I am not a native speaker).

Actually, to my native speaker's eyes, none of the suggested functions
look that close. The way the levenshtein suggestive feature works is
that we report the top 5 scoring functions. I'd bet in this case the
scores were all bad, but these were the top 5 of the scores.

> 3. Process CPU timers
> 
> (more of a feature request)
> 
> I'm trying to find causes of latency in my program.  To do that, I'm
> running a periodic timer and checking whether a function takes more time
> than some threshold.
> 
> Ideally, I'd be able to arm the timer on the function entry point and
> disarm it on exit, rather than have it run continuously; this would need
> to be a per-thread cpu-time timer (e.g. CLOCK_THREAD_CPUTIME_ID)/
> 
> Here's my current script for reference ("running" and "start_time" need
> to become maps for it to be thread-safe):
> 
> #!/usr/bin/stap
> 
> global start_time
> global running
> 
> probe begin {
>     running = 0
> }
> 
> probe
> process("/home/avi/urchin/build/release/scylla").mark("reactor_run_tasks_start")
> {
>     start_time = gettimeofday_us()
>     running = 1
> }
> 
> probe
> process("/home/avi/urchin/build/release/scylla").mark("reactor_run_tasks_end")
> {
>     running = 0
> }
> 
> probe timer.ms(10) {
>     now = gettimeofday_us()
>     if (running && (now - start_time) > 30000) {
>         printf("detected tasks running for >30ms\n")
>         print_usyms(ubacktrace())
>     }
> }
> 
> I'd appreciate any tips as to whether there's a better way to do this.

The above isn't really going to work well, for several reasons:

1) You've only got one global 'start_time' and 'running' variables. If
scylla is multithreaded or more than one instance is running, that isn't
going to work.

To fix this, you'd want to do convert them to arrays and index them by
thread ids, like this:

    start_time[tid()] = gettimeofday_us()

2) Your ubacktrace() call in the timer function isn't going to report
what you want. At that point, you aren't running in the context of the
process, you are running in the context of whatever kernel thread is
running the timer. I'm really sure what a user backtrace will report at
that point, but it certainly won't be useful.

Here's an (untested) version of what would work a bit better:

====
global start_time

probe
process("/home/avi/urchin/build/release/scylla").mark("reactor_run_tasks_start")
{
    start_time[tid()] = gettimeofday_us()
}

probe
process("/home/avi/urchin/build/release/scylla").mark("reactor_run_tasks_end")
{
    now = gettimeofday_us()
    start = start_time[tid()]
    delete start_time[tid()]
    if ((now - start) > 30000) {
         printf("detected tasks running for >30ms (%d)\n",
                (now - start))
         print_usyms(ubacktrace())
    }
}
====

If you like, you could add a timer probe to the above to report an
ongoing problem in the current process (but without printing a backtrace).

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)