Re: [PATCHSET 00/10] perf tools: Support dynamic sort keys for tracepoints (v2)

2015-12-17 Thread Arnaldo Carvalho de Melo
Em Thu, Dec 17, 2015 at 04:56:31PM +0900, Namhyung Kim escreveu:
> Hi Arnaldo,
> 
> On Wed, Dec 16, 2015 at 09:17:59PM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Wed, Dec 16, 2015 at 12:35:33AM +0900, Namhyung Kim escreveu:
> > > Hello,
> > > 
> > > This is an attempt to improve perf to deal with tracepoint events
> > > better.  The perf tools can handle tracepoint events but perf report
> > > on them is less useful since they're always sampled in a fixed
> > > location and not provide event specific info.  We can use perf script
> > > but I always wishes there's more convenient way to see the result.
> > > 
> > >  * changes in v2)
> > >   - add 'trace' sort key and make it default  (Jiri)
> > >   - add '--raw-trace' option and '/raw' field modifier  (Jiri)
> > >   - support event name shortcuts  (David)
> > 
> > Can you take a look if you can reproduce this? Without callchains it works 
> > in
> > all tests I did.
> 
> Argh, it was because I forgot to set raw_data/size field for
> --children case.  I'll send the fix soon.
> 
> Maybe we can disable --children for tracepoint sessions (or if it
> doesn't have symbol sort key)?

Looks like a plan, unless we want to have all the callchains that get to
some specific DSO or pid.

- Arnaldo
 
> Thanks,
> Namhyung
> 
> 
> > 
> > [root@zoo ~]# perf record -g -e kmem:kmalloc -a
> > ^C[ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 1.193 MB perf.data (250 samples) ]
> > 
> > [root@zoo ~]# perf report
> > perf: Segmentation fault
> >  backtrace 
> > perf[0x539f1b]
> > /lib64/libc.so.6(+0x34960)[0x7fc8e3752960]
> > perf(pevent_read_number+0x78)[0x542e40]
> > perf(pevent_read_number_field+0x70)[0x542ed3]
> > /root/.traceevent/plugins/plugin_kmem.so(+0x603)[0x7fc8e1a6c603]
> > perf(pevent_event_info+0x96)[0x547597]
> > perf[0x4dce26]
> > perf[0x4e0e89]
> > perf(hist_entry_iter__add+0xee)[0x4e125e]
> > perf[0x4304be]
> > perf[0x4c2db3]
> > perf[0x4c3301]
> > perf[0x4c6089]
> > perf(perf_session__process_events+0x3f1)[0x4c4b91]
> > perf(cmd_report+0x120b)[0x4319cb]
> > perf[0x47c871]
> > perf(main+0x63f)[0x42242f]
> > /lib64/libc.so.6(__libc_start_main+0xf0)[0x7fc8e373dfe0]
> > perf[0x422549]
> > [0x0]
> > [root@zoo ~]# ls -la ~/.traceevent/
> > total 12
> > drwxr-xr-x.  3 acme acme 4096 May  4  2015 .
> > drwx--. 61 acme acme 4096 Dec 16 21:12 ..
> > drwxr-xr-x.  2 acme acme 4096 Nov 23 11:15 plugins
> > [root@zoo ~]# ls -la ~/.traceevent
> > lrwxrwxrwx. 1 root root 23 May  4  2015 /root/.traceevent -> 
> > /home/acme/.traceevent/
> > [root@zoo ~]# perf record -e sched:sched_switch -a
> > 
> > 
> > ^C[ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 1.704 MB perf.data (4967 samples) ]
> > 
> > [root@zoo ~]# perf report
> > [root@zoo ~]# perf record -g -e sched:sched_switch -a
> > ^C[ perf record: Woken up 2 times to write data ]
> > [ perf record: Captured and wrote 2.062 MB perf.data (4743 samples) ]
> > 
> > [root@zoo ~]# perf report
> > perf: Segmentation fault
> >  backtrace 
> > perf[0x539f1b]
> > /lib64/libc.so.6(+0x34960)[0x7fecb3223960]
> > perf(pevent_read_number+0x60)[0x542e28]
> > perf(pevent_read_number_field+0x70)[0x542ed3]
> > perf(get_field_val+0x6b)[0x548cd5]
> > perf(pevent_get_field_val+0x6b)[0x548e77]
> > /root/.traceevent/plugins/plugin_sched_switch.so(+0x95b)[0x7fecb194195b]
> > perf(pevent_event_info+0x96)[0x547597]
> > perf[0x4dce26]
> > perf[0x4e0e89]
> > perf(hist_entry_iter__add+0xee)[0x4e125e]
> > perf[0x4304be]
> > perf[0x4c2db3]
> > perf[0x4c3301]
> > perf[0x4c5fdb]
> > perf[0x4c3535]
> > perf(perf_session__process_events+0x3a0)[0x4c4b40]
> > perf(cmd_report+0x120b)[0x4319cb]
> > perf[0x47c871]
> > perf(main+0x63f)[0x42242f]
> > /lib64/libc.so.6(__libc_start_main+0xf0)[0x7fecb320efe0]
> > perf[0x422549]
> > [0x0]
> > [root@zoo ~]# 
> > 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


Re: [PATCHSET 00/10] perf tools: Support dynamic sort keys for tracepoints (v2)

2015-12-17 Thread Arnaldo Carvalho de Melo
Em Thu, Dec 17, 2015 at 04:56:31PM +0900, Namhyung Kim escreveu:
> Hi Arnaldo,
> 
> On Wed, Dec 16, 2015 at 09:17:59PM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Wed, Dec 16, 2015 at 12:35:33AM +0900, Namhyung Kim escreveu:
> > > Hello,
> > > 
> > > This is an attempt to improve perf to deal with tracepoint events
> > > better.  The perf tools can handle tracepoint events but perf report
> > > on them is less useful since they're always sampled in a fixed
> > > location and not provide event specific info.  We can use perf script
> > > but I always wishes there's more convenient way to see the result.
> > > 
> > >  * changes in v2)
> > >   - add 'trace' sort key and make it default  (Jiri)
> > >   - add '--raw-trace' option and '/raw' field modifier  (Jiri)
> > >   - support event name shortcuts  (David)
> > 
> > Can you take a look if you can reproduce this? Without callchains it works 
> > in
> > all tests I did.
> 
> Argh, it was because I forgot to set raw_data/size field for
> --children case.  I'll send the fix soon.
> 
> Maybe we can disable --children for tracepoint sessions (or if it
> doesn't have symbol sort key)?

Looks like a plan, unless we want to have all the callchains that get to
some specific DSO or pid.

- Arnaldo
 
> Thanks,
> Namhyung
> 
> 
> > 
> > [root@zoo ~]# perf record -g -e kmem:kmalloc -a
> > ^C[ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 1.193 MB perf.data (250 samples) ]
> > 
> > [root@zoo ~]# perf report
> > perf: Segmentation fault
> >  backtrace 
> > perf[0x539f1b]
> > /lib64/libc.so.6(+0x34960)[0x7fc8e3752960]
> > perf(pevent_read_number+0x78)[0x542e40]
> > perf(pevent_read_number_field+0x70)[0x542ed3]
> > /root/.traceevent/plugins/plugin_kmem.so(+0x603)[0x7fc8e1a6c603]
> > perf(pevent_event_info+0x96)[0x547597]
> > perf[0x4dce26]
> > perf[0x4e0e89]
> > perf(hist_entry_iter__add+0xee)[0x4e125e]
> > perf[0x4304be]
> > perf[0x4c2db3]
> > perf[0x4c3301]
> > perf[0x4c6089]
> > perf(perf_session__process_events+0x3f1)[0x4c4b91]
> > perf(cmd_report+0x120b)[0x4319cb]
> > perf[0x47c871]
> > perf(main+0x63f)[0x42242f]
> > /lib64/libc.so.6(__libc_start_main+0xf0)[0x7fc8e373dfe0]
> > perf[0x422549]
> > [0x0]
> > [root@zoo ~]# ls -la ~/.traceevent/
> > total 12
> > drwxr-xr-x.  3 acme acme 4096 May  4  2015 .
> > drwx--. 61 acme acme 4096 Dec 16 21:12 ..
> > drwxr-xr-x.  2 acme acme 4096 Nov 23 11:15 plugins
> > [root@zoo ~]# ls -la ~/.traceevent
> > lrwxrwxrwx. 1 root root 23 May  4  2015 /root/.traceevent -> 
> > /home/acme/.traceevent/
> > [root@zoo ~]# perf record -e sched:sched_switch -a
> > 
> > 
> > ^C[ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 1.704 MB perf.data (4967 samples) ]
> > 
> > [root@zoo ~]# perf report
> > [root@zoo ~]# perf record -g -e sched:sched_switch -a
> > ^C[ perf record: Woken up 2 times to write data ]
> > [ perf record: Captured and wrote 2.062 MB perf.data (4743 samples) ]
> > 
> > [root@zoo ~]# perf report
> > perf: Segmentation fault
> >  backtrace 
> > perf[0x539f1b]
> > /lib64/libc.so.6(+0x34960)[0x7fecb3223960]
> > perf(pevent_read_number+0x60)[0x542e28]
> > perf(pevent_read_number_field+0x70)[0x542ed3]
> > perf(get_field_val+0x6b)[0x548cd5]
> > perf(pevent_get_field_val+0x6b)[0x548e77]
> > /root/.traceevent/plugins/plugin_sched_switch.so(+0x95b)[0x7fecb194195b]
> > perf(pevent_event_info+0x96)[0x547597]
> > perf[0x4dce26]
> > perf[0x4e0e89]
> > perf(hist_entry_iter__add+0xee)[0x4e125e]
> > perf[0x4304be]
> > perf[0x4c2db3]
> > perf[0x4c3301]
> > perf[0x4c5fdb]
> > perf[0x4c3535]
> > perf(perf_session__process_events+0x3a0)[0x4c4b40]
> > perf(cmd_report+0x120b)[0x4319cb]
> > perf[0x47c871]
> > perf(main+0x63f)[0x42242f]
> > /lib64/libc.so.6(__libc_start_main+0xf0)[0x7fecb320efe0]
> > perf[0x422549]
> > [0x0]
> > [root@zoo ~]# 
> > 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


Re: [PATCHSET 00/10] perf tools: Support dynamic sort keys for tracepoints (v2)

2015-12-16 Thread Namhyung Kim
Hi Arnaldo,

On Wed, Dec 16, 2015 at 09:17:59PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Wed, Dec 16, 2015 at 12:35:33AM +0900, Namhyung Kim escreveu:
> > Hello,
> > 
> > This is an attempt to improve perf to deal with tracepoint events
> > better.  The perf tools can handle tracepoint events but perf report
> > on them is less useful since they're always sampled in a fixed
> > location and not provide event specific info.  We can use perf script
> > but I always wishes there's more convenient way to see the result.
> > 
> >  * changes in v2)
> >   - add 'trace' sort key and make it default  (Jiri)
> >   - add '--raw-trace' option and '/raw' field modifier  (Jiri)
> >   - support event name shortcuts  (David)
> 
> Can you take a look if you can reproduce this? Without callchains it works in
> all tests I did.

