Speeding up ftrace printing

A kernel patch that reduces memory, while providing a performance increase of roughly a factor of three, is generally seen as a good thing. But, when there is another, more-or-less equivalent—but much faster—way to perform that action, it may appear to be an unnecessary optimization. A recent patch to the ftrace_printk() function has those characteristics, but the ability to get such a speed increase, even in something that is just convenient—rather than required—may well trump the concerns about the necessity.

Lai Jiangshan proposed adding a binary version of ftrace_printk() last December; Frederic Weisbecker has picked up the patches and submitted them for inclusion into ftrace. The basic idea is that rather than converting the arguments to strings—as specified in a printk()-style format string—ftrace_bprintk() would defer the actual conversion until the trace output is read by user space. Instead it would put the binary values into the ring buffer, along with a pointer to the format string. When the trace data is read from debugfs, the format string and binary data are used to construct the output.

Ingo Molnar liked the idea, but was unhappy with the implementation that duplicated much of the code in vsnprintf() into two new functions. He suggested that it should be possible to pull out the common code: "We should try _much_ harder at unifying these functions before giving up and duplicating them." Weisbecker agreed, which eventually resulted in a patch that breaks out the format string decoding as a separate function.

Molnar also asked for some performance numbers, which Weisbecker provided as part of his patch. He reported the memory and time difference when adding:

    ftrace_printk("This is the timer interrupt: %llu", jiffies_64);

    ftrace_printk:  duration average: 2044 ns, avg of bytes stored per entry: 39
    ftrace_bprintk: duration average: 1426 ns, avg of bytes stored per entry: 16

    ftrace_printk:  duration average: 8812 ns
    ftrace_bprintk: duration average: 2611 ns

Andrew Morton was a bit puzzled by the intent of the patch: "Trying to make something which is inherently slow run slightly faster seems...odd." But Molnar explained why it makes sense:

Breaking out the format string handling into its own format_decode() function was mostly met with approval, except that the argument list is rather ugly:

    int format_decode(const char *fmt, enum format_type *type, 
                      int *flags, int *field_width, int *base, 
                      int *precision, int *qualifier)

Torvalds also thought that the various helper functions to handle specific formats (i.e. number(), pointer(), string(), etc.) should get passed a struct printf_spec pointer as well. As he points out: "When cleaning up, let's just do it properly." Once again, Weisbecker was quick to agree; he plans to respin the patches addressing these and other comments in the near future.

In addition, because ftrace_bprintk() is a drop-in replacement for ftrace_printk(), Weisbecker proposes eliminating the current code in favor of the faster version. Molnar, at least, advocates that outcome:

While it is a minor upgrade to a relatively minor kernel subsystem, it does provide some impressive performance gains. As a bonus, the review process has resulted in some clean-up that was probably overdue. While there is validity to the argument that it is not really required, it is not very intrusive, nor very large. In the end, that is likely to be enough to see it eventually end up in the mainline.