On Mon, May 7, 2012 at 10:12 PM, Steven Rostedt <[email protected]> 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
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
On Tue, May 8, 2012 at 11:06 PM, Steven Rostedt <[email protected]> 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
On Wed, 2012-05-09 at 17:00 +0800, harryxiyou wrote:
> On Tue, May 8, 2012 at 11:06 PM, Steven Rostedt <[email protected]> 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 ;-)
>
>
>