linux-kernel - Re: blktrace: event traces displayed wrong while ftrace blktrace is active

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:	Tue, 14 Apr 2009 18:03:39 +0800
From:	Li Zefan <lizf@...fujitsu.com>
To:	"Theodore Ts'o" <tytso@....edu>
CC:	Jens Axboe <jens.axboe@...cle.com>,
	LKML <linux-kernel@...r.kernel.org>,
	Steven Rostedt <rostedt@...dmis.org>,
	Frederic Weisbecker <fweisbec@...il.com>,
	Arnaldo Carvalho de Melo <acme@...hat.com>
Subject: Re: blktrace: event traces displayed wrong while ftrace blktrace
 is active

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.

> 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.
> 

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