Argh, it was because I forgot to set raw_data/size field for
--children case.  I'll send the fix soon.

Maybe we can disable --children for tracepoint sessions (or if it
doesn't have symbol sort key)?

Thanks,
Namhyung


> 
> [root@zoo ~]# perf record -g -e kmem:kmalloc -a
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 1.193 MB perf.data (250 samples) ]
> 
> [root@zoo ~]# perf report
> perf: Segmentation fault
>  backtrace 
> perf[0x539f1b]
> /lib64/libc.so.6(+0x34960)[0x7fc8e3752960]
> perf(pevent_read_number+0x78)[0x542e40]
> perf(pevent_read_number_field+0x70)[0x542ed3]
> /root/.traceevent/plugins/plugin_kmem.so(+0x603)[0x7fc8e1a6c603]
> perf(pevent_event_info+0x96)[0x547597]
> perf[0x4dce26]
> perf[0x4e0e89]
> perf(hist_entry_iter__add+0xee)[0x4e125e]
> perf[0x4304be]
> perf[0x4c2db3]
> perf[0x4c3301]
> perf[0x4c6089]
> perf(perf_session__process_events+0x3f1)[0x4c4b91]
> perf(cmd_report+0x120b)[0x4319cb]
> perf[0x47c871]
> perf(main+0x63f)[0x42242f]
> /lib64/libc.so.6(__libc_start_main+0xf0)[0x7fc8e373dfe0]
> perf[0x422549]
> [0x0]
> [root@zoo ~]# ls -la ~/.traceevent/
> total 12
> drwxr-xr-x.  3 acme acme 4096 May  4  2015 .
> drwx--. 61 acme acme 4096 Dec 16 21:12 ..
> drwxr-xr-x.  2 acme acme 4096 Nov 23 11:15 plugins
> [root@zoo ~]# ls -la ~/.traceevent
> lrwxrwxrwx. 1 root root 23 May  4  2015 /root/.traceevent -> 
> /home/acme/.traceevent/
> [root@zoo ~]# perf record -e sched:sched_switch -a
> 
> 
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 1.704 MB perf.data (4967 samples) ]
> 
> [root@zoo ~]# perf report
> [root@zoo ~]# perf record -g -e sched:sched_switch -a
> ^C[ perf record: Woken up 2 times to write data ]
> [ perf record: Captured and wrote 2.062 MB perf.data (4743 samples) ]
> 
> [root@zoo ~]# perf report
> perf: Segmentation fault
>  backtrace 
> perf[0x539f1b]
> /lib64/libc.so.6(+0x34960)[0x7fecb3223960]
> perf(pevent_read_number+0x60)[0x542e28]
> perf(pevent_read_number_field+0x70)[0x542ed3]
> perf(get_field_val+0x6b)[0x548cd5]
> perf(pevent_get_field_val+0x6b)[0x548e77]
> /root/.traceevent/plugins/plugin_sched_switch.so(+0x95b)[0x7fecb194195b]
> perf(pevent_event_info+0x96)[0x547597]
> perf[0x4dce26]
> perf[0x4e0e89]
> perf(hist_entry_iter__add+0xee)[0x4e125e]
> perf[0x4304be]
> perf[0x4c2db3]
> perf[0x4c3301]
> perf[0x4c5fdb]
> perf[0x4c3535]
> perf(perf_session__process_events+0x3a0)[0x4c4b40]
> perf(cmd_report+0x120b)[0x4319cb]
> perf[0x47c871]
> perf(main+0x63f)[0x42242f]
> /lib64/libc.so.6(__libc_start_main+0xf0)[0x7fecb320efe0]
> perf[0x422549]
> [0x0]
> [root@zoo ~]# 
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


