[RFC]Read kernel stack with trace-cmd

[RFC]Read kernel stack with trace-cmd

[harryxiyou]

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

[RFC]Read kernel stack with trace-cmd

[harryxiyou]

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

[RFC]Read kernel stack with trace-cmd

[harryxiyou]

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