[PATCH 1/2] blktrace: fix output of unknown events

[PATCH 1/2] blktrace: fix output of unknown events

[Li Zefan]

Not all events are pc (packet command) events. An event is a pc
event only if it has BLK_TC_PC bit set.

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
---
 kernel/trace/blktrace.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
index 947c5b3..464a6e5 100644
--- a/kernel/trace/blktrace.c
+++ b/kernel/trace/blktrace.c
@@ -1181,7 +1181,7 @@ static enum print_line_t print_one_line(struct trace_iterator *iter,
 	}
 
 	if (unlikely(what == 0 || what >= ARRAY_SIZE(what2act)))
-		ret = trace_seq_printf(s, "Bad pc action %x\n", what);
+		ret = trace_seq_printf(s, "Unknown action %x\n", what);
 	else {
 		ret = log_action(iter, what2act[what].act[long_act]);
 		if (ret)
-- 
1.5.4.rc3

[PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Li Zefan]

BLK_TC_PC events should be treated differently with BLK_TC_FS events.

Before this patch:

 # echo 1 > /sys/block/sda/sda1/trace/enable
 # echo pc > /sys/block/sda/sda1/trace/act_mask
 # echo blk > /debugfs/tracing/current_tracer
 # (generate some BLK_TC_PC events)
 # cat trace
        bash-2184  [000]  1774.275413:   8,7    I   N [bash]
        bash-2184  [000]  1774.275435:   8,7    D   N [bash]
        bash-2184  [000]  1774.275540:   8,7    I   R [bash]
        bash-2184  [000]  1774.275547:   8,7    D   R [bash]
 ksoftirqd/0-4     [000]  1774.275580:   8,7    C   N 0 [0]
        bash-2184  [000]  1774.275648:   8,7    I   R [bash]
        bash-2184  [000]  1774.275653:   8,7    D   R [bash]
 ksoftirqd/0-4     [000]  1774.275682:   8,7    C   N 0 [0]
        bash-2184  [000]  1774.275739:   8,7    I   R [bash]
        bash-2184  [000]  1774.275744:   8,7    D   R [bash]
 ksoftirqd/0-4     [000]  1774.275771:   8,7    C   N 0 [0]
        bash-2184  [000]  1774.275804:   8,7    I   R [bash]
        bash-2184  [000]  1774.275808:   8,7    D   R [bash]
 ksoftirqd/0-4     [000]  1774.275836:   8,7    C   N 0 [0]

After this patch:

 # cat trace
        bash-2263  [000]   366.782149:   8,7    I   N 0 (00 ..) [bash]
        bash-2263  [000]   366.782323:   8,7    D   N 0 (00 ..) [bash]
        bash-2263  [000]   366.782557:   8,7    I   R 8 (25 00 ..) [bash]
        bash-2263  [000]   366.782560:   8,7    D   R 8 (25 00 ..) [bash]
 ksoftirqd/0-4     [000]   366.782582:   8,7    C   N (25 00 ..) [0]
        bash-2263  [000]   366.782648:   8,7    I   R 8 (5a 00 3f 00) [bash]
        bash-2263  [000]   366.782650:   8,7    D   R 8 (5a 00 3f 00) [bash]
 ksoftirqd/0-4     [000]   366.782669:   8,7    C   N (5a 00 3f 00) [0]
        bash-2263  [000]   366.782710:   8,7    I   R 8 (5a 00 08 00) [bash]
        bash-2263  [000]   366.782713:   8,7    D   R 8 (5a 00 08 00) [bash]
 ksoftirqd/0-4     [000]   366.782730:   8,7    C   N (5a 00 08 00) [0]
        bash-2263  [000]   366.783375:   8,7    I   R 36 (5a 00 08 00) [bash]
        bash-2263  [000]   366.783379:   8,7    D   R 36 (5a 00 08 00) [bash]
 ksoftirqd/0-4     [000]   366.783404:   8,7    C   N (5a 00 08 00) [0]

This is what we do with PC events in user-space blktrace.

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
---
 kernel/trace/blktrace.c |   88 ++++++++++++++++++++++++++++++++++++++++++----
 1 files changed, 80 insertions(+), 8 deletions(-)

diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
index 464a6e5..fd1ff49 100644
--- a/kernel/trace/blktrace.c
+++ b/kernel/trace/blktrace.c
@@ -970,6 +970,16 @@ static inline const void *pdu_start(const struct trace_entry *ent)
 	return te_blk_io_trace(ent) + 1;
 }
 
+static inline u32 t_action(const struct trace_entry *ent)
+{
+	return te_blk_io_trace(ent)->action;
+}
+
+static inline u32 t_bytes(const struct trace_entry *ent)
+{
+	return te_blk_io_trace(ent)->bytes;
+}
+
 static inline u32 t_sec(const struct trace_entry *ent)
 {
 	return te_blk_io_trace(ent)->bytes >> 9;
@@ -1030,25 +1040,87 @@ static int blk_log_action(struct trace_iterator *iter, const char *act)
 				MAJOR(t->device), MINOR(t->device), act, rwbs);
 }
 
