* [RFC]Read kernel stack with trace-cmd
@ 2012-05-06 13:25 harryxiyou
[not found] ` <1336399968.14207.141.camel@gandalf.stny.rr.com>
0 siblings, 1 reply; 3+ messages in thread
From: harryxiyou @ 2012-05-06 13:25 UTC (permalink / raw)
To: kernelnewbies
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
# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
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
/sys/kernel/debug/tracing/events/*/filter
syscall(SYS_getpid) = 3497
getpid() = 3497
Kernel buffer statistics:
Note: "entries" are the entries left in the kernel ring buffer and are not
recorded in the trace data. They should all be zero.
CPU: 0
entries: 0
overrun: 0
commit overrun: 0
CPU: 1
entries: 0
overrun: 0
commit overrun: 0
CPU0 data recorded at offset=0x1fc000
53248 bytes in size
CPU1 data recorded at offset=0x209000
12288 bytes in size
# ./trace-cmd report
# ./trace-cmd report > 1
trace-cmd: No such file or directory
unknown op '{'
failed to read event print fmt for hrtimer_start
unknown op '{'
failed to read event print fmt for hrtimer_expire_entry
function jbd2_dev_to_name not defined
failed to read event print fmt for jbd2_submit_inode_data
function jbd2_dev_to_name not defined
...
version = 6
cpus=2
a.out-3497 [001] 417.636333: sys_exit: NR 4 = 1
a.out-3497 [001] 417.636345: sys_enter: NR 11
(bf911946, bf910a44, bf910a4c, bf910a44, c47ff4, bf910874)
a.out-3497 [001] 417.636346: kmem_cache_alloc:
call_site=c021113a ptr=0xd2d61000 bytes_req=4096 bytes_alloc=4096
gfp_flags=GFP_KERNEL
a.out-3497 [001] 417.636347: kmem_cache_alloc:
call_site=c020e906 ptr=0xe3f6e800 bytes_req=256 bytes_alloc=256
gfp_flags=GFP_KERNEL|GFP_ZERO
a.out-3497 [001] 417.636347: kmalloc:
call_site=c020e8f8 ptr=0xe3f6e800 bytes_req=196 bytes_alloc=256
gfp_flags=GFP_KERNEL|GFP_ZERO
a.out-3497 [001] 417.636348: kmem_cache_alloc:
call_site=c016df13 ptr=0xf4124900 bytes_req=32 bytes_alloc=32
gfp_flags=GFP_KERNEL
a.out-3497 [001] 417.636348: kmalloc:
call_site=c016def0 ptr=0xf4124900 bytes_req=28 bytes_alloc=32
gfp_flags=GFP_KERNEL
a.out-3497 [001] 417.636349: kmem_cache_alloc:
call_site=c016db9c ptr=0xd2c6f780 bytes_req=128 bytes_alloc=128
gfp_flags=GFP_KERNEL
...
# cat 1 | tail -10
<idle>-0 [001] 417.652875: hrtimer_start:
[FAILED TO PARSE] timer=0xc1e03d80 function=0xc0176db0
expires=2759989000000 softexpires=2759989000000
<idle>-0 [001] 417.652877: sched_stat_wait: task:
trace-cmd:3494 wait: 22002 [ns]
<idle>-0 [001] 417.652878: sched_switch: task
swapper:0 [120] (R) ==> trace-cmd:3494 [120]
trace-cmd-3494 [001] 417.652880: mm_page_free_direct:
page=0xc174d980 pfn=3245660544 order=0
trace-cmd-3494 [001] 417.652880: mm_page_free_direct:
page=0xc174d980 pfn=3245660544 order=0
trace-cmd-3494 [001] 417.652881: kmem_cache_free:
call_site=c014a6c7 ptr=0xf6b84fc0
trace-cmd-3494 [001] 417.652889: kmem_cache_free:
call_site=c0149bf4 ptr=0xf6b1da40
trace-cmd-3494 [001] 417.652890: kmem_cache_free:
call_site=c0149ce2 ptr=0xe3fba900
trace-cmd-3494 [001] 417.652891: sys_exit: NR 7 = 3497
trace-cmd-3494 [001] 417.652896: sys_enter: NR 4
(3, 806fb9a, 1, 0, 0, bf910898)
--
Thanks
Harry Wei
^ permalink raw reply [flat|nested] 3+ messages in thread[parent not found: <1336399968.14207.141.camel@gandalf.stny.rr.com>]
* [RFC]Read kernel stack with trace-cmd [not found] ` <1336399968.14207.141.camel@gandalf.stny.rr.com> @ 2012-05-08 14:34 ` harryxiyou [not found] ` <1336489566.14207.180.camel@gandalf.stny.rr.com> 0 siblings, 1 reply; 3+ messages in thread From: harryxiyou @ 2012-05-08 14:34 UTC (permalink / raw) To: kernelnewbies 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] 3+ messages in thread
[parent not found: <1336489566.14207.180.camel@gandalf.stny.rr.com>]
* [RFC]Read kernel stack with trace-cmd [not found] ` <1336489566.14207.180.camel@gandalf.stny.rr.com> @ 2012-05-09 9:00 ` harryxiyou 0 siblings, 0 replies; 3+ messages in thread From: harryxiyou @ 2012-05-09 9:00 UTC (permalink / raw) To: kernelnewbies 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] 3+ messages in thread
end of thread, other threads:[~2012-05-09 9:00 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2012-05-06 13:25 [RFC]Read kernel stack with trace-cmd harryxiyou
[not found] ` <1336399968.14207.141.camel@gandalf.stny.rr.com>
2012-05-08 14:34 ` harryxiyou
[not found] ` <1336489566.14207.180.camel@gandalf.stny.rr.com>
2012-05-09 9:00 ` harryxiyou
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).