lkml.org 
[lkml]   [2009]   [Apr]   [14]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: blktrace: event traces displayed wrong while ftrace blktrace is active
On Tue, Apr 14, 2009 at 06:03:39PM +0800, Li Zefan wrote:
> Theodore Ts'o wrote:
> > Hi Li,
> >
> > Thanks for working on the ftrace blktrace code; I was wondering if you
> > could take a look at something. While the nop or syscall tracer is
> > selected ("echo nop > /sys/kernel/debug/tracing/current_tracer"), the
> > event traces display like this:
> >
> > <...>-4491 [001] 9556.305696: jbd2_start_commit: dev dm-0:8 transaction 335442
> > <...>-4491 [001] 9556.305700: jbd2_commit_locking: dev dm-0:8 transaction 335442
> > <...>-4491 [001] 9556.305713: jbd2_commit_flushing: dev dm-0:8 transaction 335442
> > <...>-4491 [001] 9556.305720: jbd2_submit_inode_data: dev dm-0 transaction ino 3807454
> > <...>-4491 [001] 9556.305833: jbd2_commit_logging: dev dm-0:8 transaction 335442
> > <...>-4491 [000] 9556.307241: jbd2_end_commit: dev dm-0:8 transaction 335442 head 334303
> >
> > That is, the timestamp information what CPU, what pid, etc., is present.
> >
> > However, if the blk tracer is active, this information is missing:
> >
> > jbd2_start_commit: dev dm-0:8 transaction 333227
> > jbd2_commit_locking: dev dm-0:8 transaction 333227
> > jbd2_commit_flushing: dev dm-0:8 transaction 333227
> > jbd2_submit_inode_data: dev dm-0 transaction ino 1466869
> > jbd2_submit_inode_data: dev dm-0 transaction ino 1310793
> > jbd2_commit_logging: dev dm-0:8 transaction 333227
> > jbd2_end_commit: dev dm-0:8 transaction 333227 head 332814
> >
>
> The cause is:
>
> static void blk_tracer_start(struct trace_array *tr)
> {
> blk_tracer_enabled = true;
> trace_flags &= ~TRACE_ITER_CONTEXT_INFO; <--- !!
> }
>
> If TRACE_ITER_CONTEXT_INFO is set, 'comm-pid [cpu] ts' will be
> printed, and vise versa.
>
> The purpose to unset this flag is to make binary output can be
> parsed by blkparse.


Indeed. Note that you can overwrite this default by typing:

echo context-info > trace_option

after setting bkltrace as the current tracer.

Frederic.



>
> > The context information for the blktrace is present:
> >
> > rm-25433 [001] 9578.307485: 8,18 m N cfq25433 slice expired t=0
> > rm-25433 [001] 9578.307486: 8,18 m N cfq25433 put_queue
> > kjournald2-14059 [001] 9579.032457: 8,18 A W 5631242 + 8 <- (8,18) 3671312
> > kjournald2-14059 [001] 9579.032462: 8,18 Q W 5631242 + 8 [kjournald2]
> > kjournald2-14059 [001] 9579.032470: 8,18 G W 5631242 + 8 [kjournald2]
> >
> > It's just the context information for the event traces which are
> > missing.
> >
> > Anyway, if you could take a look at this, it would be much appreciated.
> > Usually I can interpolate the the timestamps from the surrounding
> > blktrace lines, but it would be nice if I didn't have to do that.
> >
>



\
 
 \ /
  Last update: 2009-04-14 23:29    [W:1.006 / U:0.076 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site