Re: [RFC] Implement simple messages in blktrace stream

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On Mon, May 26, 2008 at 07:05:25PM +0200, Jens Axboe wrote:
> On Mon, May 26 2008, Carl Henrik Lunde wrote:
> > On Fri, May 23, 2008 at 04:35:15PM -0400, Alan D. Brunelle wrote:
> > > The following two patches (kernel + application) would allow one to
> > > annotate parts of the blktrace stream w/ simple messages.
[...]
> > When I applied this patch to 2.6.26-rc3 and added a custom trace point
> > using a jprobe I got some weird results, look at the time column:
> > 
> >   8,0    3      510     5.418563704  8895  I   R 588881520 + 24 [grep]
> >   8,0    3      511     5.418564897  8895  D   R 588881520 + 24 [grep]
> >   8,0    3      512     5.418613507  8895  U   N [grep] 1
> >   8,0    3              6.554785394     0  m   N __cfq_slice_expired timed_out=1
> >   8,0    6      506     5.418733743     0  C   R 588881520 + 24 [0]
> >   8,0    6      507     5.418773493  8895  A   R 588868016 + 32 <- (8,5) 252127624
> >   8,0    6      508     5.418773668  8895  Q   R 588868016 + 32 [grep]
> >   8,0    6      509     5.418774478  8895  G   R 588868016 + 32 [grep]
> >   8,0    6      510     5.418775305  8895  P   N [grep]
> >   8,0    6      511     5.418775543  8895  I   R 588868016 + 32 [grep]
> >   8,0    6      512     5.418776783  8895  D   R 588868016 + 32 [grep]
> >   8,0    6              5.464497425     0  m   N __cfq_slice_expired timed_out=0
> >   8,0    6              5.887160843     0  m   N __cfq_slice_expired timed_out=1
> >   8,0    6              5.887165921     0  m   N __cfq_slice_expired timed_out=0
> >   8,0    6      513     5.418825167  8895  U   N [grep] 1
> >   8,0    5      498     5.418964604     0  C   R 588868016 + 32 [0]
> >   8,0    5      499     5.419000075  8895  A   R 588868048 + 24 <- (8,5) 252127656
> >   8,0    5      500     5.419000283  8895  Q   R 588868048 + 24 [grep]
> > 
> > Until now I haven't used anything newer than 2.6.24.7 and blktrace
> > ae6d30f447518, so the issue may come from some unrelated change or perhaps
> > even jprobes, I've never used them before...
> > 
> > I use mostly default configuration options except for HZ=1000.  I'll look
> > into it later this week.
> 
> Does it work if you add something like this to trace_note()? Will need
> to be refined as only the message calls really need to be sequenced, the
> other trace notes (like process and time do not matter).
> 
> diff --git a/block/blktrace.c b/block/blktrace.c
> index b2cbb4e..2824d11 100644
> --- a/block/blktrace.c
> +++ b/block/blktrace.c
> @@ -38,8 +38,10 @@ static void trace_note(struct blk_trace *bt, pid_t pid, int action,
>  	t = relay_reserve(bt->rchan, sizeof(*t) + len);
>  	if (t) {
>  		const int cpu = smp_processor_id();
> +		unsigned long *sequence = per_cpu_ptr(bt->sequence, cpu);
>  
>  		t->magic = BLK_IO_TRACE_MAGIC | BLK_IO_TRACE_VERSION;
> +		t->sequence = ++(*sequence);
>  		t->time = ktime_to_ns(ktime_get());
>  		t->device = bt->dev;
>  		t->action = action;
> 

That did not work, but this (on top of the original patch) does seem to work

diff --git a/blkparse.c b/blkparse.c
index 09a77f6..a34516e 100644
--- a/blkparse.c
+++ b/blkparse.c
@@ -597,11 +597,10 @@ static void handle_notify(struct blk_io_trace *bit)
 			memcpy(msg, (char *)payload, bit->pdu_len);
 			msg[bit->pdu_len] = '\0';
 
-			bit->time -= genesis_time;
 			fprintf(ofp,
 				"%3d,%-3d %2d %8s %5d.%09lu %5u %2s %3s %s\n",
 				MAJOR(bit->device), MINOR(bit->device),
-				bit->cpu, "", (int) SECONDS(bit->time),
+				bit->cpu, "0", (int) SECONDS(bit->time),
 				(unsigned long) NANO_SECONDS(bit->time),
 				0, "m", "N", msg);
 		}
@@ -1594,7 +1593,9 @@ static void dump_trace(struct blk_io_trace *t, struct per_cpu_info *pci,
 		       struct per_dev_info *pdi)
 {
 	if (text_output) {
-		if (t->action & BLK_TC_ACT(BLK_TC_PC))
+		if (t->action == BLK_TN_MESSAGE)
+			handle_notify(t);
+		else if (t->action & BLK_TC_ACT(BLK_TC_PC))
 			dump_trace_pc(t, pdi, pci);
 		else
 			dump_trace_fs(t, pdi, pci);
@@ -2193,7 +2194,7 @@ static int read_events(int fd, int always_block, int *fdblock)
 		/*
 		 * not a real trace, so grab and handle it here
 		 */
-		if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY)) {
+		if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && bit->action != BLK_TN_MESSAGE) {
 			handle_notify(bit);
 			output_binary(bit, sizeof(*bit) + bit->pdu_len);
 			continue;
@@ -2336,7 +2337,7 @@ static int ms_prime(struct ms_stream *msp)
 		if (verify_trace(bit))
 			goto err;
 
-		if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY)) {
+		if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && bit->action != BLK_TN_MESSAGE) {
 			handle_notify(bit);
 			output_binary(bit, sizeof(*bit) + bit->pdu_len);
 			bit_free(bit);

-- 
Carl Henrik
--
To unsubscribe from this list: send the line "unsubscribe linux-btrace" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html

[Index of Archives]     [Netdev]     [Linux Wireless]     [Kernel Newbies]     [Security]     [Linux for Hams]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux RAID]     [Linux Admin]     [Samba]

  Powered by Linux