Re: [PATCHSET 00/10] perf tools: Support dynamic sort keys for tracepoints (v2)

2015-12-16 Thread Arnaldo Carvalho de Melo
Em Wed, Dec 16, 2015 at 12:35:33AM +0900, Namhyung Kim escreveu:
> Hello,
> 
> This is an attempt to improve perf to deal with tracepoint events
> better.  The perf tools can handle tracepoint events but perf report
> on them is less useful since they're always sampled in a fixed
> location and not provide event specific info.  We can use perf script
> but I always wishes there's more convenient way to see the result.
> 
>  * changes in v2)
>   - add 'trace' sort key and make it default  (Jiri)
>   - add '--raw-trace' option and '/raw' field modifier  (Jiri)
>   - support event name shortcuts  (David)

Can you take a look if you can reproduce this? Without callchains it works in
all tests I did.

[root@zoo ~]# perf record -g -e kmem:kmalloc -a
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.193 MB perf.data (250 samples) ]

[root@zoo ~]# perf report
perf: Segmentation fault
 backtrace 
perf[0x539f1b]
/lib64/libc.so.6(+0x34960)[0x7fc8e3752960]
perf(pevent_read_number+0x78)[0x542e40]
perf(pevent_read_number_field+0x70)[0x542ed3]
/root/.traceevent/plugins/plugin_kmem.so(+0x603)[0x7fc8e1a6c603]
perf(pevent_event_info+0x96)[0x547597]
perf[0x4dce26]
perf[0x4e0e89]
perf(hist_entry_iter__add+0xee)[0x4e125e]
perf[0x4304be]
perf[0x4c2db3]
perf[0x4c3301]
perf[0x4c6089]
perf(perf_session__process_events+0x3f1)[0x4c4b91]
perf(cmd_report+0x120b)[0x4319cb]
perf[0x47c871]
perf(main+0x63f)[0x42242f]
/lib64/libc.so.6(__libc_start_main+0xf0)[0x7fc8e373dfe0]
perf[0x422549]
[0x0]
[root@zoo ~]# ls -la ~/.traceevent/
total 12
drwxr-xr-x.  3 acme acme 4096 May  4  2015 .
drwx--. 61 acme acme 4096 Dec 16 21:12 ..
drwxr-xr-x.  2 acme acme 4096 Nov 23 11:15 plugins
[root@zoo ~]# ls -la ~/.traceevent
lrwxrwxrwx. 1 root root 23 May  4  2015 /root/.traceevent -> 
/home/acme/.traceevent/
[root@zoo ~]# perf record -e sched:sched_switch -a