+static int blk_log_dump_pdu(struct trace_seq *s, const struct trace_entry *ent)
+{
+	const char *pdu_buf;
+	int pdu_len;
+	int i, end, ret;
+
+	pdu_buf = pdu_start(ent);
+	pdu_len = te_blk_io_trace(ent)->pdu_len;
+
+	if (!pdu_len)
+		return 1;
+
+	/* find the last zero that needs to be printed */
+	for (end = pdu_len - 1; end >= 0; end--)
+		if (pdu_buf[end])
+			break;
+	end++;
+
+	if (!trace_seq_putc(s, '('))
+		return 0;
+
+	for (i = 0; i < pdu_len; i++) {
+
+		ret = trace_seq_printf(s, "%s%02x",
+				       i == 0 ? "" : " ", pdu_buf[i]);
+		if (!ret)
+			return ret;
+
+		/*
+		 * stop when the rest is just zeroes and indicate so
+		 * with a ".." appended
+		 */
+		if (i == end && end != pdu_len - 1)
+			return trace_seq_puts(s, " ..) ");
+	}
+
+	return trace_seq_puts(s, ") ");
+}
+
 static int blk_log_generic(struct trace_seq *s, const struct trace_entry *ent)
 {
 	char cmd[TASK_COMM_LEN];
 
 	trace_find_cmdline(ent->pid, cmd);
 
-	if (t_sec(ent))
-		return trace_seq_printf(s, "%llu + %u [%s]\n",
-					t_sector(ent), t_sec(ent), cmd);
-	return trace_seq_printf(s, "[%s]\n", cmd);
+	if (t_action(ent) & BLK_TC_ACT(BLK_TC_PC)) {
+		int ret;
+
+		ret = trace_seq_printf(s, "%u ", t_bytes(ent));
+		if (!ret)
+			return 0;
+		ret = blk_log_dump_pdu(s, ent);
+		if (!ret)
+			return 0;
+		return trace_seq_printf(s, "[%s]\n", cmd);
+	} else {
+		if (t_sec(ent))
+			return trace_seq_printf(s, "%llu + %u [%s]\n",
+						t_sector(ent), t_sec(ent), cmd);
+		return trace_seq_printf(s, "[%s]\n", cmd);
+	}
 }
 
 static int blk_log_with_error(struct trace_seq *s,
 			      const struct trace_entry *ent)
 {
-	if (t_sec(ent))
-		return trace_seq_printf(s, "%llu + %u [%d]\n", t_sector(ent),
-					t_sec(ent), t_error(ent));
-	return trace_seq_printf(s, "%llu [%d]\n", t_sector(ent), t_error(ent));
+	if (t_action(ent) & BLK_TC_ACT(BLK_TC_PC)) {
+		int ret;
+
+		ret = blk_log_dump_pdu(s, ent);
+		if (ret)
+			return trace_seq_printf(s, "[%d]\n", t_error(ent));
+		return 0;
+	} else {
+		if (t_sec(ent))
+			return trace_seq_printf(s, "%llu + %u [%d]\n",
+						t_sector(ent),
+						t_sec(ent), t_error(ent));
+		return trace_seq_printf(s, "%llu [%d]\n",
+					t_sector(ent), t_error(ent));
+	}
 }
 
 static int blk_log_remap(struct trace_seq *s, const struct trace_entry *ent)
-- 
1.5.4.rc3

Re: [PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Ingo Molnar]

* Li Zefan <lizf@cn.fujitsu.com> wrote:

> BLK_TC_PC events should be treated differently with BLK_TC_FS events.
> 
> Before this patch:
> 
>  # echo 1 > /sys/block/sda/sda1/trace/enable
>  # echo pc > /sys/block/sda/sda1/trace/act_mask
>  # echo blk > /debugfs/tracing/current_tracer
>  # (generate some BLK_TC_PC events)
>  # cat trace
>         bash-2184  [000]  1774.275413:   8,7    I   N [bash]
>         bash-2184  [000]  1774.275435:   8,7    D   N [bash]
>         bash-2184  [000]  1774.275540:   8,7    I   R [bash]
>         bash-2184  [000]  1774.275547:   8,7    D   R [bash]
>  ksoftirqd/0-4     [000]  1774.275580:   8,7    C   N 0 [0]
>         bash-2184  [000]  1774.275648:   8,7    I   R [bash]
>         bash-2184  [000]  1774.275653:   8,7    D   R [bash]
>  ksoftirqd/0-4     [000]  1774.275682:   8,7    C   N 0 [0]
>         bash-2184  [000]  1774.275739:   8,7    I   R [bash]
>         bash-2184  [000]  1774.275744:   8,7    D   R [bash]
>  ksoftirqd/0-4     [000]  1774.275771:   8,7    C   N 0 [0]
>         bash-2184  [000]  1774.275804:   8,7    I   R [bash]
>         bash-2184  [000]  1774.275808:   8,7    D   R [bash]
>  ksoftirqd/0-4     [000]  1774.275836:   8,7    C   N 0 [0]
> 
> After this patch:
> 
>  # cat trace
>         bash-2263  [000]   366.782149:   8,7    I   N 0 (00 ..) [bash]
>         bash-2263  [000]   366.782323:   8,7    D   N 0 (00 ..) [bash]
>         bash-2263  [000]   366.782557:   8,7    I   R 8 (25 00 ..) [bash]
>         bash-2263  [000]   366.782560:   8,7    D   R 8 (25 00 ..) [bash]
>  ksoftirqd/0-4     [000]   366.782582:   8,7    C   N (25 00 ..) [0]
>         bash-2263  [000]   366.782648:   8,7    I   R 8 (5a 00 3f 00) [bash]
>         bash-2263  [000]   366.782650:   8,7    D   R 8 (5a 00 3f 00) [bash]
>  ksoftirqd/0-4     [000]   366.782669:   8,7    C   N (5a 00 3f 00) [0]
>         bash-2263  [000]   366.782710:   8,7    I   R 8 (5a 00 08 00) [bash]
>         bash-2263  [000]   366.782713:   8,7    D   R 8 (5a 00 08 00) [bash]
>  ksoftirqd/0-4     [000]   366.782730:   8,7    C   N (5a 00 08 00) [0]
>         bash-2263  [000]   366.783375:   8,7    I   R 36 (5a 00 08 00) [bash]
>         bash-2263  [000]   366.783379:   8,7    D   R 36 (5a 00 08 00) [bash]
>  ksoftirqd/0-4     [000]   366.783404:   8,7    C   N (5a 00 08 00) [0]
> 
> This is what we do with PC events in user-space blktrace.
> 
> Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
> ---
>  kernel/trace/blktrace.c |   88 ++++++++++++++++++++++++++++++++++++++++++----
>  1 files changed, 80 insertions(+), 8 deletions(-)
> 
> diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
> index 464a6e5..fd1ff49 100644
> --- a/kernel/trace/blktrace.c
> +++ b/kernel/trace/blktrace.c
> @@ -970,6 +970,16 @@ static inline const void *pdu_start(const struct trace_entry *ent)
>  	return te_blk_io_trace(ent) + 1;
>  }
>  
> +static inline u32 t_action(const struct trace_entry *ent)
> +{
> +	return te_blk_io_trace(ent)->action;
> +}
> +
> +static inline u32 t_bytes(const struct trace_entry *ent)
> +{
> +	return te_blk_io_trace(ent)->bytes;
> +}
> +
>  static inline u32 t_sec(const struct trace_entry *ent)
>  {
>  	return te_blk_io_trace(ent)->bytes >> 9;
> @@ -1030,25 +1040,87 @@ static int blk_log_action(struct trace_iterator *iter, const char *act)
>  				MAJOR(t->device), MINOR(t->device), act, rwbs);
>  }
>  
> +static int blk_log_dump_pdu(struct trace_seq *s, const struct trace_entry *ent)
> +{
> +	const char *pdu_buf;
> +	int pdu_len;
> +	int i, end, ret;
> +
> +	pdu_buf = pdu_start(ent);
> +	pdu_len = te_blk_io_trace(ent)->pdu_len;
> +
> +	if (!pdu_len)
> +		return 1;
> +
> +	/* find the last zero that needs to be printed */
> +	for (end = pdu_len - 1; end >= 0; end--)
> +		if (pdu_buf[end])
> +			break;
> +	end++;
> +
> +	if (!trace_seq_putc(s, '('))
> +		return 0;
> +
> +	for (i = 0; i < pdu_len; i++) {
> +
> +		ret = trace_seq_printf(s, "%s%02x",
> +				       i == 0 ? "" : " ", pdu_buf[i]);
> +		if (!ret)
> +			return ret;
> +
> +		/*
> +		 * stop when the rest is just zeroes and indicate so
> +		 * with a ".." appended
> +		 */
> +		if (i == end && end != pdu_len - 1)
> +			return trace_seq_puts(s, " ..) ");
> +	}
> +
> +	return trace_seq_puts(s, ") ");
> +}
> +
>  static int blk_log_generic(struct trace_seq *s, const struct trace_entry *ent)
>  {
>  	char cmd[TASK_COMM_LEN];
>  
>  	trace_find_cmdline(ent->pid, cmd);
>  
> -	if (t_sec(ent))
> -		return trace_seq_printf(s, "%llu + %u [%s]\n",
> -					t_sector(ent), t_sec(ent), cmd);
> -	return trace_seq_printf(s, "[%s]\n", cmd);
> +	if (t_action(ent) & BLK_TC_ACT(BLK_TC_PC)) {
> +		int ret;
> +
> +		ret = trace_seq_printf(s, "%u ", t_bytes(ent));
> +		if (!ret)
> +			return 0;
> +		ret = blk_log_dump_pdu(s, ent);
> +		if (!ret)
> +			return 0;
> +		return trace_seq_printf(s, "[%s]\n", cmd);
> +	} else {
> +		if (t_sec(ent))
> +			return trace_seq_printf(s, "%llu + %u [%s]\n",
> +						t_sector(ent), t_sec(ent), cmd);
> +		return trace_seq_printf(s, "[%s]\n", cmd);
> +	}
>  }
>  
>  static int blk_log_with_error(struct trace_seq *s,
>  			      const struct trace_entry *ent)
>  {
> -	if (t_sec(ent))
> -		return trace_seq_printf(s, "%llu + %u [%d]\n", t_sector(ent),
> -					t_sec(ent), t_error(ent));
> -	return trace_seq_printf(s, "%llu [%d]\n", t_sector(ent), t_error(ent));
> +	if (t_action(ent) & BLK_TC_ACT(BLK_TC_PC)) {
> +		int ret;
> +
> +		ret = blk_log_dump_pdu(s, ent);
> +		if (ret)
> +			return trace_seq_printf(s, "[%d]\n", t_error(ent));
> +		return 0;
> +	} else {
> +		if (t_sec(ent))
> +			return trace_seq_printf(s, "%llu + %u [%d]\n",
> +						t_sector(ent),
> +						t_sec(ent), t_error(ent));
> +		return trace_seq_printf(s, "%llu [%d]\n",
> +					t_sector(ent), t_error(ent));
> +	}
>  }
>  
>  static int blk_log_remap(struct trace_seq *s, const struct trace_entry *ent)

