Some newbie questions

[Avi Kivity]

On 08/08/2016 05:58 PM, David Smith wrote:
>
>> 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.

  [1417f4]      subprogram
                external             (flag_present) Yes
                name                 (strp) "run_tasks"
                decl_file            (data1) 5
                decl_line            (data2) 812
                linkage_name         (strp) 
"_ZN7reactor9run_tasksER15circular_bufferISt10unique_ptrI4taskSt14default_deleteIS2_EESaIS5_EE"
                declaration          (flag_present) Yes
                object_pointer       (ref4) [141808]
                sibling              (ref4) [141813]
  [141808]        formal_parameter
                  type                 (ref4) [1423bd]
                  artificial           (flag_present) Yes
  [14180d]        formal_parameter
                  type                 (ref4) [14a8a8]


The debugger has no trouble setting breakpoints on the function or 
showing it in backtraces.  In any case I sprinkled some static probes there.

>> 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()

Yes, I found that out and my latest version works like this, but I ran 
into severe scaling issues.

I also switched to timer.profile.  What's its resolution on normal machines?

> 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.

Actually I got good backtraces when I instrumented a task to spin for 
100ms.  I also got some bad traces, but did not investigate more.

> 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())

Here the backtrace is useless, I know exactly what it looks like at this 
point; it's two frames away from main().

To give some context, this is a run-to-completion scheduler. I have 
tasks pushed into a queue from various sources (including other tasks), 
and this bit is the part of the main loop that dequeues a task, runs it, 
and repeats.  Some tasks take too long, and I want to identify which 
ones.  I could print the last task's vtable, but that is much less 
useful than a full backtrace at the time the task is detected as taking 
too long.


>      }
> }
> ====
>
> 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).
>

Unfortunately I already know there is a problem and need to pinpoint 
it.  Which is where the backtrace is so useful.

I can fall back to instrumenting the code with a timer (from 
timer_create(3)), but I'd much rather have the flexibility of 
non-intrusive instrumentation.