^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.704 MB perf.data (4967 samples) ]

[root@zoo ~]# perf report
[root@zoo ~]# perf record -g -e sched:sched_switch -a
^C[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 2.062 MB perf.data (4743 samples) ]

[root@zoo ~]# perf report
perf: Segmentation fault
 backtrace 
perf[0x539f1b]
/lib64/libc.so.6(+0x34960)[0x7fecb3223960]
perf(pevent_read_number+0x60)[0x542e28]
perf(pevent_read_number_field+0x70)[0x542ed3]
perf(get_field_val+0x6b)[0x548cd5]
perf(pevent_get_field_val+0x6b)[0x548e77]
/root/.traceevent/plugins/plugin_sched_switch.so(+0x95b)[0x7fecb194195b]
perf(pevent_event_info+0x96)[0x547597]
perf[0x4dce26]
perf[0x4e0e89]
perf(hist_entry_iter__add+0xee)[0x4e125e]
perf[0x4304be]
perf[0x4c2db3]
perf[0x4c3301]
perf[0x4c5fdb]
perf[0x4c3535]
perf(perf_session__process_events+0x3a0)[0x4c4b40]
perf(cmd_report+0x120b)[0x4319cb]
perf[0x47c871]
perf(main+0x63f)[0x42242f]
/lib64/libc.so.6(__libc_start_main+0xf0)[0x7fecb320efe0]
perf[0x422549]
[0x0]
[root@zoo ~]# 

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