Neat shortcut - packet command requests can be quite large in 
special cases, right?

Sidenote. Right now we reserve the full packet length in the trace 
buffer, then copy the full packet into the trace buffer:

                if (pdu_len)
                        memcpy((void *) t + sizeof(*t), pdu_data, pdu_len);

... just to scan it a second time during output and discard much of 
it later on if it has a lot of trailing zeroes.

It might make sense to pre-compress: by extending the trace record 
format with a trailing-zeroes field.

But that would make it more complex and key to tracers is simplicity 
of data acquisition.

Dunno, probably not worth it, except if data stream bloat becomes a 
real issue (which i'd not expect them to become in this case).

Anyway - Jens, the two patches look good to me, do they look fine to 
you too?

	Ingo

Re: [PATCH 1/2] blktrace: fix output of unknown events

[Arnaldo Carvalho de Melo]

Em Wed, Apr 01, 2009 at 04:18:53PM +0800, Li Zefan escreveu:
> Not all events are pc (packet command) events. An event is a pc
> event only if it has BLK_TC_PC bit set.
> 
> Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
> ---
>  kernel/trace/blktrace.c |    2 +-
>  1 files changed, 1 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
> index 947c5b3..464a6e5 100644
> --- a/kernel/trace/blktrace.c
> +++ b/kernel/trace/blktrace.c
> @@ -1181,7 +1181,7 @@ static enum print_line_t print_one_line(struct trace_iterator *iter,
>  	}
>  
>  	if (unlikely(what == 0 || what >= ARRAY_SIZE(what2act)))
> -		ret = trace_seq_printf(s, "Bad pc action %x\n", what);
> +		ret = trace_seq_printf(s, "Unknown action %x\n", what);
>  	else {
>  		ret = log_action(iter, what2act[what].act[long_act]);
>  		if (ret)

Looks ok,

Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>

Re: [PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Arnaldo Carvalho de Melo]

Em Wed, Apr 01, 2009 at 01:00:16PM +0200, Ingo Molnar escreveu:
> 
> * Li Zefan <lizf@cn.fujitsu.com> wrote:
> 
> > +	} else {
> > +		if (t_sec(ent))
> > +			return trace_seq_printf(s, "%llu + %u [%d]\n",
> > +						t_sector(ent),
> > +						t_sec(ent), t_error(ent));
> > +		return trace_seq_printf(s, "%llu [%d]\n",
> > +					t_sector(ent), t_error(ent));
> > +	}
> >  }
> >  
> >  static int blk_log_remap(struct trace_seq *s, const struct trace_entry *ent)
> 
> Neat shortcut - packet command requests can be quite large in 
> special cases, right?
> 
> Sidenote. Right now we reserve the full packet length in the trace 
> buffer, then copy the full packet into the trace buffer:
> 
>                 if (pdu_len)
>                         memcpy((void *) t + sizeof(*t), pdu_data, pdu_len);
> 
> ... just to scan it a second time during output and discard much of 
> it later on if it has a lot of trailing zeroes.
> 
> It might make sense to pre-compress: by extending the trace record 
> format with a trailing-zeroes field.

