Re: [PATCH tip 1/1] trace: judicious error checking of trace_seq results

Frederic Weisbecker
2009-02-03T23:08:19Z

On Tue, Feb 03, 2009 at 08:20:41PM -0200, Arnaldo Carvalho de Melo wrote:
> Impact: bugfix/cleanup
>
> Some callsites were returning either TRACE_ITER_PARTIAL_LINE if the
> trace_seq routines (trace_seq_printf, etc) returned 0 meaning its buffer
> was full, or zero otherwise.
>
> But...
>
> /* Return values for print_line callback */
> enum print_line_t {
> TRACE_TYPE_PARTIAL_LINE = 0, /* Retry after flushing the seq */
> TRACE_TYPE_HANDLED = 1,
> TRACE_TYPE_UNHANDLED = 2 /* Relay to other output functions */
> };
>
> In other cases the return value was not being relayed at all.
>
> Most of the time it didn't hurt because the page wasn't get filled, but
> for correctness sake, handle the return values everywhere.

Looks like a good cleanup.
Just a small comment below..

> Cc: Ingo Molnar <mingo@elte.hu>
> Cc: Frédéric Weisbecker <fweisbec@gmail.com>
> Cc: Jens Axboe <jens.axboe@oracle.com>
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> ---
> block/blktrace.c | 2 +-
> kernel/trace/trace.c | 75 ++++++++++++--------------
> kernel/trace/trace_branch.c | 2 +-
> kernel/trace/trace_output.c | 123 ++++++++++++++++++-------------------------
> 4 files changed, 87 insertions(+), 115 deletions(-)
>
> diff --git a/block/blktrace.c b/block/blktrace.c
> index 8f5c37b..12df276 100644
> --- a/block/blktrace.c
> +++ b/block/blktrace.c
> @@ -1165,7 +1165,7 @@ static int blk_trace_event_print(struct trace_iterator *iter, int flags)
> const u16 what = t->action & ((1 << BLK_TC_SHIFT) - 1);
> int ret;
>
> - if (trace_print_context(iter))
> + if (!trace_print_context(iter))
> return TRACE_TYPE_PARTIAL_LINE;
>
> if (unlikely(what == 0 || what > ARRAY_SIZE(what2act)))
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index bbdfaa2..5822ff4 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -1402,27 +1402,25 @@ static enum print_line_t print_lat_fmt(struct trace_iterator *iter)
> unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
> struct trace_event *event;
> struct trace_entry *entry = iter->ent;
> - int ret;
>
> test_cpu_buff_start(iter);
>
> event = ftrace_find_event(entry->type);
>
> if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
> - ret = trace_print_lat_context(iter);
> - if (ret)
> - return ret;
> + if (!trace_print_lat_context(iter))
> + goto partial;
> }
>
> - if (event && event->latency_trace) {
> - ret = event->latency_trace(iter, sym_flags);
> - if (ret)
> - return ret;
> - return TRACE_TYPE_HANDLED;
> - }
> + if (event && event->latency_trace)
> + return event->latency_trace(iter, sym_flags);
> +
> + if (!trace_seq_printf(s, "Unknown type %d\n", entry->type))
> + goto partial;
>
> - trace_seq_printf(s, "Unknown type %d\n", entry->type);
> return TRACE_TYPE_HANDLED;
> +partial:
> + return TRACE_TYPE_PARTIAL_LINE;
> }
>
> static enum print_line_t print_trace_fmt(struct trace_iterator *iter)
> @@ -1431,7 +1429,6 @@ static enum print_line_t print_trace_fmt(struct trace_iterator *iter)
> unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
> struct trace_entry *entry;
> struct trace_event *event;
> - int ret;
>
> entry = iter->ent;
>
> @@ -1440,22 +1437,19 @@ static enum print_line_t print_trace_fmt(struct trace_iterator *iter)
> event = ftrace_find_event(entry->type);
>
> if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
> - ret = trace_print_context(iter);
> - if (ret)
> - return ret;
> + if (!trace_print_context(iter))
> + goto partial;
> }
>
> - if (event && event->trace) {
> - ret = event->trace(iter, sym_flags);
> - if (ret)
> - return ret;
> - return TRACE_TYPE_HANDLED;
> - }
> - ret = trace_seq_printf(s, "Unknown type %d\n", entry->type);
> - if (!ret)
> - return TRACE_TYPE_PARTIAL_LINE;
> + if (event && event->trace)
> + return event->trace(iter, sym_flags);
> +
> + if (!trace_seq_printf(s, "Unknown type %d\n", entry->type))
> + goto partial;
>
> return TRACE_TYPE_HANDLED;
> +partial:
> + return TRACE_TYPE_PARTIAL_LINE;
> }
>
> static enum print_line_t print_raw_fmt(struct trace_iterator *iter)
> @@ -1463,29 +1457,25 @@ static enum print_line_t print_raw_fmt(struct trace_iterator *iter)
> struct trace_seq *s = &iter->seq;
> struct trace_entry *entry;
> struct trace_event *event;
> - int ret;
>
> entry = iter->ent;
>
> if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
> - ret = trace_seq_printf(s, "%d %d %llu ",
> - entry->pid, iter->cpu, iter->ts);
> - if (!ret)
> - return TRACE_TYPE_PARTIAL_LINE;
> + if (!trace_seq_printf(s, "%d %d %llu ",
> + entry->pid, iter->cpu, iter->ts))
> + goto partial;
> }
>
> event = ftrace_find_event(entry->type);
> - if (event && event->raw) {
> - ret = event->raw(iter, 0);
> - if (ret)
> - return ret;
> - return TRACE_TYPE_HANDLED;
> - }
> - ret = trace_seq_printf(s, "%d ?\n", entry->type);
> - if (!ret)
> - return TRACE_TYPE_PARTIAL_LINE;
> + if (event && event->raw)
> + return event->raw(iter, 0);
> +
> + if (!trace_seq_printf(s, "%d ?\n", entry->type))
> + goto partial;
>
> return TRACE_TYPE_HANDLED;
> +partial:
> + return TRACE_TYPE_PARTIAL_LINE;
> }
>
> static enum print_line_t print_hex_fmt(struct trace_iterator *iter)
> @@ -1504,8 +1494,11 @@ static enum print_line_t print_hex_fmt(struct trace_iterator *iter)
> }
>
> event = ftrace_find_event(entry->type);
> - if (event && event->hex)
> - event->hex(iter, 0);
> + if (event && event->hex) {
> + int ret = event->hex(iter, 0);
> + if (ret != TRACE_TYPE_HANDLED)
> + return ret;
> + }
>
> SEQ_PUT_FIELD_RET(s, newline);
>
> @@ -1544,7 +1537,7 @@ static enum print_line_t print_bin_fmt(struct trace_iterator *iter)
>
> event = ftrace_find_event(entry->type);
> if (event && event->binary)
> - event->binary(iter, 0);
> + return event->binary(iter, 0);
>
> return TRACE_TYPE_HANDLED;
> }
> diff --git a/kernel/trace/trace_branch.c b/kernel/trace/trace_branch.c
> index ea62f10..f6b35e1 100644
> --- a/kernel/trace/trace_branch.c
> +++ b/kernel/trace/trace_branch.c
> @@ -173,7 +173,7 @@ static int trace_branch_print(struct trace_iterator *iter, int flags)
> field->line))
> return TRACE_TYPE_PARTIAL_LINE;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
>
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index c24503b..5b3c914 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -286,55 +286,41 @@ seq_print_ip_sym(struct trace_seq *s, unsigned long ip, unsigned long sym_flags)
> return ret;
> }
>
> -static void
> +static int
> lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu)
> {
> int hardirq, softirq;
> char *comm;
>
> comm = trace_find_cmdline(entry->pid);
> -
> - trace_seq_printf(s, "%8.8s-%-5d ", comm, entry->pid);
> - trace_seq_printf(s, "%3d", cpu);
> - trace_seq_printf(s, "%c%c",
> - (entry->flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
> - (entry->flags & TRACE_FLAG_IRQS_NOSUPPORT) ? 'X' : '.',
> - ((entry->flags & TRACE_FLAG_NEED_RESCHED) ? 'N' : '.'));
> -
> hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
> softirq = entry->flags & TRACE_FLAG_SOFTIRQ;
> - if (hardirq && softirq) {
> - trace_seq_putc(s, 'H');
> - } else {
> - if (hardirq) {
> - trace_seq_putc(s, 'h');
> - } else {
> - if (softirq)
> - trace_seq_putc(s, 's');
> - else
> - trace_seq_putc(s, '.');
> - }
> - }
> +
> + if (!trace_seq_printf(s, "%8.8s-%-5d %3d%c%c%c",
> + comm, entry->pid, cpu,
> + (entry->flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
> + (entry->flags & TRACE_FLAG_IRQS_NOSUPPORT) ?
> + 'X' : '.',
> + (entry->flags & TRACE_FLAG_NEED_RESCHED) ?
> + 'N' : '.',
> + (hardirq && softirq) ? 'H' :
> + hardirq ? 'h' : softirq ? 's' : '.'))
> + return 0;
>
> if (entry->preempt_count)
> - trace_seq_printf(s, "%x", entry->preempt_count);
> - else
> - trace_seq_puts(s, ".");
> + return trace_seq_printf(s, "%x", entry->preempt_count);
> + return trace_seq_puts(s, ".");
> }
>
> static unsigned long preempt_mark_thresh = 100;
>
> -static void
> +static int
> lat_print_timestamp(struct trace_seq *s, u64 abs_usecs,
> unsigned long rel_usecs)
> {
> - trace_seq_printf(s, " %4lldus", abs_usecs);
> - if (rel_usecs > preempt_mark_thresh)
> - trace_seq_puts(s, "!: ");
> - else if (rel_usecs > 1)
> - trace_seq_puts(s, "+: ");
> - else
> - trace_seq_puts(s, " : ");
> + return trace_seq_printf(s, " %4lldus%c: ", abs_usecs,
> + rel_usecs > preempt_mark_thresh ? '!' :
> + rel_usecs > 1 ? '+' : ' ');
> }
>
> int trace_print_context(struct trace_iterator *iter)
> @@ -346,22 +332,14 @@ int trace_print_context(struct trace_iterator *iter)
> unsigned long usec_rem = do_div(t, USEC_PER_SEC);
> unsigned long secs = (unsigned long)t;
>
> - if (!trace_seq_printf(s, "%16s-%-5d ", comm, entry->pid))
> - goto partial;
> - if (!trace_seq_printf(s, "[%03d] ", entry->cpu))
> - goto partial;
> - if (!trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem))
> - goto partial;
> -
> - return 0;
> -
> -partial:
> - return TRACE_TYPE_PARTIAL_LINE;
> + return trace_seq_printf(s, "%16s-%-5d [%03d] %5lu.%06lu: ",
> + comm, entry->pid, entry->cpu, secs, usec_rem);
> }
>
> int trace_print_lat_context(struct trace_iterator *iter)
> {
> u64 next_ts;
> + int ret;
> struct trace_seq *s = &iter->seq;
> struct trace_entry *entry = iter->ent,
> *next_entry = trace_find_next_entry(iter, NULL,
> @@ -376,21 +354,22 @@ int trace_print_lat_context(struct trace_iterator *iter)
>
> if (verbose) {
> char *comm = trace_find_cmdline(entry->pid);
> - trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08lx]"
> - " %ld.%03ldms (+%ld.%03ldms): ",
> - comm,
> - entry->pid, entry->cpu, entry->flags,
> - entry->preempt_count, iter->idx,
> - ns2usecs(iter->ts),
> - abs_usecs/1000,
> - abs_usecs % 1000, rel_usecs/1000,
> - rel_usecs % 1000);
> + ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08lx]"
> + " %ld.%03ldms (+%ld.%03ldms): ", comm,
> + entry->pid, entry->cpu, entry->flags,
> + entry->preempt_count, iter->idx,
> + ns2usecs(iter->ts),
> + abs_usecs / USEC_PER_MSEC,
> + abs_usecs % USEC_PER_MSEC,
> + rel_usecs / USEC_PER_MSEC,
> + rel_usecs % USEC_PER_MSEC);
> } else {
> - lat_print_generic(s, entry, entry->cpu);
> - lat_print_timestamp(s, abs_usecs, rel_usecs);
> + ret = lat_print_generic(s, entry, entry->cpu);
> + if (ret)
> + ret = lat_print_timestamp(s, abs_usecs, rel_usecs);
> }
>
> - return 0;
> + return ret;
> }
>
> static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
> @@ -486,7 +465,7 @@ int unregister_ftrace_event(struct trace_event *event)
>
> int trace_nop_print(struct trace_iterator *iter, int flags)
> {
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> /* TRACE_FN */
> @@ -506,7 +485,7 @@ static int trace_fn_latency(struct trace_iterator *iter, int flags)
> if (!trace_seq_puts(s, ")\n"))
> goto partial;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
>
> partial:
> return TRACE_TYPE_PARTIAL_LINE;
> @@ -533,7 +512,7 @@ static int trace_fn_trace(struct trace_iterator *iter, int flags)
> if (!trace_seq_printf(s, "\n"))
> goto partial;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
>
> partial:
> return TRACE_TYPE_PARTIAL_LINE;
> @@ -550,7 +529,7 @@ static int trace_fn_raw(struct trace_iterator *iter, int flags)
> field->parent_ip))
> return TRACE_TYPE_PARTIAL_LINE;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static int trace_fn_hex(struct trace_iterator *iter, int flags)
> @@ -563,7 +542,7 @@ static int trace_fn_hex(struct trace_iterator *iter, int flags)
> SEQ_PUT_HEX_FIELD_RET(s, field->ip);
> SEQ_PUT_HEX_FIELD_RET(s, field->parent_ip);
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static int trace_fn_bin(struct trace_iterator *iter, int flags)
> @@ -576,7 +555,7 @@ static int trace_fn_bin(struct trace_iterator *iter, int flags)
> SEQ_PUT_FIELD_RET(s, field->ip);
> SEQ_PUT_FIELD_RET(s, field->parent_ip);
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static struct trace_event trace_fn_event = {
> @@ -611,7 +590,7 @@ static int trace_ctxwake_print(struct trace_iterator *iter, char *delim)
> T, comm))
> return TRACE_TYPE_PARTIAL_LINE;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static int trace_ctx_print(struct trace_iterator *iter, int flags)
> @@ -644,7 +623,7 @@ static int trace_ctxwake_raw(struct trace_iterator *iter, char S)
> T))
> return TRACE_TYPE_PARTIAL_LINE;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static int trace_ctx_raw(struct trace_iterator *iter, int flags)
> @@ -678,7 +657,7 @@ static int trace_ctxwake_hex(struct trace_iterator *iter, char S)
> SEQ_PUT_HEX_FIELD_RET(s, field->next_prio);
> SEQ_PUT_HEX_FIELD_RET(s, T);
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static int trace_ctx_hex(struct trace_iterator *iter, int flags)
> @@ -705,7 +684,7 @@ static int trace_ctxwake_bin(struct trace_iterator *iter, int flags)
> SEQ_PUT_FIELD_RET(s, field->next_prio);
> SEQ_PUT_FIELD_RET(s, field->next_state);
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static struct trace_event trace_ctx_event = {
> @@ -739,7 +718,7 @@ static int trace_special_print(struct trace_iterator *iter, int flags)
> field->arg3))
> return TRACE_TYPE_PARTIAL_LINE;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static int trace_special_hex(struct trace_iterator *iter, int flags)
> @@ -753,7 +732,7 @@ static int trace_special_hex(struct trace_iterator *iter, int flags)
> SEQ_PUT_HEX_FIELD_RET(s, field->arg2);
> SEQ_PUT_HEX_FIELD_RET(s, field->arg3);
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static int trace_special_bin(struct trace_iterator *iter, int flags)
> @@ -767,7 +746,7 @@ static int trace_special_bin(struct trace_iterator *iter, int flags)
> SEQ_PUT_FIELD_RET(s, field->arg2);
> SEQ_PUT_FIELD_RET(s, field->arg3);
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
> }
>
> static struct trace_event trace_special_event = {
> @@ -801,7 +780,7 @@ static int trace_stack_print(struct trace_iterator *iter, int flags)
> goto partial;
> }
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
>
> partial:
> return TRACE_TYPE_PARTIAL_LINE;
> @@ -830,7 +809,7 @@ static int trace_user_stack_print(struct trace_iterator *iter, int flags)
> if (!trace_seq_putc(s, '\n'))
> goto partial;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
>
> partial:
> return TRACE_TYPE_PARTIAL_LINE;
> @@ -859,7 +838,7 @@ static int trace_print_print(struct trace_iterator *iter, int flags)
> if (!trace_seq_printf(s, ": %s", field->buf))
> goto partial;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
>
> partial:
> return TRACE_TYPE_PARTIAL_LINE;
> @@ -874,7 +853,7 @@ static int trace_print_raw(struct trace_iterator *iter, int flags)
> if (!trace_seq_printf(&iter->seq, "# %lx %s", field->ip, field->buf))
> goto partial;
>
> - return 0;
> + return TRACE_TYPE_HANDLED;
>
> partial:
> return TRACE_TYPE_PARTIAL_LINE;

Shouldn't these callbacks be converted into enum print_line_t ?
Perhaps for the future users who will define their own callbacks, giving
more hints about the return type...even if an enum is still an int.

> --
> 1.6.0.6
>