Re: [PATCHSET 00/10] perf tools: Support dynamic sort keys for tracepoints (v2)

2015-12-16 Thread Arnaldo Carvalho de Melo
Em Wed, Dec 16, 2015 at 12:35:33AM +0900, Namhyung Kim escreveu:
> Hello,
> 
> This is an attempt to improve perf to deal with tracepoint events
> better.  The perf tools can handle tracepoint events but perf report
> on them is less useful since they're always sampled in a fixed
> location and not provide event specific info.  We can use perf script
> but I always wishes there's more convenient way to see the result.
> 
>  * changes in v2)
>   - add 'trace' sort key and make it default  (Jiri)
>   - add '--raw-trace' option and '/raw' field modifier  (Jiri)
>   - support event name shortcuts  (David)

Can you take a look if you can reproduce this? Without callchains it works in
all tests I did.

[root@zoo ~]# perf record -g -e kmem:kmalloc -a
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.193 MB perf.data (250 samples) ]

[root@zoo ~]# perf report
perf: Segmentation fault
 backtrace 
perf[0x539f1b]
/lib64/libc.so.6(+0x34960)[0x7fc8e3752960]
perf(pevent_read_number+0x78)[0x542e40]
perf(pevent_read_number_field+0x70)[0x542ed3]
/root/.traceevent/plugins/plugin_kmem.so(+0x603)[0x7fc8e1a6c603]
perf(pevent_event_info+0x96)[0x547597]
perf[0x4dce26]
perf[0x4e0e89]
perf(hist_entry_iter__add+0xee)[0x4e125e]
perf[0x4304be]
perf[0x4c2db3]
perf[0x4c3301]
perf[0x4c6089]
perf(perf_session__process_events+0x3f1)[0x4c4b91]
perf(cmd_report+0x120b)[0x4319cb]
perf[0x47c871]
perf(main+0x63f)[0x42242f]
/lib64/libc.so.6(__libc_start_main+0xf0)[0x7fc8e373dfe0]
perf[0x422549]
[0x0]
[root@zoo ~]# ls -la ~/.traceevent/
total 12
drwxr-xr-x.  3 acme acme 4096 May  4  2015 .
drwx--. 61 acme acme 4096 Dec 16 21:12 ..
drwxr-xr-x.  2 acme acme 4096 Nov 23 11:15 plugins
[root@zoo ~]# ls -la ~/.traceevent
lrwxrwxrwx. 1 root root 23 May  4  2015 /root/.traceevent -> 
/home/acme/.traceevent/
[root@zoo ~]# perf record -e sched:sched_switch -a


^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.704 MB perf.data (4967 samples) ]

[root@zoo ~]# perf report
[root@zoo ~]# perf record -g -e sched:sched_switch -a
^C[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 2.062 MB perf.data (4743 samples) ]

[root@zoo ~]# perf report
perf: Segmentation fault
 backtrace 
perf[0x539f1b]
/lib64/libc.so.6(+0x34960)[0x7fecb3223960]
perf(pevent_read_number+0x60)[0x542e28]
perf(pevent_read_number_field+0x70)[0x542ed3]
perf(get_field_val+0x6b)[0x548cd5]
perf(pevent_get_field_val+0x6b)[0x548e77]
/root/.traceevent/plugins/plugin_sched_switch.so(+0x95b)[0x7fecb194195b]
perf(pevent_event_info+0x96)[0x547597]
perf[0x4dce26]
perf[0x4e0e89]
perf(hist_entry_iter__add+0xee)[0x4e125e]
perf[0x4304be]
perf[0x4c2db3]
perf[0x4c3301]
perf[0x4c5fdb]
perf[0x4c3535]
perf(perf_session__process_events+0x3a0)[0x4c4b40]
perf(cmd_report+0x120b)[0x4319cb]
perf[0x47c871]
perf(main+0x63f)[0x42242f]
/lib64/libc.so.6(__libc_start_main+0xf0)[0x7fecb320efe0]
perf[0x422549]
[0x0]
[root@zoo ~]# 

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


Re: [PATCHSET 00/10] perf tools: Support dynamic sort keys for tracepoints (v2)

2015-12-16 Thread Namhyung Kim
Hi Arnaldo,