You mean something like asking, at tracer registration time to do this
kind of compression and have it done on the core tracing code? Looks
worthy if we can find a second tracer that would benefit from the space
savings at the cost of using more CPU at each event.

But perhaps providing a "memcpy" replacement to be used in such things
and leaving this to the user to decide, i.e. it may be interesting in
certain scenarios to be able to do:

echo 1 > /sys/kernel/debug/tracing/options/compress

And have the payload compressed.
 
> But that would make it more complex and key to tracers is simplicity 
> of data acquisition.
> 
> Dunno, probably not worth it, except if data stream bloat becomes a 
> real issue (which i'd not expect them to become in this case).
> 
> Anyway - Jens, the two patches look good to me, do they look fine to 
> you too?

To me too,

Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>

to this one too.

- Arnaldo

Re: [PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Li Zefan]

Hi Ingo,

I would like to ask what's the status of these 2 patches.

Arnaldo acked on them.

Li Zefan wrote:
> BLK_TC_PC events should be treated differently with BLK_TC_FS events.
> 
> Before this patch:
> 
>  # echo 1 > /sys/block/sda/sda1/trace/enable
>  # echo pc > /sys/block/sda/sda1/trace/act_mask
>  # echo blk > /debugfs/tracing/current_tracer
>  # (generate some BLK_TC_PC events)
>  # cat trace
>         bash-2184  [000]  1774.275413:   8,7    I   N [bash]
>         bash-2184  [000]  1774.275435:   8,7    D   N [bash]
>         bash-2184  [000]  1774.275540:   8,7    I   R [bash]
>         bash-2184  [000]  1774.275547:   8,7    D   R [bash]
>  ksoftirqd/0-4     [000]  1774.275580:   8,7    C   N 0 [0]
>         bash-2184  [000]  1774.275648:   8,7    I   R [bash]
>         bash-2184  [000]  1774.275653:   8,7    D   R [bash]
>  ksoftirqd/0-4     [000]  1774.275682:   8,7    C   N 0 [0]
>         bash-2184  [000]  1774.275739:   8,7    I   R [bash]
>         bash-2184  [000]  1774.275744:   8,7    D   R [bash]
>  ksoftirqd/0-4     [000]  1774.275771:   8,7    C   N 0 [0]
>         bash-2184  [000]  1774.275804:   8,7    I   R [bash]
>         bash-2184  [000]  1774.275808:   8,7    D   R [bash]
>  ksoftirqd/0-4     [000]  1774.275836:   8,7    C   N 0 [0]
> 
> After this patch:
> 
>  # cat trace
>         bash-2263  [000]   366.782149:   8,7    I   N 0 (00 ..) [bash]
>         bash-2263  [000]   366.782323:   8,7    D   N 0 (00 ..) [bash]
>         bash-2263  [000]   366.782557:   8,7    I   R 8 (25 00 ..) [bash]
>         bash-2263  [000]   366.782560:   8,7    D   R 8 (25 00 ..) [bash]
>  ksoftirqd/0-4     [000]   366.782582:   8,7    C   N (25 00 ..) [0]
>         bash-2263  [000]   366.782648:   8,7    I   R 8 (5a 00 3f 00) [bash]
>         bash-2263  [000]   366.782650:   8,7    D   R 8 (5a 00 3f 00) [bash]
>  ksoftirqd/0-4     [000]   366.782669:   8,7    C   N (5a 00 3f 00) [0]
>         bash-2263  [000]   366.782710:   8,7    I   R 8 (5a 00 08 00) [bash]
>         bash-2263  [000]   366.782713:   8,7    D   R 8 (5a 00 08 00) [bash]
>  ksoftirqd/0-4     [000]   366.782730:   8,7    C   N (5a 00 08 00) [0]
>         bash-2263  [000]   366.783375:   8,7    I   R 36 (5a 00 08 00) [bash]
>         bash-2263  [000]   366.783379:   8,7    D   R 36 (5a 00 08 00) [bash]
>  ksoftirqd/0-4     [000]   366.783404:   8,7    C   N (5a 00 08 00) [0]
> 
> This is what we do with PC events in user-space blktrace.
> 
> Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
> ---

Re: [PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Ingo Molnar]

* Li Zefan <lizf@cn.fujitsu.com> wrote:

> Hi Ingo,
> 
> I would like to ask what's the status of these 2 patches.
> 
> Arnaldo acked on them.

They looked good to me - but i'm waiting for an Ack from Jens. Jens 
has complained about seeing un-ack-ed patches in the blktrace code, 
so i've started serializing any new patches on acks from Jens. The 
workflow would be more efficient i suspect if Jens 
nominated/declared you and Arnaldo as blktrace co-maintainers too - 
most of the patches come from you two.

	Ingo

Re: [PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Jens Axboe]

On Sun, Apr 12 2009, Ingo Molnar wrote:
> 
> * Li Zefan <lizf@cn.fujitsu.com> wrote:
> 
> > Hi Ingo,
> > 
> > I would like to ask what's the status of these 2 patches.
> > 
> > Arnaldo acked on them.
> 
> They looked good to me - but i'm waiting for an Ack from Jens. Jens 
> has complained about seeing un-ack-ed patches in the blktrace code, 
> so i've started serializing any new patches on acks from Jens. The 
> workflow would be more efficient i suspect if Jens 
> nominated/declared you and Arnaldo as blktrace co-maintainers too - 
> most of the patches come from you two.

I'd be fine with listing Li Zefan as co-maintainer of the blktrace bits.
He knows what he is doing and is also a user of blktrace, so I think he
would be fine. Li, what do you think?

-- 
Jens Axboe

Re: [PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Ingo Molnar]

* Jens Axboe <jens.axboe@oracle.com> wrote:

> On Sun, Apr 12 2009, Ingo Molnar wrote:
> > 
> > * Li Zefan <lizf@cn.fujitsu.com> wrote:
> > 
> > > Hi Ingo,
> > > 
> > > I would like to ask what's the status of these 2 patches.
> > > 
> > > Arnaldo acked on them.
> > 
> > They looked good to me - but i'm waiting for an Ack from Jens. Jens 
> > has complained about seeing un-ack-ed patches in the blktrace code, 
> > so i've started serializing any new patches on acks from Jens. The 
> > workflow would be more efficient i suspect if Jens 
> > nominated/declared you and Arnaldo as blktrace co-maintainers too - 
> > most of the patches come from you two.
> 
> I'd be fine with listing Li Zefan as co-maintainer of the blktrace 
> bits. He knows what he is doing and is also a user of blktrace, so 
> I think he would be fine. Li, what do you think?

Cool ... i've also taken this as an implicit approval from you of Li 
sending blktrace patches so i have queued the two up.

The next big (and nice!) step would be the blktrace events in 
TRACE_EVENT() style. That would integrate the blktrace tracepoints 
with all the others, in one coherent framework.

Thanks,

	Ingo

Re: [PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Li Zefan]

Jens Axboe wrote:
> On Sun, Apr 12 2009, Ingo Molnar wrote:
>> * Li Zefan <lizf@cn.fujitsu.com> wrote:
>>
>>> Hi Ingo,
>>>
>>> I would like to ask what's the status of these 2 patches.
>>>
>>> Arnaldo acked on them.
>> They looked good to me - but i'm waiting for an Ack from Jens. Jens 
>> has complained about seeing un-ack-ed patches in the blktrace code, 
>> so i've started serializing any new patches on acks from Jens. The 
>> workflow would be more efficient i suspect if Jens 
>> nominated/declared you and Arnaldo as blktrace co-maintainers too - 
>> most of the patches come from you two.
> 
> I'd be fine with listing Li Zefan as co-maintainer of the blktrace bits.
> He knows what he is doing and is also a user of blktrace, so I think he
> would be fine. Li, what do you think?
> 

Thanks. It's fine for me too.

--
Zefan

Re: [PATCH 2/2] blktrace: fix output of BLK_TC_PC events

[Li Zefan]

Ingo Molnar wrote:
> * Jens Axboe <jens.axboe@oracle.com> wrote:
> 
>> On Sun, Apr 12 2009, Ingo Molnar wrote:
>>> * Li Zefan <lizf@cn.fujitsu.com> wrote:
>>>
>>>> Hi Ingo,
>>>>
>>>> I would like to ask what's the status of these 2 patches.
>>>>
>>>> Arnaldo acked on them.
>>> They looked good to me - but i'm waiting for an Ack from Jens. Jens 
>>> has complained about seeing un-ack-ed patches in the blktrace code, 
>>> so i've started serializing any new patches on acks from Jens. The 
>>> workflow would be more efficient i suspect if Jens 
>>> nominated/declared you and Arnaldo as blktrace co-maintainers too - 
>>> most of the patches come from you two.
>> I'd be fine with listing Li Zefan as co-maintainer of the blktrace 
>> bits. He knows what he is doing and is also a user of blktrace, so 
>> I think he would be fine. Li, what do you think?
> 
> Cool ... i've also taken this as an implicit approval from you of Li 
> sending blktrace patches so i have queued the two up.
> 

Thanks!

> The next big (and nice!) step would be the blktrace events in 
> TRACE_EVENT() style. That would integrate the blktrace tracepoints 
> with all the others, in one coherent framework.
> 

As I mentioned in another mail thread, this is what we are planning
to do. :)

