* Re: [RFC]Read kernel stack with trace-cmd [not found] ` <1336399968.14207.141.camel@gandalf.stny.rr.com> @ 2012-05-08 14:34 ` harryxiyou 2012-05-08 15:06 ` Steven Rostedt 0 siblings, 1 reply; 4+ messages in thread From: harryxiyou @ 2012-05-08 14:34 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel, kernelnewbies, Chen Lijun On Mon, May 7, 2012 at 10:12 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Sun, 2012-05-06 at 21:25 +0800, harryxiyou wrote: >> Hi Steven, >> >> Maybe this is not the right place for asking a trace-cmd matter. If true, >> please ignore this mail. Thanks. >> I wanna to read stack contents with our trace-cmd. But i can only get >> something about function information like following. I can not get kernel >> stack infos with trace-cmd. How should i run trace-cmd for kernel stack >> ones. Cloud anyone give me some suggestions? >> >> My Environments: >> # uname -r >> 2.6.32-21-generic > > Wow that's an old kernel. Yup ;-) > >> # lsb_release -a >> No LSB modules are available. >> Distributor ID: Ubuntu > > Note, I don't use Ubuntu. I use Debian or Fedora. > >> Description: Ubuntu 10.04.4 LTS >> Release: 10.04 >> Codename: lucid >> gcc version 4.4.3 (Ubuntu 4.4.3-4ubuntu5.1) >> >> Following are my test code and logs after running trace-cmd. >> >> /* >> * linux_os/sys_call.c >> * >> * Harry Wei (C) 2012 5 6 >> */ >> #include <syscall.h> >> #include <unistd.h> >> #include <stdio.h> >> #include <sys/types.h> >> >> int main(int argc, char **argv) { >> long ID1 = 0L; >> long ID2 = 0L; >> >> ID1 = syscall(SYS_getpid); >> printf("syscall(SYS_getpid) = %ld\n", ID1); >> ID2 = getpid(); >> printf("getpid() = %ld\n", ID2); >> return 0; >> } >> >> $ gcc sys_call.c >> >> # ./trace-cmd record -e all ../../workshop1/homeworkxy/linux_os/a.out > > > Have you tried it with -O stacktrace ? > > trace-cmd record -e all -O stacktrace > After this cmd, i get following ones. [...] => handle_IRQ_event (c019fc34) => handle_edge_irq (c01a1b84) => handle_irq (c01059ed) => do_IRQ (c058fa1c) => common_interrupt (c0103a30) => mod_timer (c015bd42) => i915_add_request (f850cef4) => i915_gem_do_execbuffer (f8510adc) Xorg-1104 [001] 3106.003258: irq_handler_exit: irq=29 return=handled Xorg-1104 [001] 3106.003259: kernel_stack: <stack trace> => handle_edge_irq (c01a1b84) => handle_irq (c01059ed) => do_IRQ (c058fa1c) => common_interrupt (c0103a30) => mod_timer (c015bd42) => i915_add_request (f850cef4) => i915_gem_do_execbuffer (f8510adc) => i915_gem_execbuffer (f851123b) Xorg-1104 [001] 3106.003272: kfree: call_site=f8510958 ptr=0xf5ab9380 Xorg-1104 [001] 3106.003273: kernel_stack: <stack trace> => i915_gem_do_execbuffer (f8510958) => i915_gem_execbuffer (f851123b) => drm_ioctl (f81d57cd) => vfs_ioctl (c0216231) => do_vfs_ioctl (c0216519) => sys_ioctl (c0216817) [...] Xorg-1104 [001] 3106.003348: sched_wakeup: task trace-cmd:3028 [120] success=1 [001] Xorg-1104 [001] 3106.003348: kernel_stack: <stack trace> => wake_up_process (c0142bd4) => hrtimer_wakeup (c016acad) => __run_hrtimer (c016b14a)^Ctrace-cmd: Received SIGINT Xorg-1104 [001] 3106.003348: kernel_stack: <stack trace> => wake_up_process (c0142bd4) => hrtimer_wakeup (c016acad) => __run_hrtimer (c016b14a) => hrtimer_interrupt (c016b4e0) => smp_apic_timer_interrupt (c058fae7) => apic_timer_interrupt (c0103df1) => __module_text_address (c017cdf0) [...] => wake_up_process (c0142bd4) => hrtimer_wakeup (c016acad) => __run_hrtimer (c016b14a)^Ctrace-cmd: Received SIGINT Xorg-1104 [001] 3106.003348: kernel_stack: <stack trace> [...] Note: i can't stop the cmd './trace-cmd report' after './trace-cmd record -e all -O stacktrace' but enter 'CTRC+C'. If it is a bug here? Any comments? -- Thanks Harry Wei ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [RFC]Read kernel stack with trace-cmd 2012-05-08 14:34 ` [RFC]Read kernel stack with trace-cmd harryxiyou @ 2012-05-08 15:06 ` Steven Rostedt 2012-05-09 9:00 ` harryxiyou 0 siblings, 1 reply; 4+ messages in thread From: Steven Rostedt @ 2012-05-08 15:06 UTC (permalink / raw) To: harryxiyou; +Cc: linux-kernel, kernelnewbies, Chen Lijun On Tue, 2012-05-08 at 22:34 +0800, harryxiyou wrote: > > > > Have you tried it with -O stacktrace ? > > > > trace-cmd record -e all -O stacktrace > > > > After this cmd, i get following ones. > > [...] > => handle_IRQ_event (c019fc34) > => handle_edge_irq (c01a1b84) > => handle_irq (c01059ed) > => do_IRQ (c058fa1c) > => common_interrupt (c0103a30) > => mod_timer (c015bd42) > => i915_add_request (f850cef4) > => i915_gem_do_execbuffer (f8510adc) > Xorg-1104 [001] 3106.003258: irq_handler_exit: Isn't this what you asked for? > irq=29 return=handled > Xorg-1104 [001] 3106.003259: kernel_stack: <stack trace> > => handle_edge_irq (c01a1b84) > => handle_irq (c01059ed) > => do_IRQ (c058fa1c) > => common_interrupt (c0103a30) > => mod_timer (c015bd42) > => i915_add_request (f850cef4) > => i915_gem_do_execbuffer (f8510adc) > => i915_gem_execbuffer (f851123b) > Xorg-1104 [001] 3106.003272: kfree: > call_site=f8510958 ptr=0xf5ab9380 > Xorg-1104 [001] 3106.003273: kernel_stack: <stack trace> > => i915_gem_do_execbuffer (f8510958) > => i915_gem_execbuffer (f851123b) > => drm_ioctl (f81d57cd) > => vfs_ioctl (c0216231) > => do_vfs_ioctl (c0216519) > => sys_ioctl (c0216817) > [...] > Xorg-1104 [001] 3106.003348: sched_wakeup: task > trace-cmd:3028 [120] success=1 [001] > Xorg-1104 [001] 3106.003348: kernel_stack: <stack trace> > => wake_up_process (c0142bd4) > => hrtimer_wakeup (c016acad) > => __run_hrtimer (c016b14a)^Ctrace-cmd: Received SIGINT > Xorg-1104 [001] 3106.003348: kernel_stack: <stack trace> > => wake_up_process (c0142bd4) > => hrtimer_wakeup (c016acad) > => __run_hrtimer (c016b14a) > => hrtimer_interrupt (c016b4e0) > => smp_apic_timer_interrupt (c058fae7) > => apic_timer_interrupt (c0103df1) > => __module_text_address (c017cdf0) > [...] > => wake_up_process (c0142bd4) > => hrtimer_wakeup (c016acad) > => __run_hrtimer (c016b14a)^Ctrace-cmd: Received SIGINT > Xorg-1104 [001] 3106.003348: kernel_stack: <stack trace> > [...] > > > Note: i can't stop the cmd './trace-cmd report' after > './trace-cmd record -e all -O stacktrace' but enter 'CTRC+C'. > > If it is a bug here? Any comments? It should stop, but perhaps not immediately. Best to pipe it through less: trace-cmd report |less I may, in the future, make trace-cmd report do its own paging, like git does. But for now, I just use less. The reason for the special ctrl-c is because of the python plugin. It has some strange side effects. One is that it overrides ctrl-c, so I add a handler to explicitly kill trace-cmd. But that still causes a delay before the kill happens. -- Steve ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [RFC]Read kernel stack with trace-cmd 2012-05-08 15:06 ` Steven Rostedt @ 2012-05-09 9:00 ` harryxiyou 2012-05-09 13:58 ` Steven Rostedt 0 siblings, 1 reply; 4+ messages in thread From: harryxiyou @ 2012-05-09 9:00 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel, kernelnewbies, Chen Lijun On Tue, May 8, 2012 at 11:06 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Tue, 2012-05-08 at 22:34 +0800, harryxiyou wrote: > >> > [...] >> => i915_add_request (f850cef4) >> => i915_gem_do_execbuffer (f8510adc) >> Xorg-1104 [001] 3106.003258: irq_handler_exit: > > Isn't this what you asked for? Hmmm.., this is what i wanna see ;-) Actually, i don't know how to analyse these datas got by trace-cmd. Cloud you please give me some descriptions for following ones? #./trace-cmd report | less version = 6 cpus=2 trace-cmd-1666 [000] 66.206448: sys_exit: NR 4 = 1 Xorg-977 [001] 66.206449: sys_exit: NR 265 = 0 trace-cmd-1666 [000] 66.206450: kernel_stack: <stack trace> => syscall_exit_work (c010352a) Xorg-977 [001] 66.206450: kernel_stack: <stack trace> => syscall_exit_work (c010352a) Xorg-977 [001] 66.206455: sys_enter: NR 54 (9, c00c6466, bfcfccb0, 9f42bf0, 863b7b4, bfcfccd8) Xorg-977 [001] 66.206455: kernel_stack: <stack trace> => syscall_trace_entry (c01034ff) trace-cmd-1666 [000] 66.206456: mm_page_alloc: page=0xc13c65a0 pfn=3241960864 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE trace-cmd-1666 [000] 66.206457: kernel_stack: <stack trace> => do_wp_page (c01e5659) => handle_mm_fault (c01e641c) => do_page_fault (c058da8d) => error_code (c058b983) Xorg-977 [001] 66.206463: sys_exit: NR 54 = 0 Xorg-977 [001] 66.206463: kernel_stack: <stack trace> => syscall_exit_work (c010352a) trace-cmd-1666 [000] 66.206467: sys_enter: NR 4 (1, b782f000, 1d, 1d, b782f000, bf91b918) Xorg-977 [001] 66.206467: sys_enter: NR 54 (9, c00c6466, bfcfcd20, 9e767a8, 863b7b4, bfcfcd48) trace-cmd-1666 [000] 66.206467: kernel_stack: <stack trace> => syscall_trace_entry (c01034ff) Xorg-977 [001] 66.206467: kernel_stack: <stack trace> => syscall_trace_entry (c01034ff) Xorg-977 [001] 66.206470: sys_exit: NR 54 = 0 Xorg-977 [001] 66.206470: kernel_stack: <stack trace> => syscall_exit_work (c010352a) Xorg-977 [001] 66.206473: sys_enter: NR 54 (9, c00c6466, bfcfcd90, 9f42620, 863b7b4, bfcfcdb8) Xorg-977 [001] 66.206473: kernel_stack: <stack trace> => syscall_trace_entry (c01034ff) trace-cmd-1666 [000] 66.206475: timer_start: timer 0xef0be8c8: func delayed_work_timer_fn, expires 53251, timeout 1 trace-cmd-1666 [000] 66.206475: kernel_stack: <stack trace> => add_timer (c015be36) => queue_delayed_work_on (c01642df) => queue_delayed_work (c0164370) => schedule_delayed_work (c01643a6) => tty_flip_buffer_push (c03ba7c3) => pty_write (c03bb7ca) => process_output_block (c03b5992) => n_tty_write (c03b669b) Xorg-977 [001] 66.206476: sys_exit: NR 54 = 0 Xorg-977 [001] 66.206476: kernel_stack: <stack trace> => syscall_exit_work (c010352a) Xorg-977 [001] 66.206478: sys_enter: NR 54 (9, c00c6466, bfcfcd90, 9f546d0, 863b7d8, bfcfcdb8) Xorg-977 [001] 66.206479: kernel_stack: <stack trace> => syscall_trace_entry (c01034ff) trace-cmd-1666 [000] 66.206481: sched_wakeup: task trace-cmd:1666 [120] success=0 [000] trace-cmd-1666 [000] 66.206481: kernel_stack: <stack trace> [...] > >> irq=29 return=handled >> Xorg-1104 [001] 3106.003259: kernel_stack: <stack trace> [...] >> => hrtimer_wakeup (c016acad) >> => __run_hrtimer (c016b14a)^Ctrace-cmd: Received SIGINT >> Xorg-1104 [001] 3106.003348: kernel_stack: <stack trace> >> [...] >> >> >> Note: i can't stop the cmd './trace-cmd report' after >> './trace-cmd record -e all -O stacktrace' but enter 'CTRC+C'. >> >> If it is a bug here? Any comments? > > It should stop, but perhaps not immediately. Best to pipe it through > less: > > trace-cmd report |less Yup, it works for me, thanks ;-) > > I may, in the future, make trace-cmd report do its own paging, like git > does. But for now, I just use less. > > The reason for the special ctrl-c is because of the python plugin. It > has some strange side effects. One is that it overrides ctrl-c, so I add > a handler to explicitly kill trace-cmd. But that still causes a delay > before the kill happens. > Hmm.., It sounds well, thanks ;-) -- Thanks Harry Wei ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [RFC]Read kernel stack with trace-cmd 2012-05-09 9:00 ` harryxiyou @ 2012-05-09 13:58 ` Steven Rostedt 0 siblings, 0 replies; 4+ messages in thread From: Steven Rostedt @ 2012-05-09 13:58 UTC (permalink / raw) To: harryxiyou; +Cc: linux-kernel, kernelnewbies, Chen Lijun On Wed, 2012-05-09 at 17:00 +0800, harryxiyou wrote: > On Tue, May 8, 2012 at 11:06 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > > On Tue, 2012-05-08 at 22:34 +0800, harryxiyou wrote: > > > >> > > [...] > >> => i915_add_request (f850cef4) > >> => i915_gem_do_execbuffer (f8510adc) > >> Xorg-1104 [001] 3106.003258: irq_handler_exit: > > > > Isn't this what you asked for? > > Hmmm.., this is what i wanna see ;-) Actually, i don't know how to > analyse these datas got by trace-cmd. Cloud you please give me > some descriptions for following ones? Now -Ostacktrace will only give you the kernel stack, not the userspace. If you are tracing system calls, then that's pretty pointless to use. You could use -Ouserstacktrace but it will only make sense if the userspace had framepointers configured in. Including glibc. Which is seldom done. > > #./trace-cmd report | less > version = 6 > cpus=2 > trace-cmd-1666 [000] 66.206448: sys_exit: NR 4 = 1 > Xorg-977 [001] 66.206449: sys_exit: NR 265 = 0 > trace-cmd-1666 [000] 66.206450: kernel_stack: <stack trace> > => syscall_exit_work (c010352a) > Xorg-977 [001] 66.206450: kernel_stack: <stack trace> > => syscall_exit_work (c010352a) > Xorg-977 [001] 66.206455: sys_enter: NR 54 > (9, c00c6466, bfcfccb0, 9f42bf0, 863b7b4, bfcfccd8) > Xorg-977 [001] 66.206455: kernel_stack: <stack trace> > => syscall_trace_entry (c01034ff) > trace-cmd-1666 [000] 66.206456: mm_page_alloc: > page=0xc13c65a0 pfn=3241960864 order=0 migratetype=2 > gfp_flags=GFP_HIGHUSER_MOVABLE > trace-cmd-1666 [000] 66.206457: kernel_stack: <stack trace> > => do_wp_page (c01e5659) > => handle_mm_fault (c01e641c) > => do_page_fault (c058da8d) > => error_code (c058b983) here... > Xorg-977 [001] 66.206463: sys_exit: NR 54 = 0 > Xorg-977 [001] 66.206463: kernel_stack: <stack trace> > => syscall_exit_work (c010352a) > trace-cmd-1666 [000] 66.206467: sys_enter: NR 4 > (1, b782f000, 1d, 1d, b782f000, bf91b918) > Xorg-977 [001] 66.206467: sys_enter: NR 54 > (9, c00c6466, bfcfcd20, 9e767a8, 863b7b4, bfcfcd48) > trace-cmd-1666 [000] 66.206467: kernel_stack: <stack trace> > => syscall_trace_entry (c01034ff) > Xorg-977 [001] 66.206467: kernel_stack: <stack trace> > => syscall_trace_entry (c01034ff) > Xorg-977 [001] 66.206470: sys_exit: NR 54 = 0 > Xorg-977 [001] 66.206470: kernel_stack: <stack trace> > => syscall_exit_work (c010352a) > Xorg-977 [001] 66.206473: sys_enter: NR 54 > (9, c00c6466, bfcfcd90, 9f42620, 863b7b4, bfcfcdb8) > Xorg-977 [001] 66.206473: kernel_stack: <stack trace> > => syscall_trace_entry (c01034ff) > trace-cmd-1666 [000] 66.206475: timer_start: timer > 0xef0be8c8: func delayed_work_timer_fn, expires 53251, timeout 1 > trace-cmd-1666 [000] 66.206475: kernel_stack: <stack trace> > => add_timer (c015be36) > => queue_delayed_work_on (c01642df) > => queue_delayed_work (c0164370) > => schedule_delayed_work (c01643a6) > => tty_flip_buffer_push (c03ba7c3) > => pty_write (c03bb7ca) > => process_output_block (c03b5992) > => n_tty_write (c03b669b) and here, are the only "interesting" traces. And they are not that interesting. It shows the function graph down to the tracepoint. I really can't tell you how to analyze these, because I have no idea what you are trying to do. -- Steve > Xorg-977 [001] 66.206476: sys_exit: NR 54 = 0 > Xorg-977 [001] 66.206476: kernel_stack: <stack trace> > => syscall_exit_work (c010352a) > Xorg-977 [001] 66.206478: sys_enter: NR 54 > (9, c00c6466, bfcfcd90, 9f546d0, 863b7d8, bfcfcdb8) > Xorg-977 [001] 66.206479: kernel_stack: <stack trace> > => syscall_trace_entry (c01034ff) > trace-cmd-1666 [000] 66.206481: sched_wakeup: task > trace-cmd:1666 [120] success=0 [000] > trace-cmd-1666 [000] 66.206481: kernel_stack: <stack trace> > [...] > > > > >> irq=29 return=handled > >> Xorg-1104 [001] 3106.003259: kernel_stack: <stack trace> > [...] > >> => hrtimer_wakeup (c016acad) > >> => __run_hrtimer (c016b14a)^Ctrace-cmd: Received SIGINT > >> Xorg-1104 [001] 3106.003348: kernel_stack: <stack trace> > >> [...] > >> > >> > >> Note: i can't stop the cmd './trace-cmd report' after > >> './trace-cmd record -e all -O stacktrace' but enter 'CTRC+C'. > >> > >> If it is a bug here? Any comments? > > > > It should stop, but perhaps not immediately. Best to pipe it through > > less: > > > > trace-cmd report |less > > Yup, it works for me, thanks ;-) > > > > > I may, in the future, make trace-cmd report do its own paging, like git > > does. But for now, I just use less. > > > > The reason for the special ctrl-c is because of the python plugin. It > > has some strange side effects. One is that it overrides ctrl-c, so I add > > a handler to explicitly kill trace-cmd. But that still causes a delay > > before the kill happens. > > > > Hmm.., It sounds well, thanks ;-) > > > ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2012-05-09 13:58 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <CAD+1EGN=QjPkkqNNybqRHkMs7a-qR_gWL7-dMxrcE92qrX0X2w@mail.gmail.com>
[not found] ` <1336399968.14207.141.camel@gandalf.stny.rr.com>
2012-05-08 14:34 ` [RFC]Read kernel stack with trace-cmd harryxiyou
2012-05-08 15:06 ` Steven Rostedt
2012-05-09 9:00 ` harryxiyou
2012-05-09 13:58 ` Steven Rostedt
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®