* diagnosing unexpected sched_stat_wait
@ 2016-03-04 19:15 Jonah Petri
2016-03-04 22:05 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 6+ messages in thread
From: Jonah Petri @ 2016-03-04 19:15 UTC (permalink / raw)
To: linux-rt-users
Hello,
My application is doing realtime low-latency audio, and we're seeing
occasional dropouts, which we've traced (via ftrace) to an unexplained
sched_stat_wait event on our audio-handling user thread.
We're really not sure what might be causing this, but if I could get
the user stack trace causing this event, it would let me see exactly
the problem. Even the top frame of the stack would be invaluable.
Is there a way to get this info? Preferrably with ftrace, but any
methods or hints would be much appreciated.
Thanks!
Jonah
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: diagnosing unexpected sched_stat_wait
2016-03-04 19:15 diagnosing unexpected sched_stat_wait Jonah Petri
@ 2016-03-04 22:05 ` Arnaldo Carvalho de Melo
2016-03-04 22:24 ` Jonah Petri
0 siblings, 1 reply; 6+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-03-04 22:05 UTC (permalink / raw)
To: Jonah Petri; +Cc: linux-rt-users
Em Fri, Mar 04, 2016 at 02:15:25PM -0500, Jonah Petri escreveu:
> Hello,
>
> My application is doing realtime low-latency audio, and we're seeing
> occasional dropouts, which we've traced (via ftrace) to an unexplained
> sched_stat_wait event on our audio-handling user thread.
>
> We're really not sure what might be causing this, but if I could get
> the user stack trace causing this event, it would let me see exactly
> the problem. Even the top frame of the stack would be invaluable.
>
> Is there a way to get this info? Preferrably with ftrace, but any
> methods or hints would be much appreciated.
[root@jouet ~]# perf list *:sched_stat_wait
List of pre-defined events (to be used in -e):
sched:sched_stat_wait [Tracepoint event]
[root@jouet ~]# perf record -a --call-graph dwarf -e sched:*stat_wait
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 4.157 MB perf.data (763 samples) ]
[root@jouet ~]#
[root@jouet ~]# perf report --stdio | head -53
Failed to open /tmp/perf-7459.map, continuing without symbols
no symbols found in /usr/sbin/rngd, maybe install a debug package?
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 763 of event 'sched:sched_stat_wait'
# Event count (approx.): 2027097
#
# Children Self Trace output
# ........ ........ ...............................................
#
8.94% 8.94% comm=Xorg pid=2730 delay=181323 [ns]
|
---entry_SYSCALL_64_fastpath
sys_poll
do_sys_poll
poll_schedule_timeout
schedule_hrtimeout_range
schedule_hrtimeout_range_clock
schedule
__schedule
pick_next_task_fair
set_next_entity
update_stats_wait_end
0x563bfb142909
__libc_start_main
main
meta_run
g_main_loop_run
g_main_context_iterate.isra.29
0x7fb1060a9fdd
4.73% 4.73% comm=gnome-terminal- pid=3412 delay=95977 [ns]
|
---entry_SYSCALL_64_fastpath
sys_poll
do_sys_poll
poll_schedule_timeout
schedule_hrtimeout_range
schedule_hrtimeout_range_clock
schedule
__schedule
pick_next_task_fair
set_next_entity
update_stats_wait_end
_start
__libc_start_main
main
g_application_run
g_main_context_iteration
g_main_context_iterate.isra.29
0x7fd2cbd9bfdd
[root@jouet ~]#
Replace 'record -a' with 'record --pid YOUR-PID' or workload, etc, see:
man perf-record
If you get some unresolved symbols, install 'gcc -g' built binaries or
-debuginfo packages or equivalent in !fedora/RHEL distros.
- Arnaldo
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: diagnosing unexpected sched_stat_wait
2016-03-04 22:05 ` Arnaldo Carvalho de Melo
@ 2016-03-04 22:24 ` Jonah Petri
2016-03-07 14:28 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 6+ messages in thread
From: Jonah Petri @ 2016-03-04 22:24 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo; +Cc: linux-rt-users
Hi, thanks for the reply!
I have gone down that route, but I don't get user stack traces at all.
I suspect this is because I'm on ARM 3.14.52, which does not support
CONFIG_USER_STACKTRACE_SUPPORT. Nor does it support
CONFIG_ARCH_SUPPORTS_UPROBES.
All that said, I DO get stack traces when using straight perf record
with "--call-graph dwarf". (Does that imply "-e cpu-clock"?). So, I
was hoping that whatever is enabling that event to get stack traces
might be available to me.
Jonah
On Fri, Mar 4, 2016 at 5:05 PM, Arnaldo Carvalho de Melo
<acme@kernel.org> wrote:
> Em Fri, Mar 04, 2016 at 02:15:25PM -0500, Jonah Petri escreveu:
>> Hello,
>>
>> My application is doing realtime low-latency audio, and we're seeing
>> occasional dropouts, which we've traced (via ftrace) to an unexplained
>> sched_stat_wait event on our audio-handling user thread.
>>
>> We're really not sure what might be causing this, but if I could get
>> the user stack trace causing this event, it would let me see exactly
>> the problem. Even the top frame of the stack would be invaluable.
>>
>> Is there a way to get this info? Preferrably with ftrace, but any
>> methods or hints would be much appreciated.
>
> [root@jouet ~]# perf list *:sched_stat_wait
>
> List of pre-defined events (to be used in -e):
>
> sched:sched_stat_wait [Tracepoint event]
>
> [root@jouet ~]# perf record -a --call-graph dwarf -e sched:*stat_wait
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 4.157 MB perf.data (763 samples) ]
>
> [root@jouet ~]#
> [root@jouet ~]# perf report --stdio | head -53
> Failed to open /tmp/perf-7459.map, continuing without symbols
> no symbols found in /usr/sbin/rngd, maybe install a debug package?
> # To display the perf.data header info, please use --header/--header-only options.
> #
> #
> # Total Lost Samples: 0
> #
> # Samples: 763 of event 'sched:sched_stat_wait'
> # Event count (approx.): 2027097
> #
> # Children Self Trace output
> # ........ ........ ...............................................
> #
> 8.94% 8.94% comm=Xorg pid=2730 delay=181323 [ns]
> |
> ---entry_SYSCALL_64_fastpath
> sys_poll
> do_sys_poll
> poll_schedule_timeout
> schedule_hrtimeout_range
> schedule_hrtimeout_range_clock
> schedule
> __schedule
> pick_next_task_fair
> set_next_entity
> update_stats_wait_end
> 0x563bfb142909
> __libc_start_main
> main
> meta_run
> g_main_loop_run
> g_main_context_iterate.isra.29
> 0x7fb1060a9fdd
>
> 4.73% 4.73% comm=gnome-terminal- pid=3412 delay=95977 [ns]
> |
> ---entry_SYSCALL_64_fastpath
> sys_poll
> do_sys_poll
> poll_schedule_timeout
> schedule_hrtimeout_range
> schedule_hrtimeout_range_clock
> schedule
> __schedule
> pick_next_task_fair
> set_next_entity
> update_stats_wait_end
> _start
> __libc_start_main
> main
> g_application_run
> g_main_context_iteration
> g_main_context_iterate.isra.29
> 0x7fd2cbd9bfdd
>
> [root@jouet ~]#
>
> Replace 'record -a' with 'record --pid YOUR-PID' or workload, etc, see:
>
> man perf-record
>
> If you get some unresolved symbols, install 'gcc -g' built binaries or
> -debuginfo packages or equivalent in !fedora/RHEL distros.
>
> - Arnaldo
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: diagnosing unexpected sched_stat_wait
2016-03-04 22:24 ` Jonah Petri
@ 2016-03-07 14:28 ` Arnaldo Carvalho de Melo
2016-03-07 14:53 ` Jonah Petri
0 siblings, 1 reply; 6+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-03-07 14:28 UTC (permalink / raw)
To: Jonah Petri; +Cc: linux-rt-users
Em Fri, Mar 04, 2016 at 05:24:56PM -0500, Jonah Petri escreveu:
> Hi, thanks for the reply!
>
> I have gone down that route, but I don't get user stack traces at all.
> I suspect this is because I'm on ARM 3.14.52, which does not support
> CONFIG_USER_STACKTRACE_SUPPORT. Nor does it support
> CONFIG_ARCH_SUPPORTS_UPROBES.
probably the two options above are unrelated, I'm not familiar with
ARM, but I doubt they are required for perf to collect userland
stacktraces.
> All that said, I DO get stack traces when using straight perf record
> with "--call-graph dwarf". (Does that imply "-e cpu-clock"?). So, I
Ok, good data point, as what 'perf record --callgraph dwarf' does is to
take register and userland stack samples so that later it can use it
together with CFI information from the binaries involved to do the stack
unwinding.
> was hoping that whatever is enabling that event to get stack traces
> might be available to me.
So what you are not managing to do is to collect userland stacktraces
from tracepoints, right?
Any ARM person here to try to help diagnose why this does work on x86_64
but not on ARM?
- Arnaldo
> Jonah
>
>
> On Fri, Mar 4, 2016 at 5:05 PM, Arnaldo Carvalho de Melo
> <acme@kernel.org> wrote:
> > Em Fri, Mar 04, 2016 at 02:15:25PM -0500, Jonah Petri escreveu:
> >> Hello,
> >>
> >> My application is doing realtime low-latency audio, and we're seeing
> >> occasional dropouts, which we've traced (via ftrace) to an unexplained
> >> sched_stat_wait event on our audio-handling user thread.
> >>
> >> We're really not sure what might be causing this, but if I could get
> >> the user stack trace causing this event, it would let me see exactly
> >> the problem. Even the top frame of the stack would be invaluable.
> >>
> >> Is there a way to get this info? Preferrably with ftrace, but any
> >> methods or hints would be much appreciated.
> >
> > [root@jouet ~]# perf list *:sched_stat_wait
> >
> > List of pre-defined events (to be used in -e):
> >
> > sched:sched_stat_wait [Tracepoint event]
> >
> > [root@jouet ~]# perf record -a --call-graph dwarf -e sched:*stat_wait
> > ^C[ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 4.157 MB perf.data (763 samples) ]
> >
> > [root@jouet ~]#
> > [root@jouet ~]# perf report --stdio | head -53
> > Failed to open /tmp/perf-7459.map, continuing without symbols
> > no symbols found in /usr/sbin/rngd, maybe install a debug package?
> > # To display the perf.data header info, please use --header/--header-only options.
> > #
> > #
> > # Total Lost Samples: 0
> > #
> > # Samples: 763 of event 'sched:sched_stat_wait'
> > # Event count (approx.): 2027097
> > #
> > # Children Self Trace output
> > # ........ ........ ...............................................
> > #
> > 8.94% 8.94% comm=Xorg pid=2730 delay=181323 [ns]
> > |
> > ---entry_SYSCALL_64_fastpath
> > sys_poll
> > do_sys_poll
> > poll_schedule_timeout
> > schedule_hrtimeout_range
> > schedule_hrtimeout_range_clock
> > schedule
> > __schedule
> > pick_next_task_fair
> > set_next_entity
> > update_stats_wait_end
> > 0x563bfb142909
> > __libc_start_main
> > main
> > meta_run
> > g_main_loop_run
> > g_main_context_iterate.isra.29
> > 0x7fb1060a9fdd
> >
> > 4.73% 4.73% comm=gnome-terminal- pid=3412 delay=95977 [ns]
> > |
> > ---entry_SYSCALL_64_fastpath
> > sys_poll
> > do_sys_poll
> > poll_schedule_timeout
> > schedule_hrtimeout_range
> > schedule_hrtimeout_range_clock
> > schedule
> > __schedule
> > pick_next_task_fair
> > set_next_entity
> > update_stats_wait_end
> > _start
> > __libc_start_main
> > main
> > g_application_run
> > g_main_context_iteration
> > g_main_context_iterate.isra.29
> > 0x7fd2cbd9bfdd
> >
> > [root@jouet ~]#
> >
> > Replace 'record -a' with 'record --pid YOUR-PID' or workload, etc, see:
> >
> > man perf-record
> >
> > If you get some unresolved symbols, install 'gcc -g' built binaries or
> > -debuginfo packages or equivalent in !fedora/RHEL distros.
> >
> > - Arnaldo
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: diagnosing unexpected sched_stat_wait
2016-03-07 14:28 ` Arnaldo Carvalho de Melo
@ 2016-03-07 14:53 ` Jonah Petri
2016-03-09 18:30 ` Jonah Petri
0 siblings, 1 reply; 6+ messages in thread
From: Jonah Petri @ 2016-03-07 14:53 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo; +Cc: linux-rt-users
On Mon, Mar 7, 2016 at 9:28 AM, Arnaldo Carvalho de Melo
<acme@kernel.org> wrote:
>> I have gone down that route, but I don't get user stack traces at all.
>> I suspect this is because I'm on ARM 3.14.52, which does not support
>> CONFIG_USER_STACKTRACE_SUPPORT. Nor does it support
>> CONFIG_ARCH_SUPPORTS_UPROBES.
>> All that said, I DO get stack traces when using straight perf record
>> with "--call-graph dwarf". (Does that imply "-e cpu-clock"?). So, I
>
> Ok, good data point, as what 'perf record --callgraph dwarf' does is to
> take register and userland stack samples so that later it can use it
> together with CFI information from the binaries involved to do the stack
> unwinding.
>
Right, that's my understanding as well. Given that I do get stack
traces in some cases, this makes me wonder what the difference between
the events which yield user stack traces (seemingly "Software event"
in perf list) and events which do not yield user stack traces
(seemingly "Tracepoint" in perf list). My next steps are to work
through these mechanisms and try to understand the difference.
>> was hoping that whatever is enabling that event to get stack traces
>> might be available to me.
>
> So what you are not managing to do is to collect userland stacktraces
> from tracepoints, right?
Correct.
>
> Any ARM person here to try to help diagnose why this does work on x86_64
> but not on ARM?
>
Any pointers appreciated! Thanks!
Jonah
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: diagnosing unexpected sched_stat_wait
2016-03-07 14:53 ` Jonah Petri
@ 2016-03-09 18:30 ` Jonah Petri
0 siblings, 0 replies; 6+ messages in thread
From: Jonah Petri @ 2016-03-09 18:30 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo; +Cc: linux-rt-users
To close the loop on this, the support in the kernel for this is
missing for ARM in 3.14.52. I backported the following into
arch/arm/include/asm/perf_event.h:
#define perf_arch_fetch_caller_regs(regs, __ip) { \
register unsigned long sp asm ("sp"); \
(regs)->ARM_pc = (__ip); \
(regs)->ARM_fp = (unsigned long) __builtin_frame_address(0); \
(regs)->ARM_sp = sp; \
(regs)->ARM_cpsr = SVC_MODE; \
}
And now, I get stacks as expected!
Jonah
On Mon, Mar 7, 2016 at 9:53 AM, Jonah Petri <jpetri@izotope.com> wrote:
> On Mon, Mar 7, 2016 at 9:28 AM, Arnaldo Carvalho de Melo
> <acme@kernel.org> wrote:
>>> I have gone down that route, but I don't get user stack traces at all.
>>> I suspect this is because I'm on ARM 3.14.52, which does not support
>>> CONFIG_USER_STACKTRACE_SUPPORT. Nor does it support
>>> CONFIG_ARCH_SUPPORTS_UPROBES.
>>> All that said, I DO get stack traces when using straight perf record
>>> with "--call-graph dwarf". (Does that imply "-e cpu-clock"?). So, I
>>
>> Ok, good data point, as what 'perf record --callgraph dwarf' does is to
>> take register and userland stack samples so that later it can use it
>> together with CFI information from the binaries involved to do the stack
>> unwinding.
>>
>
> Right, that's my understanding as well. Given that I do get stack
> traces in some cases, this makes me wonder what the difference between
> the events which yield user stack traces (seemingly "Software event"
> in perf list) and events which do not yield user stack traces
> (seemingly "Tracepoint" in perf list). My next steps are to work
> through these mechanisms and try to understand the difference.
>
>>> was hoping that whatever is enabling that event to get stack traces
>>> might be available to me.
>>
>> So what you are not managing to do is to collect userland stacktraces
>> from tracepoints, right?
>
> Correct.
>
>>
>> Any ARM person here to try to help diagnose why this does work on x86_64
>> but not on ARM?
>>
>
> Any pointers appreciated! Thanks!
>
> Jonah
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2016-03-09 18:30 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2016-03-04 19:15 diagnosing unexpected sched_stat_wait Jonah Petri
2016-03-04 22:05 ` Arnaldo Carvalho de Melo
2016-03-04 22:24 ` Jonah Petri
2016-03-07 14:28 ` Arnaldo Carvalho de Melo
2016-03-07 14:53 ` Jonah Petri
2016-03-09 18:30 ` Jonah Petri
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.