From: Steven Rostedt <[email protected]>
Impact: speed up on event tracing
The event_trace_printk is currently a wrapper function that calls
trace_vprintk. Because it uses a variable for the fmt it misses out
on the optimization of using the binary printk.
This patch makes event_trace_printk into a macro wrapper to use the
fmt as the same as the trace_printks.
Signed-off-by: Steven Rostedt <[email protected]>
---
kernel/trace/trace.h | 17 +++++++++++++++++
kernel/trace/trace_events.c | 10 ----------
2 files changed, 17 insertions(+), 10 deletions(-)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index cede1ab..35cfa7b 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -773,4 +773,21 @@ void event_trace_printk(unsigned long ip, const char *fmt, ...);
extern struct ftrace_event_call __start_ftrace_events[];
extern struct ftrace_event_call __stop_ftrace_events[];
+extern const char *__start___trace_bprintk_fmt[];
+extern const char *__stop___trace_bprintk_fmt[];
+
+#define event_trace_printk(ip, fmt, args...) \
+do { \
+ __trace_printk_check_format(fmt, ##args); \
+ tracing_record_cmdline(current); \
+ if (__builtin_constant_p(fmt)) { \
+ static const char *trace_printk_fmt \
+ __attribute__((section("__trace_printk_fmt"))) = \
+ __builtin_constant_p(fmt) ? fmt : NULL; \
+ \
+ __trace_bprintk(ip, trace_printk_fmt, ##args); \
+ } else \
+ __trace_printk(ip, fmt, ##args); \
+} while (0)
+
#endif /* _LINUX_KERNEL_TRACE_H */
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index ca624df..238ea95 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -24,16 +24,6 @@ static DEFINE_MUTEX(event_mutex);
(unsigned long)event < (unsigned long)__stop_ftrace_events; \
event++)
-void event_trace_printk(unsigned long ip, const char *fmt, ...)
-{
- va_list ap;
-
- va_start(ap, fmt);
- tracing_record_cmdline(current);
- trace_vprintk(ip, task_curr_ret_stack(current), fmt, ap);
- va_end(ap);
-}
-
static void ftrace_clear_events(void)
{
struct ftrace_event_call *call = (void *)__start_ftrace_events;
--
1.6.1.3
--
On Thu, 12 Mar 2009 22:37:12 -0400 Steven Rostedt <[email protected]> wrote:
> + static const char *trace_printk_fmt \
> + __attribute__((section("__trace_printk_fmt"))) = \
> + __builtin_constant_p(fmt) ? fmt : NULL; \
hm. Does this put trace_printk_fmt into the __trace_printk_fmt
section, or does it put *trace_printk_fmt in there?
On Thu, 12 Mar 2009, Andrew Morton wrote:
> On Thu, 12 Mar 2009 22:37:12 -0400 Steven Rostedt <[email protected]> wrote:
>
> > + static const char *trace_printk_fmt \
> > + __attribute__((section("__trace_printk_fmt"))) = \
> > + __builtin_constant_p(fmt) ? fmt : NULL; \
>
> hm. Does this put trace_printk_fmt into the __trace_printk_fmt
> section, or does it put *trace_printk_fmt in there?
We save the pointer into that section:
0xc0432100: "my format is to print this number %d\n"
[...]
section <__trace_printk_fmt>:
[...]
0xc0483210: 0xc0432100 (trace_printk_fmt)
It would be difficult to make the string be located in the section when
the caller simply does:
trace_printk("my format is to print this number %d\n", mynum);
Although I guess we could try by using [] = fmt, but the pointer just
seemed easier.
Note, for modules, we have a hash of all strings/pointers. When a module
is loaded, we copy the strings into the hash (if it is not already there)
and keep it loaded, even if the module is removed. This is because the
pointer to this string would still be around inside the trace buffer.
-- Steve
> +#define event_trace_printk(ip, fmt, args...) \
> +do { \
> + __trace_printk_check_format(fmt, ##args); \
> + tracing_record_cmdline(current); \
> + if (__builtin_constant_p(fmt)) { \
> + static const char *trace_printk_fmt \
> + __attribute__((section("__trace_printk_fmt"))) = \
> + __builtin_constant_p(fmt) ? fmt : NULL; \
Why __builtin_constant_p(fmt) evaluate twice?
> + \
> + __trace_bprintk(ip, trace_printk_fmt, ##args); \
> + } else \
> + __trace_printk(ip, fmt, ##args); \
> +} while (0)
On Fri, 13 Mar 2009, KOSAKI Motohiro wrote:
> > +#define event_trace_printk(ip, fmt, args...) \
> > +do { \
> > + __trace_printk_check_format(fmt, ##args); \
> > + tracing_record_cmdline(current); \
> > + if (__builtin_constant_p(fmt)) { \
> > + static const char *trace_printk_fmt \
> > + __attribute__((section("__trace_printk_fmt"))) = \
> > + __builtin_constant_p(fmt) ? fmt : NULL; \
>
> Why __builtin_constant_p(fmt) evaluate twice?
It's explained in another patch. But this was a real PITA. We first tried
this with just the "if (__builtin_return_p(fmt))" but the way gcc works,
it handles the global data assignments before optimizing out condition
logic. Thus we ended up getting errors about can not initialize static
variable with a non constant.
But the ? : operation of the assignment is optimized before the assignment
is made. Thus, if fmt is not constant, then we avoid this warning. Then
during the conditional optimization, gcc will remove that part of the code
altogether.
Thus the double __builtin_constant_p(fmt) is needed twice. Try taking out
one of them and see what happens with:
myfunc(const char *fmt) {
event_trace_printk(fmt);
}
Of course the way this is made, we may not call it that way, but I wanted
to be safe.
-- Steve
>
>
> > + \
> > + __trace_bprintk(ip, trace_printk_fmt, ##args); \
> > + } else \
> > + __trace_printk(ip, fmt, ##args); \
> > +} while (0)
>
>
>
> > > +#define event_trace_printk(ip, fmt, args...) \
> > > +do { \
> > > + __trace_printk_check_format(fmt, ##args); \
> > > + tracing_record_cmdline(current); \
> > > + if (__builtin_constant_p(fmt)) { \
> > > + static const char *trace_printk_fmt \
> > > + __attribute__((section("__trace_printk_fmt"))) = \
> > > + __builtin_constant_p(fmt) ? fmt : NULL; \
> >
> > Why __builtin_constant_p(fmt) evaluate twice?
>
> It's explained in another patch. But this was a real PITA. We first tried
> this with just the "if (__builtin_return_p(fmt))" but the way gcc works,
> it handles the global data assignments before optimizing out condition
> logic. Thus we ended up getting errors about can not initialize static
> variable with a non constant.
>
> But the ? : operation of the assignment is optimized before the assignment
> is made. Thus, if fmt is not constant, then we avoid this warning. Then
> during the conditional optimization, gcc will remove that part of the code
> altogether.
>
> Thus the double __builtin_constant_p(fmt) is needed twice. Try taking out
> one of them and see what happens with:
>
> myfunc(const char *fmt) {
>
> event_trace_printk(fmt);
>
> }
>
> Of course the way this is made, we may not call it that way, but I wanted
> to be safe.
Thanks for kindful explain.
So, I guess many developer feel it's strange.
adding comment is better?
On Fri, 13 Mar 2009, KOSAKI Motohiro wrote:
> > > > +#define event_trace_printk(ip, fmt, args...) \
> > > > +do { \
> > > > + __trace_printk_check_format(fmt, ##args); \
> > > > + tracing_record_cmdline(current); \
> > > > + if (__builtin_constant_p(fmt)) { \
> > > > + static const char *trace_printk_fmt \
> > > > + __attribute__((section("__trace_printk_fmt"))) = \
> > > > + __builtin_constant_p(fmt) ? fmt : NULL; \
> > >
> > > Why __builtin_constant_p(fmt) evaluate twice?
> >
> > It's explained in another patch. But this was a real PITA. We first tried
> > this with just the "if (__builtin_return_p(fmt))" but the way gcc works,
> > it handles the global data assignments before optimizing out condition
> > logic. Thus we ended up getting errors about can not initialize static
> > variable with a non constant.
> >
> > But the ? : operation of the assignment is optimized before the assignment
> > is made. Thus, if fmt is not constant, then we avoid this warning. Then
> > during the conditional optimization, gcc will remove that part of the code
> > altogether.
> >
> > Thus the double __builtin_constant_p(fmt) is needed twice. Try taking out
> > one of them and see what happens with:
> >
> > myfunc(const char *fmt) {
> >
> > event_trace_printk(fmt);
> >
> > }
> >
> > Of course the way this is made, we may not call it that way, but I wanted
> > to be safe.
>
> Thanks for kindful explain.
> So, I guess many developer feel it's strange.
> adding comment is better?
Yeah, I cut and pasted this out from the trace_printk in kernel.h where I
had the comment there. But I think you are right, I probably should copy
that comment here too.
-- Steve
Commit-ID: bdc067582b8b71c7771bab076bbc51569c594fb4
Gitweb: http://git.kernel.org/tip/bdc067582b8b71c7771bab076bbc51569c594fb4
Author: Steven Rostedt <[email protected]>
AuthorDate: Fri, 13 Mar 2009 00:12:52 -0400
Commit: Steven Rostedt <[email protected]>
CommitDate: Fri, 13 Mar 2009 00:15:46 -0400
tracing: add comment for use of double __builtin_consant_p
Impact: documentation
The use of the double __builtin_contant_p checks in the event_trace_printk
can be confusing to developers and reviewers. This patch adds a comment
to explain why it is there.
Requested-by: KOSAKI Motohiro <[email protected]>
LKML-Reference: <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
---
kernel/trace/trace.h | 5 +++++
1 files changed, 5 insertions(+), 0 deletions(-)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 35cfa7b..67595b8 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -776,6 +776,11 @@ extern struct ftrace_event_call __stop_ftrace_events[];
extern const char *__start___trace_bprintk_fmt[];
extern const char *__stop___trace_bprintk_fmt[];
+/*
+ * The double __builtin_constant_p is because gcc will give us an error
+ * if we try to allocate the static variable to fmt if it is not a
+ * constant. Even with the outer if statement optimizing out.
+ */
#define event_trace_printk(ip, fmt, args...) \
do { \
__trace_printk_check_format(fmt, ##args); \