On Wed, Dec 16, 2015 at 09:17:59PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Wed, Dec 16, 2015 at 12:35:33AM +0900, Namhyung Kim escreveu:
> > Hello,
> > 
> > This is an attempt to improve perf to deal with tracepoint events
> > better.  The perf tools can handle tracepoint events but perf report
> > on them is less useful since they're always sampled in a fixed
> > location and not provide event specific info.  We can use perf script
> > but I always wishes there's more convenient way to see the result.
> > 
> >  * changes in v2)
> >   - add 'trace' sort key and make it default  (Jiri)
> >   - add '--raw-trace' option and '/raw' field modifier  (Jiri)
> >   - support event name shortcuts  (David)
> 
> Can you take a look if you can reproduce this? Without callchains it works in
> all tests I did.

Argh, it was because I forgot to set raw_data/size field for
--children case.  I'll send the fix soon.

Maybe we can disable --children for tracepoint sessions (or if it
doesn't have symbol sort key)?

Thanks,
Namhyung


> 
> [root@zoo ~]# perf record -g -e kmem:kmalloc -a
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 1.193 MB perf.data (250 samples) ]
> 
> [root@zoo ~]# perf report
> perf: Segmentation fault
>  backtrace 
> perf[0x539f1b]
> /lib64/libc.so.6(+0x34960)[0x7fc8e3752960]
> perf(pevent_read_number+0x78)[0x542e40]
> perf(pevent_read_number_field+0x70)[0x542ed3]
> /root/.traceevent/plugins/plugin_kmem.so(+0x603)[0x7fc8e1a6c603]
> perf(pevent_event_info+0x96)[0x547597]
> perf[0x4dce26]
> perf[0x4e0e89]
> perf(hist_entry_iter__add+0xee)[0x4e125e]
> perf[0x4304be]
> perf[0x4c2db3]
> perf[0x4c3301]
> perf[0x4c6089]
> perf(perf_session__process_events+0x3f1)[0x4c4b91]
> perf(cmd_report+0x120b)[0x4319cb]
> perf[0x47c871]
> perf(main+0x63f)[0x42242f]
> /lib64/libc.so.6(__libc_start_main+0xf0)[0x7fc8e373dfe0]
> perf[0x422549]
> [0x0]
> [root@zoo ~]# ls -la ~/.traceevent/
> total 12
> drwxr-xr-x.  3 acme acme 4096 May  4  2015 .
> drwx--. 61 acme acme 4096 Dec 16 21:12 ..
> drwxr-xr-x.  2 acme acme 4096 Nov 23 11:15 plugins
> [root@zoo ~]# ls -la ~/.traceevent
> lrwxrwxrwx. 1 root root 23 May  4  2015 /root/.traceevent -> 
> /home/acme/.traceevent/
> [root@zoo ~]# perf record -e sched:sched_switch -a
> 
> 
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 1.704 MB perf.data (4967 samples) ]
> 
> [root@zoo ~]# perf report
> [root@zoo ~]# perf record -g -e sched:sched_switch -a
> ^C[ perf record: Woken up 2 times to write data ]
> [ perf record: Captured and wrote 2.062 MB perf.data (4743 samples) ]
> 
> [root@zoo ~]# perf report
> perf: Segmentation fault
>  backtrace 
> perf[0x539f1b]
> /lib64/libc.so.6(+0x34960)[0x7fecb3223960]
> perf(pevent_read_number+0x60)[0x542e28]
> perf(pevent_read_number_field+0x70)[0x542ed3]
> perf(get_field_val+0x6b)[0x548cd5]
> perf(pevent_get_field_val+0x6b)[0x548e77]
> /root/.traceevent/plugins/plugin_sched_switch.so(+0x95b)[0x7fecb194195b]
> perf(pevent_event_info+0x96)[0x547597]
> perf[0x4dce26]
> perf[0x4e0e89]
> perf(hist_entry_iter__add+0xee)[0x4e125e]
> perf[0x4304be]
> perf[0x4c2db3]
> perf[0x4c3301]
> perf[0x4c5fdb]
> perf[0x4c3535]
> perf(perf_session__process_events+0x3a0)[0x4c4b40]
> perf(cmd_report+0x120b)[0x4319cb]
> perf[0x47c871]
> perf(main+0x63f)[0x42242f]
> /lib64/libc.so.6(__libc_start_main+0xf0)[0x7fecb320efe0]
> perf[0x422549]
> [0x0]
> [root@zoo ~]# 
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


[PATCHSET 00/10] perf tools: Support dynamic sort keys for tracepoints (v2)

2015-12-15 Thread Namhyung Kim
Hello,

