[PATCH 0/5 v2] Binary ftrace_printk

[PATCH 0/5 v2] Binary ftrace_printk

[Frederic Weisbecker]

This new iteration addresses Steven's reviews.
Notably:

- only build the ftrace_printk format section if CONFIG_TRACING is set
- be scheduler tracing safe (don't use preempt_enable directly from
  ftrace_printk to avoid tracing recursion)
- fix a loss of format string when a module is unloaded. Since we can loose
  it on the ring-buffer if it is in overwrite mode, we don't keep track
  of the format given by the modules to free them. We just copy their
  ftrace_printk string format forever. Note that it is safe against duplicate
  strings since we verify if the string is already present in our list before
  allocating a new one.

---
An new optimization is making its way to ftrace. Its purpose is to
make ftrace_printk() consuming less memory and become faster.

Written by Lai Jiangshan, the approach is to delay the formatting
job from tracing time to output time.
Currently, a call to ftrace_printk will format the whole string and
insert it into the ring buffer. Then you can read it on /debug/tracing/trace
file.

The new implementation stores the address of the format string and
the binary parameters into the ring buffer, making the packet more compact
and faster to insert.
Later, when the user exports the traces, the format string is retrieved
with the binary parameters and the formatting job is eventually done.

Here is the result of a small comparative benchmark while putting the following
ftrace_printk on the timer interrupt. ftrace_printk is the old implementation,
ftrace_bprintk is a the new one:

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

After some time running on low load (no X, no really active processes):

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

Higher load (started X and launched a cat running on a X console looping on
traces printing):

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

Which means the new implementation can be 70 % faster on higher load.
And it consumes lesser memory on the ring buffer.

The three first patches rebase against latest -tip the ftrace_bprintk work done
by Lai few monthes ago.

The two others integrate ftrace_bprintk as a replacement for the old
ftrace_printk implementation and factorize the printf style format decoding
which is now used by three functions.

Frederic Weisbecker (2):
  tracing/core: drop the old ftrace_printk implementation in favour of
    ftrace_bprintk
  vsprintf: unify the format decoding layer for its 3 users

Lai Jiangshan (3):
  add binary printf
  ftrace: infrastructure for supporting binary record
  ftrace: add ftrace_bprintk()

 include/asm-generic/vmlinux.lds.h    |    3 +
 include/linux/ftrace.h               |   44 ++-
 include/linux/module.h               |    5 +
 include/linux/string.h               |    7 +
 kernel/module.c                      |    6 +
 kernel/trace/Kconfig                 |    1 +
 kernel/trace/Makefile                |    1 +
 kernel/trace/trace.c                 |  141 +++---
 kernel/trace/trace.h                 |    8 +-
 kernel/trace/trace_functions_graph.c |    6 +-
 kernel/trace/trace_mmiotrace.c       |    9 +-
 kernel/trace/trace_output.c          |   31 +-
 kernel/trace/trace_output.h          |    2 +
 kernel/trace/trace_printk.c          |  138 +++++
 lib/Kconfig                          |    3 +
 lib/vsprintf.c                       | 1006 ++++++++++++++++++++++++++--------
 16 files changed, 1087 insertions(+), 324 deletions(-)
 create mode 100644 kernel/trace/trace_printk.c

Re: [PATCH 0/5 v2] Binary ftrace_printk

[Frederic Weisbecker]

On Thu, Mar 05, 2009 at 05:53:58AM +0100, Frederic Weisbecker wrote:
> 
> This new iteration addresses Steven's reviews.
> Notably:
> 
> - only build the ftrace_printk format section if CONFIG_TRACING is set
> - be scheduler tracing safe (don't use preempt_enable directly from
>   ftrace_printk to avoid tracing recursion)
> - fix a loss of format string when a module is unloaded. Since we can loose
>   it on the ring-buffer if it is in overwrite mode, we don't keep track
>   of the format given by the modules to free them. We just copy their
>   ftrace_printk string format forever. Note that it is safe against duplicate
>   strings since we verify if the string is already present in our list before
>   allocating a new one.
> 
> ---


tip:master has seen some changes concerning the tracing bits since this patchset
submission, notably the movement of ftrace_printk to include/kernel.h

These patches probably won't anymore apply properly.
Do you want me to rebase them against latest tip/master?

Or perhaps you prefer to wait for a Acked-by from Linus or Andrew?

Frederic.


