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