This is an attempt to improve perf to deal with tracepoint events
better.  The perf tools can handle tracepoint events but perf report
on them is less useful since they're always sampled in a fixed
location and not provide event specific info.  We can use perf script
but I always wishes there's more convenient way to see the result.

 * changes in v2)
  - add 'trace' sort key and make it default  (Jiri)
  - add '--raw-trace' option and '/raw' field modifier  (Jiri)
  - support event name shortcuts  (David)


I suggest dynamic sort keys created for each event.field on demand.
Consider following example:

  # Overhead  Command  Shared Object Symbol
  #   ...    ..
  #
  47.22%  swapper  [kernel.vmlinux]  [k] __schedule
  21.67%  transmission-gt  [kernel.vmlinux]  [k] __schedule
   8.23%  netctl-auto  [kernel.vmlinux]  [k] __schedule
   5.53%  kworker/0:1H [kernel.vmlinux]  [k] __schedule
   1.98%  Xephyr   [kernel.vmlinux]  [k] __schedule
   1.33%  irq/33-iwlwifi   [kernel.vmlinux]  [k] __schedule
   1.17%  wpa_cli  [kernel.vmlinux]  [k] __schedule
   1.13%  rcu_preempt  [kernel.vmlinux]  [k] __schedule
   0.85%  ksoftirqd/0  [kernel.vmlinux]  [k] __schedule
   0.77%  Timer[kernel.vmlinux]  [k] __schedule
  ...

Currently perf report only shows this but important info is on the
event fields, that is:

  # sudo cat /sys/kernel/debug/tracing/events/sched/sched_switch/format
  name: sched_switch
  ID: 268
  format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;

field:char prev_comm[16]; offset:8;  size:16; signed:1;
field:pid_t prev_pid; offset:24; size:4;  signed:1;
field:int prev_prio;  offset:28; size:4;  signed:1;
field:long prev_state;offset:32; size:8;  signed:1;
field:char next_comm[16]; offset:40; size:16; signed:1;
field:pid_t next_pid; offset:56; size:4;  signed:1;
field:int next_prio;  offset:60; size:4;  signed:1;

  print fmt: "prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==>
  next_comm=%s next_pid=%d next_prio=%d",
REC->prev_comm, REC->prev_pid, REC->prev_prio,
REC->prev_state & (2048-1) ? __print_flags(REC->prev_state & (2048-1),
"|", { 1, "S"} , { 2, "D" }, { 4, "T" }, { 8, "t" }, { 16, "Z" }, { 32, "X" 
},
{ 64, "x" }, { 128, "K"}, { 256, "W" }, { 512, "P" }, { 1024, "N" }) : "R",
REC->prev_state & 2048 ? "+" : "", REC->next_comm, REC->next_pid, 
REC->next_prio

With dynamic sort keys, you can use  as a sort key.  Those
dynamic keys are checked and created on demand.  For instance, below is
to sort by next_pid field on the same data file.

  $ perf report -s comm,sched:sched_switch.next_pid --stdio
  ...
  # Overhead  Commandnext_pid
  #   ...  ..
  #
  21.23%  transmission-gt   0
  20.86%  swapper   17773
   6.62%  netctl-auto   0
   5.25%  swapper 109
   5.21%  kworker/0:1H  0
   1.98%  Xephyr0
   1.98%  swapper6524
   1.98%  swapper   27478
   1.37%  swapper   27476
   1.17%  swapper 233
  ...

