Messages in this thread | | | Date | Tue, 14 Apr 2009 23:25:33 +0200 | From | Frederic Weisbecker <> | Subject | Re: 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. > > >
| |