> An new optimization is making its way to ftrace. Its purpose is to
> make ftrace_printk() consuming less memory and become faster.
> 
> Written by Lai Jiangshan, the approach is to delay the formatting
> job from tracing time to output time.
> Currently, a call to ftrace_printk will format the whole string and
> insert it into the ring buffer. Then you can read it on /debug/tracing/trace
> file.
> 
> The new implementation stores the address of the format string and
> the binary parameters into the ring buffer, making the packet more compact
> and faster to insert.
> Later, when the user exports the traces, the format string is retrieved
> with the binary parameters and the formatting job is eventually done.
> 
> Here is the result of a small comparative benchmark while putting the following
> ftrace_printk on the timer interrupt. ftrace_printk is the old implementation,
> ftrace_bprintk is a the new one:
> 
> ftrace_printk("This is the timer interrupt: %llu", jiffies_64);
> 
> After some time running on low load (no X, no really active processes):
> 
> 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
> 
> Higher load (started X and launched a cat running on a X console looping on
> traces printing):
> 
> ftrace_printk:  duration average: 8812 ns
> ftrace_bprintk: duration average: 2611 ns
> 
> Which means the new implementation can be 70 % faster on higher load.
> And it consumes lesser memory on the ring buffer.
> 
> The three first patches rebase against latest -tip the ftrace_bprintk work done
> by Lai few monthes ago.
> 
> The two others integrate ftrace_bprintk as a replacement for the old
> ftrace_printk implementation and factorize the printf style format decoding
> which is now used by three functions.
> 
> Frederic Weisbecker (2):
>   tracing/core: drop the old ftrace_printk implementation in favour of
>     ftrace_bprintk
>   vsprintf: unify the format decoding layer for its 3 users
> 
> Lai Jiangshan (3):
>   add binary printf
>   ftrace: infrastructure for supporting binary record
>   ftrace: add ftrace_bprintk()
> 
>  include/asm-generic/vmlinux.lds.h    |    3 +
>  include/linux/ftrace.h               |   44 ++-
>  include/linux/module.h               |    5 +
>  include/linux/string.h               |    7 +
>  kernel/module.c                      |    6 +
>  kernel/trace/Kconfig                 |    1 +
>  kernel/trace/Makefile                |    1 +
>  kernel/trace/trace.c                 |  141 +++---
>  kernel/trace/trace.h                 |    8 +-
>  kernel/trace/trace_functions_graph.c |    6 +-
>  kernel/trace/trace_mmiotrace.c       |    9 +-
>  kernel/trace/trace_output.c          |   31 +-
>  kernel/trace/trace_output.h          |    2 +
>  kernel/trace/trace_printk.c          |  138 +++++
>  lib/Kconfig                          |    3 +
>  lib/vsprintf.c                       | 1006 ++++++++++++++++++++++++++--------
>  16 files changed, 1087 insertions(+), 324 deletions(-)
>  create mode 100644 kernel/trace/trace_printk.c
> 
> 

Re: [PATCH 0/5 v2] Binary ftrace_printk

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> On Thu, Mar 05, 2009 at 05:53:58AM +0100, Frederic Weisbecker wrote:
> > 
> > This new iteration addresses Steven's reviews.
> > Notably:
> > 
> > - only build the ftrace_printk format section if CONFIG_TRACING is set
> > - be scheduler tracing safe (don't use preempt_enable directly from
> >   ftrace_printk to avoid tracing recursion)
> > - fix a loss of format string when a module is unloaded. Since we can loose
> >   it on the ring-buffer if it is in overwrite mode, we don't keep track
> >   of the format given by the modules to free them. We just copy their
> >   ftrace_printk string format forever. Note that it is safe against duplicate
> >   strings since we verify if the string is already present in our list before
> >   allocating a new one.
> > 
> > ---
> 
> 
> tip:master has seen some changes concerning the tracing bits 
> since this patchset submission, notably the movement of 
> ftrace_printk to include/kernel.h
> 
> These patches probably won't anymore apply properly. Do you 
> want me to rebase them against latest tip/master?

Yeah, please do. (Would there be a way for you to submit via 
tools that preserve the email-threading of the patches? Right 
now your mails come in separate threads each.)

> Or perhaps you prefer to wait for a Acked-by from Linus or 
> Andrew?

The current lineup looks pretty good to me.

Patch #1 is what modifies lib/vsprintf.c and unless Linus or 
Andrew objects i plan to put that into tip:core/printk so that 
it's not embedded in the tracing tree and sent upstream 
separately.

Then i'll merge that branch into the tracing tree and apply 
patches #2...#5. So as long as you send against tip:master (i.e. 
against the latest tracing bits) i'll be able to sort it out 
neatly.

	Ingo

Re: [PATCH 0/5 v2] Binary ftrace_printk

[Frederic Weisbecker]

On Fri, Mar 06, 2009 at 12:58:22PM +0100, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> 
> > On Thu, Mar 05, 2009 at 05:53:58AM +0100, Frederic Weisbecker wrote:
> > > 
> > > This new iteration addresses Steven's reviews.
> > > Notably:
> > > 
> > > - only build the ftrace_printk format section if CONFIG_TRACING is set
> > > - be scheduler tracing safe (don't use preempt_enable directly from
> > >   ftrace_printk to avoid tracing recursion)
> > > - fix a loss of format string when a module is unloaded. Since we can loose
> > >   it on the ring-buffer if it is in overwrite mode, we don't keep track
> > >   of the format given by the modules to free them. We just copy their
> > >   ftrace_printk string format forever. Note that it is safe against duplicate
> > >   strings since we verify if the string is already present in our list before
> > >   allocating a new one.
> > > 
> > > ---
> > 
> > 
> > tip:master has seen some changes concerning the tracing bits 
> > since this patchset submission, notably the movement of 
> > ftrace_printk to include/kernel.h
> > 
> > These patches probably won't anymore apply properly. Do you 
> > want me to rebase them against latest tip/master?
> 
> Yeah, please do. (Would there be a way for you to submit via 
> tools that preserve the email-threading of the patches? Right 
> now your mails come in separate threads each.)


Ok, I will try that. Until now I used a very simple smtp client.
I will try git-send-mail.

 
> > Or perhaps you prefer to wait for a Acked-by from Linus or 
> > Andrew?
> 
> The current lineup looks pretty good to me.
> 
> Patch #1 is what modifies lib/vsprintf.c and unless Linus or 
> Andrew objects i plan to put that into tip:core/printk so that 
> it's not embedded in the tracing tree and sent upstream 
> separately.
> 
> Then i'll merge that branch into the tracing tree and apply 
> patches #2...#5. So as long as you send against tip:master (i.e. 
> against the latest tracing bits) i'll be able to sort it out 
> neatly.
> 
> 	Ingo


Ok.