Multiple dynamic sort keys are also supported and the event name can
be simplified (or even om in a couple of ways (see patch 10/10):

  $ perf report -s comm,switch.next_pid,next_comm --stdio
  ...
  # Overhead  Commandnext_pid next_comm
  #   ...  ..  
  #
  20.86%  swapper   17773   transmission-gt
   9.64%  transmission-gt   0 swapper/0
   9.16%  transmission-gt   0 swapper/2
   5.25%  swapper 109  kworker/0:1H
   5.21%  kworker/0:1H  0 swapper/0
   2.14%  netctl-auto   0 swapper/2
   1.98%  netctl-auto   0 swapper/0
   1.98%  swapper6524Xephyr
   1.98%  swapper   27478   netctl-auto
   1.78%  transmission-gt   0 swapper/3
   1.53%  Xephyr0 swapper/0
   1.29%  netctl-auto   0 swapper/1
   1.29%  swapper   27476   netctl-auto
   1.21%  netctl-auto   0 swapper/3
   1.17%  swapper 233irq/33-iwlwifi
  ...

Note that pid 0 exists for each cpu so have comm of 'swapper/N'.

Also now it add a new 'trace' sort key to print whole trace output.
(The 'trace' sort key is the default key for tracepoint 

[PATCHSET 00/10] perf tools: Support dynamic sort keys for tracepoints (v2)

2015-12-15 Thread Namhyung Kim
Hello,

This is an attempt to improve perf to deal with tracepoint events
better.  The perf tools can handle tracepoint events but perf report
on them is less useful since they're always sampled in a fixed
location and not provide event specific info.  We can use perf script
but I always wishes there's more convenient way to see the result.

 * changes in v2)
  - add 'trace' sort key and make it default  (Jiri)
  - add '--raw-trace' option and '/raw' field modifier  (Jiri)
  - support event name shortcuts  (David)


I suggest dynamic sort keys created for each event.field on demand.
Consider following example:

  # Overhead  Command  Shared Object Symbol
  #   ...    ..
  #
  47.22%  swapper  [kernel.vmlinux]  [k] __schedule
  21.67%  transmission-gt  [kernel.vmlinux]  [k] __schedule
   8.23%  netctl-auto  [kernel.vmlinux]  [k] __schedule
   5.53%  kworker/0:1H [kernel.vmlinux]  [k] __schedule
   1.98%  Xephyr   [kernel.vmlinux]  [k] __schedule
   1.33%  irq/33-iwlwifi   [kernel.vmlinux]  [k] __schedule
   1.17%  wpa_cli  [kernel.vmlinux]  [k] __schedule
   1.13%  rcu_preempt  [kernel.vmlinux]  [k] __schedule
   0.85%  ksoftirqd/0  [kernel.vmlinux]  [k] __schedule
   0.77%  Timer[kernel.vmlinux]  [k] __schedule
  ...

Currently perf report only shows this but important info is on the
event fields, that is:

  # sudo cat /sys/kernel/debug/tracing/events/sched/sched_switch/format
  name: sched_switch
  ID: 268
  format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;

field:char prev_comm[16]; offset:8;  size:16; signed:1;
field:pid_t prev_pid; offset:24; size:4;  signed:1;
field:int prev_prio;  offset:28; size:4;  signed:1;
field:long prev_state;offset:32; size:8;  signed:1;
field:char next_comm[16]; offset:40; size:16; signed:1;
field:pid_t next_pid; offset:56; size:4;  signed:1;
field:int next_prio;  offset:60; size:4;  signed:1;

  print fmt: "prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==>
  next_comm=%s next_pid=%d next_prio=%d",
REC->prev_comm, REC->prev_pid, REC->prev_prio,
REC->prev_state & (2048-1) ? __print_flags(REC->prev_state & (2048-1),
"|", { 1, "S"} , { 2, "D" }, { 4, "T" }, { 8, "t" }, { 16, "Z" }, { 32, "X" 
},
{ 64, "x" }, { 128, "K"}, { 256, "W" }, { 512, "P" }, { 1024, "N" }) : "R",
REC->prev_state & 2048 ? "+" : "", REC->next_comm, REC->next_pid, 
REC->next_prio

With dynamic sort keys, you can use  as a sort key.  Those
dynamic keys are checked and created on demand.  For instance, below is
to sort by next_pid field on the same data file.

  $ perf report -s comm,sched:sched_switch.next_pid --stdio
  ...
  # Overhead  Commandnext_pid
  #   ...  ..
  #
  21.23%  transmission-gt   0
  20.86%  swapper   17773
   6.62%  netctl-auto   0
   5.25%  swapper 109
   5.21%  kworker/0:1H  0
   1.98%  Xephyr0
   1.98%  swapper6524
   1.98%  swapper   27478
   1.37%  swapper   27476
   1.17%  swapper 233
  ...

Multiple dynamic sort keys are also supported and the event name can
be simplified (or even om in a couple of ways (see patch 10/10):

  $ perf report -s comm,switch.next_pid,next_comm --stdio
  ...
  # Overhead  Commandnext_pid next_comm
  #   ...  ..  
  #
  20.86%  swapper   17773   transmission-gt
   9.64%  transmission-gt   0 swapper/0
   9.16%  transmission-gt   0 swapper/2
   5.25%  swapper 109  kworker/0:1H
   5.21%  kworker/0:1H  0 swapper/0
   2.14%  netctl-auto   0 swapper/2
   1.98%  netctl-auto   0 swapper/0
   1.98%  swapper6524Xephyr
   1.98%  swapper   27478   netctl-auto
   1.78%  transmission-gt   0 swapper/3
   1.53%  Xephyr0 swapper/0
   1.29%  netctl-auto   0 swapper/1
   1.29%  swapper   27476   netctl-auto
   1.21%  netctl-auto   0 swapper/3
   1.17%  swapper 233irq/33-iwlwifi
  ...

Note that pid 0 exists for each cpu so have comm of 'swapper/N'.

Also now it add a new 'trace' sort key to print whole trace output.
(The 'trace' sort key is the default key for tracepoint