Re: [PATCH] ftrace: printk formatting infrastructure

[Andrew Morton <akpm@linux-foundation.org>]

On Fri, 1 Aug 2008 00:54:39 -0400 (EDT) Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> This patch adds a feature that can help kernel developers debug their
> code using ftrace.
> 
>   int ftrace_printk(const char *fmt, ...);
> 
> This records into the ftrace buffer using printf formatting. The entry
> size in the buffers are still a fixed length. A new type has been added
> that allows for more entries to be used for a single recording.
> 
> The start of the print is still the same as the other entries.
> 
> It returns the number of characters written to the ftrace buffer.
> 
> 
> For example:
> 
> Having a module with the following code:
> 
> static int __init ftrace_print_test(void)
> {
>         ftrace_printk("jiffies are %ld\n", jiffies);
> 	return 0;
> }
> 
> Gives me:
> 
>   insmod-5441  3...1 7569us : ftrace_print_test: jiffies are 4296626666
> 
> for the latency_trace file and:
> 
>           insmod-5441  [03]  1959.370498: ftrace_print_test jiffies are 4296626666
> 
> for the trace file.
> 
> Note: Only the infrastructure should go into the kernel. It is to help 
> facilitate debugging for other kernel developers. Calls to ftrace_printk 
> is not intended to be left in the kernel, and should be frowned upon just 
> like scattering printks around in the code.
> 
> But having this easily at your fingertips helps the debugging go faster 
> and bugs be solved quicker.
> 
> Maybe later on, we can hook this with markers and have their printf format 
> be sucked into ftrace output.
> 

Seems like it would be useful.

Do we have any evidence that reandom developers are using ftrace yet? 
And any feedback from them?

>
> ...
>
> +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;
> +	struct trace_cont *cont;
> +
> +	ent = trace_entry_idx(tr, data, iter, iter->cpu);
> +	if (!ent || ent->type != TRACE_CONT) {
> +		trace_seq_putc(s, '\n');
> +		return;
> +	}
> +
> +	do {
> +		cont = (struct trace_cont *)ent;

What you have here is umm, a variant record, or its in-memory equiv
which probably has a name.

> ...
>
> +/*
> + * When an item needs more than one entry to fill a buffer
> + * it can use this structure.
> + */
> +struct trace_cont {
> +	char type;
> +	char buf[];
> +};

Would it not be cleaner and clearer to do this:

struct trace_entry {
	char			type;
	union {
		struct {
			char			cpu;
			char			flags;
			char			preempt_count;
			int			pid;
			cycle_t			t;
			union {
				struct ftrace_entry		fn;
				struct ctx_switch_entry		ctx;
				struct special_entry		special;
				struct stack_entry		stack;
				struct mmiotrace_rw		mmiorw;
				struct mmiotrace_map		mmiomap;
			};
		};
		char buf[0];
		<other things here>
	}
};

So the first byte (`type') indicates which of the members of that union
are actually contained in the payload.

That way it's all typesafe and avoids casting.


Of course, rather than using the anonymous union/struct trickery it
would be much nicer and clearer to do it this way:

struct trace_field {
	char			cpu;
	char			flags;
	char			preempt_count;
	int			pid;
	cycle_t			t;
	union {
		struct ftrace_entry		fn;
		struct ctx_switch_entry		ctx;
		struct special_entry		special;
		struct stack_entry		stack;
		struct mmiotrace_rw		mmiorw;
		struct mmiotrace_map		mmiomap;
	};
};

struct trace_cont_field {
	char buf[];
};

...

struct trace_entry {
	char type;
	union {
		struct trace_field trace_field;
		struct trace_cont_field trace_cont_field;
		...
	};
};

however that would require a large (but very simple) edit to the
existing code.

In the long run, the larger patch would be better though.