Message-ID: <20080908201923.192373d3@daedalus.pq.iki.fi>
Date:	Mon, 8 Sep 2008 20:19:23 +0300
From:	Pekka Paalanen <pq@....fi>
To:	Steven Rostedt <rostedt@...dmis.org>
Cc:	Frédéric Weisbecker <fweisbec@...il.com>,
	Ingo Molnar <mingo@...e.hu>,
	Linux Kernel <linux-kernel@...r.kernel.org>
Subject: Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

On Sun, 7 Sep 2008 13:29:40 -0400 (EDT)
Steven Rostedt <rostedt@...dmis.org> wrote:

> 
> On Sun, 7 Sep 2008, Pekka Paalanen wrote:
> 
> > Steven,
> > 
> > is there a logic behind trace_seq_print_cont() printing the terminating
> > newline only, when there actually is no TRACE_CONT entry?
> 
> Actually, that case is more of an anomaly than the correct. It means
> that somehow the print statement wanted to continue, but did not. This 
> means that the print statement probably did not finish the line, and
> that we should do a newline to make sure the next entry starts on a
> new line.

Oh, I never thought it from that point of view.

> > static void
> > trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
> > {
> > 	struct trace_array *tr = iter->tr;
> > 	struct trace_array_cpu *data = tr->data[iter->cpu];
> > 	struct trace_entry *ent;
> > 
> > 	ent = trace_entry_idx(tr, data, iter, iter->cpu);
> > 	if (!ent || ent->type != TRACE_CONT) {
> > 		trace_seq_putc(s, '\n');
> > 		return;
> > 	}
> > 
> > 	do {
> > 		trace_seq_printf(s, "%s", ent->cont.buf);
> > 		__trace_iterator_increment(iter, iter->cpu);
> > 		ent = trace_entry_idx(tr, data, iter, iter->cpu);
> > 	} while (ent && ent->type == TRACE_CONT);
> > }
> 
> Because we do a merge sort of the entries in each CPU buffer, after we
> get the next entry to print, we increment that iteration buffer. This
> means that trace_entry_idx() will return the next entry field after
> we got the iter->ent. This is also why we use iter->ent instead of
> just calling trace_entry_idx. This keeps the merge sort simpler.

Yes, I forgot the per-cpu buffers. When merging you want the first one
wrt. timestamp, and when continuing you want the next on that cpu's
buffer.

> > Here it uses trace_entry_idx() to get 'ent'. What's the difference to
> > iter->ent? I don't understand how trace_entry_idx() works, but looking
> > at how it is used, it must return the pointer to the *next* entry in
> > the ring buffer. So I don't understand the name of the function, and I
> > don't see a call to __trace_iterator_increment(), which is confusing.
> 
> iter->ent is the entry to be used in the "show" function. When we found 
> that entry, we incremented the buffer to get it ready for the next
> merge sort.
> 
> When we get to show, iter->ent is the entry to print, and if we use
> iter_entry_idx() that will point to the next entry in that buffer that
> will be used next time. I also did this to make it easier for the latency 
> format be able to calculate the notations (like the '!').
> 
> > If contrary to the assumption, 'ent' is not a continuation, it prints
> > the terminating newline. This is an exceptional case, as the original
> > entry was marked as having continuation entries.
> 
> Right, this is somehow an entry was flagged as continue, but it did not.
> It is probably a bug in the code, and instead of writing a strange format,
> where the next entry continued on the same line, I chose to let the
> entry go onto the next line.
> 
> > The normal case then is to execute the do-while, until it hits a
> > non-continuation entry. Here it does *not* print the terminating newline.
> 
> Correct. The reason is that the ftrace_printk() call should have contained
> its own new line. I could also add a check (and probably will) to see if
> the printk did end with a newline, and add one if it did not.

My first idea was to filter out all newlines from messages, making a
message a single line, and then force a newline, but now I realize
that would be an exception to the printk convention. Maybe I should
just start a new line in the output, when I get a newline :-)
Although that probably means my version of trace_seq_print_cont() must
live in trace.c, which IMHO is over-crowded already.

But then there's a small chance the whole output of a single
TRACE_PRINT entry might not fit into one trace_seq ever, since each
line in mmiotrace has a prologue. Oh well, can't win always, I'll just
drop what doesn't fit into output.

Hmm, it already does that, doesn't it, if the output does not fit into
trace_seq buffer. There might be a corner case...

> > Steven, could you explain what is going on here?
> 
> Just did ;-)
> 
> Hope it helps,

Oh yes, thank you very much :-)

btw. How do you feel about moving the #ifdef CONFIG_MMIOTRACE functions
from trace.c to trace_mmiotrace.c and unstatifying all the functions
they need? Seems some of them are inline, and the spinlock stuff just
looks so... raw :-)

-- 
Pekka Paalanen
http://www.iki.fi/pq/
--
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/

Powered by blists - more mailing lists