Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Steven Rostedt <rostedt@goodmis.org>]

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.

> 
> Hmm, wait a minute, I don't understand how this thing works at all.

Heh, I guess I need to add more comments :-/

> 
> Let's take for instance print_lat_fmt() which is the first user of
> trace_seq_print_cont(). Now, print_lat_fmt() does
> 
> 	struct trace_entry *entry = iter->ent;

iter->ent is the start of the entry to print. It is not necessarily
the current entry in the iteration buffer.

> 
> and uses 'entry'. Let's assume it is of type TRACE_PRINT. It does
> 
> 	case TRACE_PRINT:
> 		seq_print_ip_sym(s, field->print.ip, sym_flags);
> 		trace_seq_printf(s, ": %s", field->print.buf);
> 		if (field->flags & TRACE_FLAG_CONT)
> 			trace_seq_print_cont(s, iter);
> 		break;
> 
> Ok, it prints the beginning of the message, and if there should be
> continuation blocks, it calls trace_seq_print_cont(), defined as
> follows:
> 
> 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.

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

> 
> Steven, could you explain what is going on here?

Just did ;-)

Hope it helps,

-- Steve