--
Zefan

[tip:tracing/core] blktrace: fix output of unknown events

[tip-bot for Li Zefan]

Commit-ID:  b78825d608f30a47e3154ab6872a03f0de0c9d45
Gitweb:     http://git.kernel.org/tip/b78825d608f30a47e3154ab6872a03f0de0c9d45
Author:     Li Zefan <lizf@cn.fujitsu.com>
AuthorDate: Wed, 1 Apr 2009 16:18:53 +0800
Committer:  Ingo Molnar <mingo@elte.hu>
CommitDate: Sun, 12 Apr 2009 15:32:45 +0200

blktrace: fix output of unknown events

Not all events are pc (packet command) events. An event is a pc
event only if it has BLK_TC_PC bit set.

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jens Axboe <jens.axboe@oracle.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <49D3236D.3090705@cn.fujitsu.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>


---
 kernel/trace/blktrace.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
index 921ef5d..e45e1af 100644
--- a/kernel/trace/blktrace.c
+++ b/kernel/trace/blktrace.c
@@ -1182,7 +1182,7 @@ static enum print_line_t print_one_line(struct trace_iterator *iter,
 	}
 
 	if (unlikely(what == 0 || what >= ARRAY_SIZE(what2act)))
-		ret = trace_seq_printf(s, "Bad pc action %x\n", what);
+		ret = trace_seq_printf(s, "Unknown action %x\n", what);
 	else {
 		ret = log_action(iter, what2act[what].act[long_act]);
 		if (ret)

[tip:tracing/core] blktrace: fix output of BLK_TC_PC events

[tip-bot for Li Zefan]

Commit-ID:  66de7792c02693b49671afe58c771fde3b092fc7
Gitweb:     http://git.kernel.org/tip/66de7792c02693b49671afe58c771fde3b092fc7
Author:     Li Zefan <lizf@cn.fujitsu.com>
AuthorDate: Wed, 1 Apr 2009 16:19:19 +0800
Committer:  Ingo Molnar <mingo@elte.hu>
CommitDate: Sun, 12 Apr 2009 15:32:46 +0200

blktrace: fix output of BLK_TC_PC events

BLK_TC_PC events should be treated differently with BLK_TC_FS events.

Before this patch:

 # echo 1 > /sys/block/sda/sda1/trace/enable
 # echo pc > /sys/block/sda/sda1/trace/act_mask
 # echo blk > /debugfs/tracing/current_tracer
 # (generate some BLK_TC_PC events)
 # cat trace
        bash-2184  [000]  1774.275413:   8,7    I   N [bash]
        bash-2184  [000]  1774.275435:   8,7    D   N [bash]
        bash-2184  [000]  1774.275540:   8,7    I   R [bash]
        bash-2184  [000]  1774.275547:   8,7    D   R [bash]
 ksoftirqd/0-4     [000]  1774.275580:   8,7    C   N 0 [0]
        bash-2184  [000]  1774.275648:   8,7    I   R [bash]
        bash-2184  [000]  1774.275653:   8,7    D   R [bash]
 ksoftirqd/0-4     [000]  1774.275682:   8,7    C   N 0 [0]
        bash-2184  [000]  1774.275739:   8,7    I   R [bash]
        bash-2184  [000]  1774.275744:   8,7    D   R [bash]
 ksoftirqd/0-4     [000]  1774.275771:   8,7    C   N 0 [0]
        bash-2184  [000]  1774.275804:   8,7    I   R [bash]
        bash-2184  [000]  1774.275808:   8,7    D   R [bash]
 ksoftirqd/0-4     [000]  1774.275836:   8,7    C   N 0 [0]

After this patch:

 # cat trace
        bash-2263  [000]   366.782149:   8,7    I   N 0 (00 ..) [bash]
        bash-2263  [000]   366.782323:   8,7    D   N 0 (00 ..) [bash]
        bash-2263  [000]   366.782557:   8,7    I   R 8 (25 00 ..) [bash]
        bash-2263  [000]   366.782560:   8,7    D   R 8 (25 00 ..) [bash]
 ksoftirqd/0-4     [000]   366.782582:   8,7    C   N (25 00 ..) [0]
        bash-2263  [000]   366.782648:   8,7    I   R 8 (5a 00 3f 00) [bash]
        bash-2263  [000]   366.782650:   8,7    D   R 8 (5a 00 3f 00) [bash]
 ksoftirqd/0-4     [000]   366.782669:   8,7    C   N (5a 00 3f 00) [0]
        bash-2263  [000]   366.782710:   8,7    I   R 8 (5a 00 08 00) [bash]
        bash-2263  [000]   366.782713:   8,7    D   R 8 (5a 00 08 00) [bash]
 ksoftirqd/0-4     [000]   366.782730:   8,7    C   N (5a 00 08 00) [0]
        bash-2263  [000]   366.783375:   8,7    I   R 36 (5a 00 08 00) [bash]
        bash-2263  [000]   366.783379:   8,7    D   R 36 (5a 00 08 00) [bash]
 ksoftirqd/0-4     [000]   366.783404:   8,7    C   N (5a 00 08 00) [0]

This is what we do with PC events in user-space blktrace.

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jens Axboe <jens.axboe@oracle.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <49D32387.9040106@cn.fujitsu.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>


---
 kernel/trace/blktrace.c |   88 ++++++++++++++++++++++++++++++++++++++++++----
 1 files changed, 80 insertions(+), 8 deletions(-)

diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
index e45e1af..2b98195 100644
--- a/kernel/trace/blktrace.c
+++ b/kernel/trace/blktrace.c
@@ -971,6 +971,16 @@ static inline const void *pdu_start(const struct trace_entry *ent)
 	return te_blk_io_trace(ent) + 1;
 }
 
