This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Re: Some newbie questions
On 08/11/2016 07:18 PM, Frank Ch. Eigler wrote:
Hi -
avi wrote:
[...]
(Have you tried a stap script that merely traps all the same the
function calls, and has empty probe handlers?)
I can try it.
It was actually pretty bad with empty handlers:
#
66.25% scylla [kernel.kallsyms] [k] > _raw_spin_lock
|
---_raw_spin_lock
|
|--49.95%-- 0x62ab
| syscall_trace_leave
[...]
|--49.46%-- 0x619b
| syscall_trace_enter_phase2
[...]
I don't have any system call probes. Just two empty static probes, and
a timer.profile handler.
It would sure be nice if perf gave you an explanation of those 0x62ab
bits. Maybe use dwarf unwind based callgraph collection? The stap
runtime does sometimes create probes for internal purposes, such as
trapping exec/mmap operations (so probes on new programs can be
activated). It is conceivable that this is the source of the spinlock
activity, but such a high rate doesn't make sense.
I replicated on a more modern machine (also wider: 2s24c48t). I had to
--suppress-time-limits or stap would exit almost immediately.
My load indeed calls epoll_wait() at a high rate, with zero timeout.
But now it's completely dominated by tracing overhead.
#!/usr/bin/stap
# usage: task_latency.stap process_name latency_threshold_ms
global start_time
probe process(@1).mark("reactor_run_tasks_single_start") {
start_time[pid(), tid()] = gettimeofday_us()
}
probe process(@1).mark("reactor_run_tasks_single_end") {
delete start_time[pid(), tid()]
}
probe timer.profile {
if ([pid(), tid()] in start_time) {
now = gettimeofday_us()
start = start_time[pid(), tid()]
if ((now - start) > $2 * 1000) {
printf("detected tasks running for >%sms\n", @2)
print_usyms(ubacktrace())
}
}
}
#
# Total Lost Samples: 357
#
# Samples: 308K of event 'cycles:ppp'
# Event count (approx.): 222398334161
#
# Overhead Command Shared Object Symbol
# ........ ............... ...................
.....................................................................................................................................................................................................................................................
#
50.66% scylla [kernel.kallsyms] [k]
queued_spin_lock_slowpath
|
---queued_spin_lock_slowpath
|
|--49.99%--_raw_spin_lock
| |
| |--48.48%--task_utrace_struct
| | |
| | |--25.21%--utrace_report_syscall_entry
| | | syscall_trace_enter_phase2
| | | syscall_trace_enter
| | | do_syscall_64
| | | return_from_SYSCALL_64
| | | |
| | | --23.47%--epoll_pwait
| | |
reactor_backend_epoll::wait_and_process
| | | |
| | |
|--15.91%--std::_Function_handler<bool (),
reactor::run()::{lambda()#7}>::_M_invoke
| | | | reactor::run
| | | |
smp::configure(boost::program_options::variables_map)::{lambda()#3}::operator()
| | | |
posix_thread::start_routine
| | | | start_thread
| | | | __clone
| | | |
| | |
--7.56%--std::_Function_handler<bool (),
reactor::run()::{lambda()#8}>::_M_invoke
| | | logalloc::tracker::impl::compact_on_idle
| | | reactor::run
| | |
smp::configure(boost::program_options::variables_map)::{lambda()#3}::operator()
| | |
posix_thread::start_routine
| | | start_thread
| | | __clone
| | |
| | --23.27%--utrace_report_syscall_exit
| | syscall_slow_exit_work
| | do_syscall_64
| | return_from_SYSCALL_64
| | |
| | --21.92%--epoll_pwait
| | reactor_backend_epoll::wait_and_process
| | |
| | |--14.83%--std::_Function_handler<bool (),
reactor::run()::{lambda()#7}>::_M_invoke
| | | reactor::run
| | |
smp::configure(boost::program_options::variables_map)::{lambda()#3}::operator()
| | | posix_thread::start_routine
| | | start_thread
| | | __clone
| | |
| | --7.09%--std::_Function_handler<bool (),
reactor::run()::{lambda()#8}>::_M_invoke
| | logalloc::tracker::impl::compact_on_idle
| | reactor::run
| |
smp::configure(boost::program_options::variables_map)::{lambda()#3}::operator()
| | posix_thread::start_routine
| | start_thread
| | __clone
| |
| --1.27%--__lock_task_sighand
| |
| --0.67%--send_sigqueue
| posix_timer_event
| cpu_timer_fire
| run_posix_cpu_timers
| update_process_times
| tick_sched_handle.isra.16
| tick_sched_timer
| __hrtimer_run_queues
| hrtimer_interrupt
:
Will timer.profile work with dyninst?
Profile timers, not yet, but normal periodic ones like timer.hz(997) yes.
Unfortunately backtracing is also not yet implemented there.
Well, it's not very useful to me then.