perf trace errors

perf trace errors

[Christoph Hellwig]

I get some rather interesting errors using perf trace with the block
tracepoints on current mainline, e.g.:

perf record -f -e 'block:block_bio_queue:record' -R -F 1 -a -s
<do some disk I/O end then ctrl+c>
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.237 MB perf.data (~10362 samples) ]

brick:/home/hch# perf trace
  Fatal: unknown op '-'
          xfssyncd-4232  [000]    87.798249255: block_bio_queue: 253,

There are lots of occurances of that exactly same warning in
builtin-trace.c, and the code sourrouning them is sufficiently enough
convoluted that I'm not able to track it down.

Re: perf trace errors

[Frederic Weisbecker]

On Sun, Oct 11, 2009 at 04:54:41AM +0200, Christoph Hellwig wrote:
> I get some rather interesting errors using perf trace with the block
> tracepoints on current mainline, e.g.:
> 
> perf record -f -e 'block:block_bio_queue:record' -R -F 1 -a -s
> <do some disk I/O end then ctrl+c>
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.237 MB perf.data (~10362 samples) ]
> 
> brick:/home/hch# perf trace
>   Fatal: unknown op '-'
>           xfssyncd-4232  [000]    87.798249255: block_bio_queue: 253,
> 
> There are lots of occurances of that exactly same warning in
> builtin-trace.c, and the code sourrouning them is sufficiently enough
> convoluted that I'm not able to track it down.


Yeah, there are still some trace events that are not well supported
in perf trace, for now... I'll fix that by the time.

Thanks.

Re: perf trace errors

[Christoph Hellwig]

On Sun, Oct 11, 2009 at 02:19:28PM +0200, Frederic Weisbecker wrote:
> Yeah, there are still some trace events that are not well supported
> in perf trace, for now... I'll fix that by the time.

Any idea what is the missing part?  I tried to understand the code but
I haven't even managed to grasp the data structures yet.

The weird thing is that these message seem to come from parsing of
the filters, and a simple trace the whole system trace shouldn't
really have to set any filters anyway, nor should the filters depdend
on what trace point you use.

Note that the in addition to all the block trace points also all my
new xfs tracepoints also give errors from perf trace.  Things tend
to work quite nicely with the ASCII output from the kernel.

Re: perf trace errors

[Frederic Weisbecker]

On Sun, Oct 11, 2009 at 02:40:30PM +0200, Christoph Hellwig wrote:
> On Sun, Oct 11, 2009 at 02:19:28PM +0200, Frederic Weisbecker wrote:
> > Yeah, there are still some trace events that are not well supported
> > in perf trace, for now... I'll fix that by the time.
> 
> Any idea what is the missing part?  I tried to understand the code but
> I haven't even managed to grasp the data structures yet.
> 
> The weird thing is that these message seem to come from parsing of
> the filters, and a simple trace the whole system trace shouldn't
> really have to set any filters anyway, nor should the filters depdend
> on what trace point you use.
> 
> Note that the in addition to all the block trace points also all my
> new xfs tracepoints also give errors from perf trace.  Things tend
> to work quite nicely with the ASCII output from the kernel.
> 


It's about the trace event format file parsing, especially the format
line:

print fmt: "%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) 
- 1))), REC->rwbs, (unsigned long long)REC->sector, REC->nr_sector, REC->comm

This is done from tools/perf/util/trace-event-parse.c

It is supposed to handle such cases already, not sure exactly where is
the problem currently, that needs some investigation.

Re: perf trace errors

[Ingo Molnar]

* Christoph Hellwig <hch@lst.de> wrote:

> I get some rather interesting errors using perf trace with the block
> tracepoints on current mainline, e.g.:
> 
> perf record -f -e 'block:block_bio_queue:record' -R -F 1 -a -s
> <do some disk I/O end then ctrl+c>
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.237 MB perf.data (~10362 samples) ]
> 
> brick:/home/hch# perf trace
>   Fatal: unknown op '-'
>           xfssyncd-4232  [000]    87.798249255: block_bio_queue: 253,
> 
> There are lots of occurances of that exactly same warning in 
> builtin-trace.c, and the code sourrouning them is sufficiently enough 
> convoluted that I'm not able to track it down.

FYI, these bugs are fixed in latest -tip, your testcase works for me:

aldebaran:~/linux/linux/tools/perf> perf record -f -e 'block:block_bio_queue:record' -R -F 1 -a -s
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.027 MB perf.data (~1168 samples) ]

