This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Re: Some newbie questions
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.