Re: Some newbie questions

[Avi Kivity <avi@scylladb.com>]

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.