aldebaran:~/linux/linux/tools/perf> perf trace
       kjournald-1406  [000] 10900.853086: block_bio_queue: 8,0 W 68735 + 8 [kjournald]
       kjournald-1406  [000] 10900.853097: block_bio_queue: 8,0 W 68743 + 8 [kjournald]
       kjournald-1406  [000] 10900.853100: block_bio_queue: 8,0 W 68751 + 8 [kjournald]
       kjournald-1406  [000] 10900.853103: block_bio_queue: 8,0 W 68759 + 8 [kjournald]
       flush-8:0-20110 [007] 10900.853117: block_bio_queue: 8,0 W 64487535 + 8 [flush-8:0]
       flush-8:0-20110 [007] 10900.853129: block_bio_queue: 8,0 W 64487551 + 8 [flush-8:0]
       flush-8:0-20110 [007] 10900.853138: block_bio_queue: 8,0 W 64487559 + 8 [flush-8:0]
       flush-8:0-20110 [007] 10900.853149: block_bio_queue: 8,0 W 64700511 + 8 [flush-8:0]
            sync-16876 [008] 10900.851948: block_bio_queue: 8,0 R 3218919 + 40 [sync]
            sync-16876 [008] 10900.853062: block_bio_queue: 8,0 W 63 + 8 [sync]
            sync-16876 [008] 10900.853067: block_bio_queue: 8,0 W 71 + 8 [sync]
            sync-16876 [008] 10900.853071: block_bio_queue: 8,0 W 79 + 8 [sync]
            sync-16876 [008] 10900.853077: block_bio_queue: 8,0 W 15466559 + 8 [sync]
            sync-16876 [011] 10900.840473: block_bio_queue: 8,0 R 3218887 + 32 [bash]

Mind checking whether it works for you?

Thanks,

	Ingo

Re: perf trace errors

[Christoph Hellwig]

On Fri, Oct 16, 2009 at 10:32:42AM +0200, Ingo Molnar wrote:
> FYI, these bugs are fixed in latest -tip, your testcase works for me:

> Mind checking whether it works for you?

Yes, it works on -tip, but not yet on mainline.  What still doesn't
work yet on -tip either is printing of dynamic strings in some events,
e.g.:

       kjournald-1105  [000]   643.002702: block_rq_complete: 253,0 W () 2283224

Re: perf trace errors

[Frederic Weisbecker]

2009/10/25 Christoph Hellwig <hch@lst.de>:
> On Fri, Oct 16, 2009 at 10:32:42AM +0200, Ingo Molnar wrote:
>> FYI, these bugs are fixed in latest -tip, your testcase works for me:
>
>> Mind checking whether it works for you?
>
> Yes, it works on -tip, but not yet on mainline.  What still doesn't
> work yet on -tip either is printing of dynamic strings in some events,
> e.g.:
>
>       kjournald-1105  [000]   643.002702: block_rq_complete: 253,0 W () 2283224


Ah, interesting, it means we support __string() but not well other
dynamic arrays.
I'll have a look at it.

Thanks.

Re: perf trace errors

[Steven Rostedt]

On Mon, 2009-10-26 at 00:43 +0100, Frederic Weisbecker wrote:
> 2009/10/25 Christoph Hellwig <hch@lst.de>:
> > On Fri, Oct 16, 2009 at 10:32:42AM +0200, Ingo Molnar wrote:
> >> FYI, these bugs are fixed in latest -tip, your testcase works for me:
> >
> >> Mind checking whether it works for you?
> >
> > Yes, it works on -tip, but not yet on mainline.  What still doesn't
> > work yet on -tip either is printing of dynamic strings in some events,
> > e.g.:
> >
> >       kjournald-1105  [000]   643.002702: block_rq_complete: 253,0 W () 2283224
> 
> 
> Ah, interesting, it means we support __string() but not well other
> dynamic arrays.
> I'll have a look at it.

Frederic,

Have you found anything with this yet? If not, I can take a look too.

-- Steve

Re: perf trace errors

[Frederic Weisbecker]

On Thu, Oct 29, 2009 at 05:24:49PM -0400, Steven Rostedt wrote:
> On Mon, 2009-10-26 at 00:43 +0100, Frederic Weisbecker wrote:
> > 2009/10/25 Christoph Hellwig <hch@lst.de>:
> > > On Fri, Oct 16, 2009 at 10:32:42AM +0200, Ingo Molnar wrote:
> > >> FYI, these bugs are fixed in latest -tip, your testcase works for me:
> > >
> > >> Mind checking whether it works for you?
> > >
> > > Yes, it works on -tip, but not yet on mainline.  What still doesn't
> > > work yet on -tip either is printing of dynamic strings in some events,
> > > e.g.:
> > >
> > >       kjournald-1105  [000]   643.002702: block_rq_complete: 253,0 W () 2283224
> > 
> > 
> > Ah, interesting, it means we support __string() but not well other
> > dynamic arrays.
> > I'll have a look at it.
> 
> Frederic,
> 
> Have you found anything with this yet? If not, I can take a look too.
> 


I haven't yet checked actually, I was out of my box this week.
But if you still have some time to check that too, then yeah,
it would be nice :)

Thanks.