+static inline u32 t_action(const struct trace_entry *ent)
+{
+	return te_blk_io_trace(ent)->action;
+}
+
+static inline u32 t_bytes(const struct trace_entry *ent)
+{
+	return te_blk_io_trace(ent)->bytes;
+}
+
 static inline u32 t_sec(const struct trace_entry *ent)
 {
 	return te_blk_io_trace(ent)->bytes >> 9;
@@ -1031,25 +1041,87 @@ static int blk_log_action(struct trace_iterator *iter, const char *act)
 				MAJOR(t->device), MINOR(t->device), act, rwbs);
 }
 
+static int blk_log_dump_pdu(struct trace_seq *s, const struct trace_entry *ent)
+{
+	const char *pdu_buf;
+	int pdu_len;
+	int i, end, ret;
+
+	pdu_buf = pdu_start(ent);
+	pdu_len = te_blk_io_trace(ent)->pdu_len;
+
+	if (!pdu_len)
+		return 1;
+
+	/* find the last zero that needs to be printed */
+	for (end = pdu_len - 1; end >= 0; end--)
+		if (pdu_buf[end])
+			break;
+	end++;
+
+	if (!trace_seq_putc(s, '('))
+		return 0;
+
+	for (i = 0; i < pdu_len; i++) {
+
+		ret = trace_seq_printf(s, "%s%02x",
+				       i == 0 ? "" : " ", pdu_buf[i]);
+		if (!ret)
+			return ret;
+
+		/*
+		 * stop when the rest is just zeroes and indicate so
+		 * with a ".." appended
+		 */
+		if (i == end && end != pdu_len - 1)
+			return trace_seq_puts(s, " ..) ");
+	}
+
+	return trace_seq_puts(s, ") ");
+}
+
 static int blk_log_generic(struct trace_seq *s, const struct trace_entry *ent)
 {
 	char cmd[TASK_COMM_LEN];
 
 	trace_find_cmdline(ent->pid, cmd);
 
-	if (t_sec(ent))
-		return trace_seq_printf(s, "%llu + %u [%s]\n",
-					t_sector(ent), t_sec(ent), cmd);
-	return trace_seq_printf(s, "[%s]\n", cmd);
+	if (t_action(ent) & BLK_TC_ACT(BLK_TC_PC)) {
+		int ret;
+
+		ret = trace_seq_printf(s, "%u ", t_bytes(ent));
+		if (!ret)
+			return 0;
+		ret = blk_log_dump_pdu(s, ent);
+		if (!ret)
+			return 0;
+		return trace_seq_printf(s, "[%s]\n", cmd);
+	} else {
+		if (t_sec(ent))
+			return trace_seq_printf(s, "%llu + %u [%s]\n",
+						t_sector(ent), t_sec(ent), cmd);
+		return trace_seq_printf(s, "[%s]\n", cmd);
+	}
 }
 
 static int blk_log_with_error(struct trace_seq *s,
 			      const struct trace_entry *ent)
 {
-	if (t_sec(ent))
-		return trace_seq_printf(s, "%llu + %u [%d]\n", t_sector(ent),
-					t_sec(ent), t_error(ent));
-	return trace_seq_printf(s, "%llu [%d]\n", t_sector(ent), t_error(ent));
+	if (t_action(ent) & BLK_TC_ACT(BLK_TC_PC)) {
+		int ret;
+
+		ret = blk_log_dump_pdu(s, ent);
+		if (ret)
+			return trace_seq_printf(s, "[%d]\n", t_error(ent));
+		return 0;
+	} else {
+		if (t_sec(ent))
+			return trace_seq_printf(s, "%llu + %u [%d]\n",
+						t_sector(ent),
+						t_sec(ent), t_error(ent));
+		return trace_seq_printf(s, "%llu [%d]\n",
+					t_sector(ent), t_error(ent));
+	}
 }
 
 static int blk_log_remap(struct trace_seq *s, const struct trace_entry *ent)