LKML Archive on lore.kernel.org
help / color / mirror / Atom feed
* [PATCH 0/3] ftrace: code consolidation
@ 2008-11-04 4:15 Steven Rostedt
2008-11-04 4:15 ` [PATCH 1/3] ftrace: ftrace_preempt_disable Steven Rostedt
` (2 more replies)
0 siblings, 3 replies; 13+ messages in thread
From: Steven Rostedt @ 2008-11-04 4:15 UTC (permalink / raw)
To: linux-kernel; +Cc: Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Andrew Morton
[ For 2.6.29 ]
The first two patches makes ftrace function calling and other
sensitive tracing use a macro to handle preemption disabling.
This removes a lot of duplicate code that works on preventing
the scheduler from infinite recursion.
The last patch sets an easy way for the user to either use
irq disabling or preemption disabing for the function tracer.
Peter Zijlstra noticed a bit of a trace that was not showing
up due to lost traces caused by interrupts when the function
tracer was running.
Due to the sensitive nature of the function tracer, it can
not allow for recursive tracing, so it needs to disable
recursion while it records the trace. But this also means
that without disabling interrupts, any interrupt that happens
while the trace is happening will be lost from the trace
itself.
-- Steve
^ permalink raw reply [flat|nested] 13+ messages in thread
* [PATCH 1/3] ftrace: ftrace_preempt_disable
2008-11-04 4:15 [PATCH 0/3] ftrace: code consolidation Steven Rostedt
@ 2008-11-04 4:15 ` Steven Rostedt
2008-11-04 9:10 ` Ingo Molnar
2008-11-04 4:15 ` [PATCH 2/3] ftrace: insert in the ftrace_preempt_disable functions Steven Rostedt
2008-11-04 4:15 ` [PATCH 3/3] ftrace: function tracer with irqs disabled Steven Rostedt
2 siblings, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-11-04 4:15 UTC (permalink / raw)
To: linux-kernel
Cc: Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
[-- Attachment #1: ftrace-preempt-disable.patch --]
[-- Type: text/plain, Size: 4269 bytes --]
Parts of the tracer needs to be careful about schedule recursion.
If the NEED_RESCHED flag is set, a preempt_enable will call schedule.
Inside the schedule function, the NEED_RESCHED flag is cleared.
The problem arises when a trace happens in the schedule function but before
NEED_RESCHED is cleared. The race is as follows:
schedule()
>> tracer called
trace_function()
preempt_disable()
[ record trace ]
preempt_enable() <<- here's the issue.
[check NEED_RESCHED]
schedule()
[ Repeat the above, over and over again ]
The naive approach is simply to use preempt_enable_no_schedule instead.
The problem with that approach is that, although we solve the schedule
recursion issue, we now might lose a preemption check when not in the
schedule function.
trace_function()
preempt_disable()
[ record trace ]
[Interrupt comes in and sets NEED_RESCHED]
preempt_enable_no_resched()
[continue without scheduling]
The way ftrace handles this problem is with the following approach:
int resched;
resched = need_resched();
preempt_disable_notrace();
[record trace]
if (resched)
preempt_enable_no_sched_notrace();
else
preempt_enable_notrace();
This may seem like the opposite of what we want. If resched is set
then we call the "no_sched" version?? The reason we do this is because
if NEED_RESCHED is set before we disable preemption, there's two reasons
for that:
1) we are in an atomic code path
2) we are already on our way to the schedule function, and maybe even
in the schedule function, but have yet to clear the flag.
Both the above cases we do not want to schedule.
This solution has already been implemented within the ftrace infrastructure.
But the problem is that it has been implemented several times. This patch
encapsulates this code to two nice functions.
resched = ftrace_preempt_disable();
[ record trace]
ftrace_preempt_enable(resched);
This way the tracers do not need to worry about getting it right.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
kernel/trace/trace.h | 48 ++++++++++++++++++++++++++++++++++++++++++++++++
1 file changed, 48 insertions(+)
Index: linux-tip.git/kernel/trace/trace.h
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.h 2008-11-03 18:09:05.000000000 -0500
+++ linux-tip.git/kernel/trace/trace.h 2008-11-03 18:27:38.000000000 -0500
@@ -419,4 +419,52 @@ enum trace_iterator_flags {
extern struct tracer nop_trace;
+/**
+ * ftrace_preempt_disable - disable preemption scheduler safe
+ *
+ * When tracing can happen inside the scheduler, there exists
+ * cases that the tracing might happen before the need_resched
+ * flag is checked. If this happens and the tracer calls
+ * preempt_enable (after a disable), a schedule might take place
+ * causing an infinite recursion.
+ *
+ * To prevent this, we read the need_recshed flag before
+ * disabling preemption. When we want to enable preemption we
+ * check the flag, if it is set, then we call preempt_enable_no_resched.
+ * Otherwise, we call preempt_enable.
+ *
+ * The rational for doing the above is that if need resched is set
+ * and we have yet to reschedule, we are either in an atomic location
+ * (where we do not need to check for scheduling) or we are inside
+ * the scheduler and do not want to resched.
+ */
+static inline int ftrace_preempt_disable(void)
+{
+ int resched;
+
+ resched = need_resched();
+ preempt_disable_notrace();
+
+ return resched;
+}
+
+/**
+ * ftrace_preempt_enable - enable preemption scheduler safe
+ * @resched: the return value from ftrace_preempt_disable
+ *
+ * This is a scheduler safe way to enable preemption and not miss
+ * any preemption checks. The disabled saved the state of preemption.
+ * If resched is set, then we were either inside an atomic or
+ * are inside the scheduler (we would have already scheduled
+ * otherwise). In this case, we do not want to call normal
+ * preempt_enable, but preempt_enable_no_resched instead.
+ */
+static inline void ftrace_preempt_enable(int resched)
+{
+ if (resched)
+ preempt_enable_no_resched_notrace();
+ else
+ preempt_enable_notrace();
+}
+
#endif /* _LINUX_KERNEL_TRACE_H */
--
^ permalink raw reply [flat|nested] 13+ messages in thread
* [PATCH 2/3] ftrace: insert in the ftrace_preempt_disable functions
2008-11-04 4:15 [PATCH 0/3] ftrace: code consolidation Steven Rostedt
2008-11-04 4:15 ` [PATCH 1/3] ftrace: ftrace_preempt_disable Steven Rostedt
@ 2008-11-04 4:15 ` Steven Rostedt
2008-11-04 4:15 ` [PATCH 3/3] ftrace: function tracer with irqs disabled Steven Rostedt
2 siblings, 0 replies; 13+ messages in thread
From: Steven Rostedt @ 2008-11-04 4:15 UTC (permalink / raw)
To: linux-kernel
Cc: Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
[-- Attachment #1: ftrace-preempt-disable-implement.patch --]
[-- Type: text/plain, Size: 5142 bytes --]
This patch replaces the schedule safe preempt disable code with the
ftrace_preempt_disable and ftrace_preempt_enable safe functions.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
kernel/trace/ring_buffer.c | 27 +++++++++------------------
kernel/trace/trace.c | 8 ++------
kernel/trace/trace_sched_wakeup.c | 13 ++-----------
kernel/trace/trace_stack.c | 8 ++------
4 files changed, 15 insertions(+), 41 deletions(-)
Index: linux-tip.git/kernel/trace/ring_buffer.c
===================================================================
--- linux-tip.git.orig/kernel/trace/ring_buffer.c 2008-11-03 18:49:30.000000000 -0500
+++ linux-tip.git/kernel/trace/ring_buffer.c 2008-11-03 19:05:24.000000000 -0500
@@ -16,6 +16,8 @@
#include <linux/list.h>
#include <linux/fs.h>
+#include "trace.h"
+
/* Up this if you want to test the TIME_EXTENTS and normalization */
#define DEBUG_SHIFT 0
@@ -1122,8 +1124,7 @@ ring_buffer_lock_reserve(struct ring_buf
return NULL;
/* If we are tracing schedule, we don't want to recurse */
- resched = need_resched();
- preempt_disable_notrace();
+ resched = ftrace_preempt_disable();
cpu = raw_smp_processor_id();
@@ -1154,10 +1155,7 @@ ring_buffer_lock_reserve(struct ring_buf
return event;
out:
- if (resched)
- preempt_enable_notrace();
- else
- preempt_enable_notrace();
+ ftrace_preempt_enable(resched);
return NULL;
}
@@ -1199,12 +1197,9 @@ int ring_buffer_unlock_commit(struct rin
/*
* Only the last preempt count needs to restore preemption.
*/
- if (preempt_count() == 1) {
- if (per_cpu(rb_need_resched, cpu))
- preempt_enable_no_resched_notrace();
- else
- preempt_enable_notrace();
- } else
+ if (preempt_count() == 1)
+ ftrace_preempt_enable(per_cpu(rb_need_resched, cpu));
+ else
preempt_enable_no_resched_notrace();
return 0;
@@ -1237,8 +1232,7 @@ int ring_buffer_write(struct ring_buffer
if (atomic_read(&buffer->record_disabled))
return -EBUSY;
- resched = need_resched();
- preempt_disable_notrace();
+ resched = ftrace_preempt_disable();
cpu = raw_smp_processor_id();
@@ -1264,10 +1258,7 @@ int ring_buffer_write(struct ring_buffer
ret = 0;
out:
- if (resched)
- preempt_enable_no_resched_notrace();
- else
- preempt_enable_notrace();
+ ftrace_preempt_enable(resched);
return ret;
}
Index: linux-tip.git/kernel/trace/trace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c 2008-11-03 18:49:37.000000000 -0500
+++ linux-tip.git/kernel/trace/trace.c 2008-11-03 19:05:24.000000000 -0500
@@ -893,8 +893,7 @@ function_trace_call(unsigned long ip, un
return;
pc = preempt_count();
- resched = need_resched();
- preempt_disable_notrace();
+ resched = ftrace_preempt_disable();
local_save_flags(flags);
cpu = raw_smp_processor_id();
data = tr->data[cpu];
@@ -904,10 +903,7 @@ function_trace_call(unsigned long ip, un
trace_function(tr, data, ip, parent_ip, flags, pc);
atomic_dec(&data->disabled);
- if (resched)
- preempt_enable_no_resched_notrace();
- else
- preempt_enable_notrace();
+ ftrace_preempt_enable(resched);
}
static struct ftrace_ops trace_ops __read_mostly =
Index: linux-tip.git/kernel/trace/trace_sched_wakeup.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_sched_wakeup.c 2008-11-03 18:49:30.000000000 -0500
+++ linux-tip.git/kernel/trace/trace_sched_wakeup.c 2008-11-03 19:05:24.000000000 -0500
@@ -50,8 +50,7 @@ wakeup_tracer_call(unsigned long ip, uns
return;
pc = preempt_count();
- resched = need_resched();
- preempt_disable_notrace();
+ resched = ftrace_preempt_disable();
cpu = raw_smp_processor_id();
data = tr->data[cpu];
@@ -81,15 +80,7 @@ wakeup_tracer_call(unsigned long ip, uns
out:
atomic_dec(&data->disabled);
- /*
- * To prevent recursion from the scheduler, if the
- * resched flag was set before we entered, then
- * don't reschedule.
- */
- if (resched)
- preempt_enable_no_resched_notrace();
- else
- preempt_enable_notrace();
+ ftrace_preempt_enable(resched);
}
static struct ftrace_ops trace_ops __read_mostly =
Index: linux-tip.git/kernel/trace/trace_stack.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_stack.c 2008-11-03 18:49:30.000000000 -0500
+++ linux-tip.git/kernel/trace/trace_stack.c 2008-11-03 19:05:24.000000000 -0500
@@ -107,8 +107,7 @@ stack_trace_call(unsigned long ip, unsig
if (unlikely(!ftrace_enabled || stack_trace_disabled))
return;
- resched = need_resched();
- preempt_disable_notrace();
+ resched = ftrace_preempt_disable();
cpu = raw_smp_processor_id();
/* no atomic needed, we only modify this variable by this cpu */
@@ -120,10 +119,7 @@ stack_trace_call(unsigned long ip, unsig
out:
per_cpu(trace_active, cpu)--;
/* prevent recursion in schedule */
- if (resched)
- preempt_enable_no_resched_notrace();
- else
- preempt_enable_notrace();
+ ftrace_preempt_enable(resched);
}
static struct ftrace_ops trace_ops __read_mostly =
--
^ permalink raw reply [flat|nested] 13+ messages in thread
* [PATCH 3/3] ftrace: function tracer with irqs disabled
2008-11-04 4:15 [PATCH 0/3] ftrace: code consolidation Steven Rostedt
2008-11-04 4:15 ` [PATCH 1/3] ftrace: ftrace_preempt_disable Steven Rostedt
2008-11-04 4:15 ` [PATCH 2/3] ftrace: insert in the ftrace_preempt_disable functions Steven Rostedt
@ 2008-11-04 4:15 ` Steven Rostedt
2008-11-04 8:07 ` Ingo Molnar
2 siblings, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-11-04 4:15 UTC (permalink / raw)
To: linux-kernel
Cc: Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
[-- Attachment #1: ftrace-irq-disabled-function-tracing.patch --]
[-- Type: text/plain, Size: 4587 bytes --]
To help with performance, I set the ftracer to not disable interrupts,
and only to disable preemption. If an interrupt occurred, it would not
be traced, because the function tracer protects itself from recursion.
This may be faster, but the trace output might miss some traces.
This patch makes the fuction trace disable interrupts, but it also
adds a runtime feature to disable preemption instead. It does this by
having two different tracer functions. When the function tracer is
enabled, it will check to see which version is requested (irqs disabled
or preemption disabled). Then it will use the corresponding function
as the tracer.
Irq disabling is the default behaviour, but if the user wants better
performance, with the chance of missing traces, then they can choose
the preempt disabled version.
Running hackbench 3 times with the irqs disabled and 3 times with
the preempt disabled function tracer yielded:
tracing type times entries recorded
------------ -------- ----------------
irq disabled 43.393 166433066
43.282 166172618
43.298 166256704
preempt disabled 38.969 159871710
38.943 159972935
39.325 161056510
Average:
irqs disabled: 43.324 166287462
preempt disabled: 39.079 160300385
preempt is 10.8 percent faster than irqs disabled.
I wrote a patch to count function trace recursion and reran hackbench.
With irq disabled: 1,150 times the function tracer did not trace due to
recursion.
with preempt disabled: 5,117,718 times.
The thousand times with irq disabled could be due to NMIs, or simply a case
where it called a function that was not protected by notrace.
But we also see that a large amount of the trace is lost with the
preempt version.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
kernel/trace/trace.c | 40 +++++++++++++++++++++++++++++++++++++++-
kernel/trace/trace.h | 1 +
2 files changed, 40 insertions(+), 1 deletion(-)
Index: linux-tip.git/kernel/trace/trace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c 2008-11-03 19:05:24.000000000 -0500
+++ linux-tip.git/kernel/trace/trace.c 2008-11-03 22:29:17.000000000 -0500
@@ -235,6 +235,7 @@ static const char *trace_options[] = {
"stacktrace",
"sched-tree",
"ftrace_printk",
+ "ftrace_preempt",
NULL
};
@@ -880,7 +881,7 @@ ftrace_special(unsigned long arg1, unsig
#ifdef CONFIG_FUNCTION_TRACER
static void
-function_trace_call(unsigned long ip, unsigned long parent_ip)
+function_trace_call_preempt_only(unsigned long ip, unsigned long parent_ip)
{
struct trace_array *tr = &global_trace;
struct trace_array_cpu *data;
@@ -906,6 +907,37 @@ function_trace_call(unsigned long ip, un
ftrace_preempt_enable(resched);
}
+static void
+function_trace_call(unsigned long ip, unsigned long parent_ip)
+{
+ struct trace_array *tr = &global_trace;
+ struct trace_array_cpu *data;
+ unsigned long flags;
+ long disabled;
+ int cpu;
+ int pc;
+
+ if (unlikely(!ftrace_function_enabled))
+ return;
+
+ /*
+ * Need to use raw, since this must be called before the
+ * recursive protection is performed.
+ */
+ raw_local_irq_save(flags);
+ cpu = raw_smp_processor_id();
+ data = tr->data[cpu];
+ disabled = atomic_inc_return(&data->disabled);
+
+ if (likely(disabled == 1)) {
+ pc = preempt_count();
+ trace_function(tr, data, ip, parent_ip, flags, pc);
+ }
+
+ atomic_dec(&data->disabled);
+ raw_local_irq_restore(flags);
+}
+
static struct ftrace_ops trace_ops __read_mostly =
{
.func = function_trace_call,
@@ -914,6 +946,12 @@ static struct ftrace_ops trace_ops __rea
void tracing_start_function_trace(void)
{
ftrace_function_enabled = 0;
+
+ if (trace_flags & TRACE_ITER_PREEMPTONLY)
+ trace_ops.func = function_trace_call_preempt_only;
+ else
+ trace_ops.func = function_trace_call;
+
register_ftrace_function(&trace_ops);
if (tracer_enabled)
ftrace_function_enabled = 1;
Index: linux-tip.git/kernel/trace/trace.h
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.h 2008-11-03 18:49:38.000000000 -0500
+++ linux-tip.git/kernel/trace/trace.h 2008-11-03 19:15:04.000000000 -0500
@@ -415,6 +415,7 @@ enum trace_iterator_flags {
TRACE_ITER_STACKTRACE = 0x100,
TRACE_ITER_SCHED_TREE = 0x200,
TRACE_ITER_PRINTK = 0x400,
+ TRACE_ITER_PREEMPTONLY = 0x800,
};
extern struct tracer nop_trace;
--
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH 3/3] ftrace: function tracer with irqs disabled
2008-11-04 4:15 ` [PATCH 3/3] ftrace: function tracer with irqs disabled Steven Rostedt
@ 2008-11-04 8:07 ` Ingo Molnar
2008-11-04 8:17 ` Zhang, Yanmin
2008-11-04 9:04 ` Ingo Molnar
0 siblings, 2 replies; 13+ messages in thread
From: Ingo Molnar @ 2008-11-04 8:07 UTC (permalink / raw)
To: Steven Rostedt
Cc: linux-kernel, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
* Steven Rostedt <rostedt@goodmis.org> wrote:
> Running hackbench 3 times with the irqs disabled and 3 times with
> the preempt disabled function tracer yielded:
>
> tracing type times entries recorded
> ------------ -------- ----------------
> irq disabled 43.393 166433066
> 43.282 166172618
> 43.298 166256704
>
> preempt disabled 38.969 159871710
> 38.943 159972935
> 39.325 161056510
your numbers might be correct, but i found that hackbench is not
reliable boot-to-boot - it can easily produce 10% systematic noise or
more. (perhaps depending on how the various socket data structures
happen to be allocated)
the really conclusive way to test this would be to add a hack that
either does preempt disable or irqs disable, depending on a runtime
flag - and then observe how hackbench performance reacts to the value
of that flag.
note that preempt-disable will also produce less trace entries,
especially in very irq-rich workloads. Hence it will be "faster".
Ingo
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH 3/3] ftrace: function tracer with irqs disabled
2008-11-04 8:07 ` Ingo Molnar
@ 2008-11-04 8:17 ` Zhang, Yanmin
2008-11-04 9:04 ` Ingo Molnar
1 sibling, 0 replies; 13+ messages in thread
From: Zhang, Yanmin @ 2008-11-04 8:17 UTC (permalink / raw)
To: Ingo Molnar
Cc: Steven Rostedt, linux-kernel, Thomas Gleixner, Peter Zijlstra,
Andrew Morton, Steven Rostedt
On Tue, 2008-11-04 at 09:07 +0100, Ingo Molnar wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > Running hackbench 3 times with the irqs disabled and 3 times with
> > the preempt disabled function tracer yielded:
> >
> > tracing type times entries recorded
> > ------------ -------- ----------------
> > irq disabled 43.393 166433066
> > 43.282 166172618
> > 43.298 166256704
> >
> > preempt disabled 38.969 159871710
> > 38.943 159972935
> > 39.325 161056510
>
> your numbers might be correct, but i found that hackbench is not
> reliable boot-to-boot
I found that, too. But if I kill most background processes before testing,
hackbench result looks quite stable.
> - it can easily produce 10% systematic noise or
> more. (perhaps depending on how the various socket data structures
> happen to be allocated)
>
> the really conclusive way to test this would be to add a hack that
> either does preempt disable or irqs disable, depending on a runtime
> flag - and then observe how hackbench performance reacts to the value
> of that flag.
>
> note that preempt-disable will also produce less trace entries,
> especially in very irq-rich workloads. Hence it will be "faster".
>
> Ingo
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH 3/3] ftrace: function tracer with irqs disabled
2008-11-04 8:07 ` Ingo Molnar
2008-11-04 8:17 ` Zhang, Yanmin
@ 2008-11-04 9:04 ` Ingo Molnar
2008-11-04 14:44 ` Steven Rostedt
1 sibling, 1 reply; 13+ messages in thread
From: Ingo Molnar @ 2008-11-04 9:04 UTC (permalink / raw)
To: Steven Rostedt
Cc: linux-kernel, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
* Ingo Molnar <mingo@elte.hu> wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > Running hackbench 3 times with the irqs disabled and 3 times with
> > the preempt disabled function tracer yielded:
> >
> > tracing type times entries recorded
> > ------------ -------- ----------------
> > irq disabled 43.393 166433066
> > 43.282 166172618
> > 43.298 166256704
> >
> > preempt disabled 38.969 159871710
> > 38.943 159972935
> > 39.325 161056510
>
> your numbers might be correct, but i found that hackbench is not
> reliable boot-to-boot - it can easily produce 10% systematic noise
> or more. (perhaps depending on how the various socket data
> structures happen to be allocated)
>
> the really conclusive way to test this would be to add a hack that
> either does preempt disable or irqs disable, depending on a runtime
> flag - and then observe how hackbench performance reacts to the
> value of that flag.
... which is exactly what your patch implements :-)
> note that preempt-disable will also produce less trace entries,
> especially in very irq-rich workloads. Hence it will be "faster".
this point still holds. Do we have any good guess about the 'captured
trace events per second' rate in the two cases, are they the same?
Ingo
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH 1/3] ftrace: ftrace_preempt_disable
2008-11-04 4:15 ` [PATCH 1/3] ftrace: ftrace_preempt_disable Steven Rostedt
@ 2008-11-04 9:10 ` Ingo Molnar
2008-11-04 21:48 ` [PATCH] ftrace: ftrace_preempt_disable comment fix Steven Rostedt
0 siblings, 1 reply; 13+ messages in thread
From: Ingo Molnar @ 2008-11-04 9:10 UTC (permalink / raw)
To: Steven Rostedt
Cc: linux-kernel, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
i've applied your 3 patches to tip/tracing/ftrace:
b2a866f: ftrace: function tracer with irqs disabled
182e9f5: ftrace: insert in the ftrace_preempt_disable()/enable() functions
8f0a056: ftrace: introduce ftrace_preempt_disable()/enable()
thanks Steve!
Ingo
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH 3/3] ftrace: function tracer with irqs disabled
2008-11-04 9:04 ` Ingo Molnar
@ 2008-11-04 14:44 ` Steven Rostedt
2008-11-04 16:43 ` Ingo Molnar
0 siblings, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-11-04 14:44 UTC (permalink / raw)
To: Ingo Molnar
Cc: linux-kernel, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
On Tue, 4 Nov 2008, Ingo Molnar wrote:
>
> * Ingo Molnar <mingo@elte.hu> wrote:
>
> > * Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > > Running hackbench 3 times with the irqs disabled and 3 times with
> > > the preempt disabled function tracer yielded:
> > >
> > > tracing type times entries recorded
> > > ------------ -------- ----------------
> > > irq disabled 43.393 166433066
> > > 43.282 166172618
> > > 43.298 166256704
> > >
> > > preempt disabled 38.969 159871710
> > > 38.943 159972935
> > > 39.325 161056510
> >
> > your numbers might be correct, but i found that hackbench is not
> > reliable boot-to-boot - it can easily produce 10% systematic noise
> > or more. (perhaps depending on how the various socket data
> > structures happen to be allocated)
> >
> > the really conclusive way to test this would be to add a hack that
> > either does preempt disable or irqs disable, depending on a runtime
> > flag - and then observe how hackbench performance reacts to the
> > value of that flag.
>
> ... which is exactly what your patch implements :-)
Yep ;-)
Those numbers were done without any reboots in between. I even tried it
several times, randomly picking to use irqs_disabled and preempt_disabled,
and everytime preempt_disabled was around 39 secs, and irqs disabled was
around 43.
>
> > note that preempt-disable will also produce less trace entries,
> > especially in very irq-rich workloads. Hence it will be "faster".
>
> this point still holds. Do we have any good guess about the 'captured
> trace events per second' rate in the two cases, are they the same?
If you look at the end of my change log, I printed stats from a patch I
added that counted the times that ftrace recursed, but did not record.
Those numbers were quite big with preempt_disabled.
>> With irq disabled: 1,150 times the function tracer did not trace due to
>> recursion.
>> with preempt disabled: 5,117,718 times.
When we used the preempt disabled version, we lost 5 million traces, as
suppose to the irq disabled which was only 1,150 traces lost.
Considering that we had 166,256,704 traces total, that 5 million is only
4% lost of traces. Still quite a lot. But again, this is an extreme,
because we are tracing hackbench.
-- Steve
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH 3/3] ftrace: function tracer with irqs disabled
2008-11-04 14:44 ` Steven Rostedt
@ 2008-11-04 16:43 ` Ingo Molnar
0 siblings, 0 replies; 13+ messages in thread
From: Ingo Molnar @ 2008-11-04 16:43 UTC (permalink / raw)
To: Steven Rostedt
Cc: linux-kernel, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
* Steven Rostedt <rostedt@goodmis.org> wrote:
> > > > tracing type times entries recorded
> > > > ------------ -------- ----------------
> > > > irq disabled 43.393 166433066
> > > > 43.282 166172618
> > > > 43.298 166256704
> > > >
> > > > preempt disabled 38.969 159871710
> > > > 38.943 159972935
> > > > 39.325 161056510
> When we used the preempt disabled version, we lost 5 million traces,
> as suppose to the irq disabled which was only 1,150 traces lost.
>
> Considering that we had 166,256,704 traces total, that 5 million is
> only 4% lost of traces. Still quite a lot. But again, this is an
> extreme, because we are tracing hackbench.
there's about 10% difference between the two hackbench results - so
the lack of 5% of the traces could make up for about half of that
overhead.
anyway, that still leaves the other 5% as the _true_ overhead of IRQ
disable.
is there some other workload that does not lose this many trace
entries, making it easier to compare irqs-off against preempt-off?
Ingo
^ permalink raw reply [flat|nested] 13+ messages in thread
* [PATCH] ftrace: ftrace_preempt_disable comment fix
2008-11-04 9:10 ` Ingo Molnar
@ 2008-11-04 21:48 ` Steven Rostedt
2008-11-04 21:52 ` [PATCH v2] " Steven Rostedt
0 siblings, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-11-04 21:48 UTC (permalink / raw)
To: Ingo Molnar
Cc: linux-kernel, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
Impact: comment fixes
Updates to ftrace_preempt_disable comments as recommended to me
by Andrew Morton.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
kernel/trace/trace.h | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)
Index: linux-trace.git/kernel/trace/trace.h
===================================================================
--- linux-trace.git.orig/kernel/trace/trace.h 2008-11-04 16:32:57.000000000 -0500
+++ linux-trace.git/kernel/trace/trace.h 2008-11-04 16:36:11.000000000 -0500
@@ -425,17 +425,17 @@ extern struct tracer nop_trace;
* ftrace_preempt_disable - disable preemption scheduler safe
*
* When tracing can happen inside the scheduler, there exists
- * cases that the tracing might happen before the need_resched
+ * cases where tracing might happen before the need_resched
* flag is checked. If this happens and the tracer calls
* preempt_enable (after a disable), a schedule might take place
* causing an infinite recursion.
*
* To prevent this, we read the need_recshed flag before
- * disabling preemption. When we want to enable preemption we
- * check the flag, if it is set, then we call preempt_enable_no_resched.
- * Otherwise, we call preempt_enable.
+ * disabling preemption and store it. When we want to enable preemption
+ * we check the stored flag, if it is set, then we call
+ * preempt_enable_no_resched. Otherwise, we call preempt_enable.
*
- * The rational for doing the above is that if need resched is set
+ * The rationale for doing the above is that if need resched is set
* and we have yet to reschedule, we are either in an atomic location
* (where we do not need to check for scheduling) or we are inside
* the scheduler and do not want to resched.
^ permalink raw reply [flat|nested] 13+ messages in thread
* [PATCH v2] ftrace: ftrace_preempt_disable comment fix
2008-11-04 21:48 ` [PATCH] ftrace: ftrace_preempt_disable comment fix Steven Rostedt
@ 2008-11-04 21:52 ` Steven Rostedt
2008-11-04 22:05 ` [PATCH v3] " Steven Rostedt
0 siblings, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-11-04 21:52 UTC (permalink / raw)
To: Ingo Molnar
Cc: linux-kernel, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
[
Changes since v1:
Fixed "need_recshed" to "need_resched"
]
Impact: comment fixes
Updates to ftrace_preempt_disable comments as recommended
by Andrew Morton.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
kernel/trace/trace.h | 12 ++++++------
1 file changed, 6 insertions(+), 6 deletions(-)
Index: linux-trace.git/kernel/trace/trace.h
===================================================================
--- linux-trace.git.orig/kernel/trace/trace.h 2008-11-04 16:48:25.000000000 -0500
+++ linux-trace.git/kernel/trace/trace.h 2008-11-04 16:50:30.000000000 -0500
@@ -425,17 +425,17 @@ extern struct tracer nop_trace;
* ftrace_preempt_disable - disable preemption scheduler safe
*
* When tracing can happen inside the scheduler, there exists
- * cases that the tracing might happen before the need_resched
+ * cases where tracing might happen before the need_resched
* flag is checked. If this happens and the tracer calls
* preempt_enable (after a disable), a schedule might take place
* causing an infinite recursion.
*
- * To prevent this, we read the need_recshed flag before
- * disabling preemption. When we want to enable preemption we
- * check the flag, if it is set, then we call preempt_enable_no_resched.
- * Otherwise, we call preempt_enable.
+ * To prevent this, we read the need_resched flag before
+ * disabling preemption and store it. When we want to enable preemption
+ * we check the stored flag, if it is set, then we call
+ * preempt_enable_no_resched. Otherwise, we call preempt_enable.
*
- * The rational for doing the above is that if need resched is set
+ * The rationale for doing the above is that if need resched is set
* and we have yet to reschedule, we are either in an atomic location
* (where we do not need to check for scheduling) or we are inside
* the scheduler and do not want to resched.
^ permalink raw reply [flat|nested] 13+ messages in thread
* [PATCH v3] ftrace: ftrace_preempt_disable comment fix
2008-11-04 21:52 ` [PATCH v2] " Steven Rostedt
@ 2008-11-04 22:05 ` Steven Rostedt
0 siblings, 0 replies; 13+ messages in thread
From: Steven Rostedt @ 2008-11-04 22:05 UTC (permalink / raw)
To: Ingo Molnar
Cc: linux-kernel, Thomas Gleixner, Peter Zijlstra, Andrew Morton,
Steven Rostedt
[
Changes since v2:
Andrew pointed out that "need resched" should be "need_resched".
He's trying to be more critical than Randy Dunlap. ;-)
]
Impact: comment fixes
Updates to ftrace_preempt_disable comments as recommended
by Andrew Morton.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
kernel/trace/trace.h | 12 ++++++------
1 file changed, 6 insertions(+), 6 deletions(-)
Index: linux-trace.git/kernel/trace/trace.h
===================================================================
--- linux-trace.git.orig/kernel/trace/trace.h 2008-11-04 16:53:46.000000000 -0500
+++ linux-trace.git/kernel/trace/trace.h 2008-11-04 17:02:14.000000000 -0500
@@ -425,17 +425,17 @@ extern struct tracer nop_trace;
* ftrace_preempt_disable - disable preemption scheduler safe
*
* When tracing can happen inside the scheduler, there exists
- * cases that the tracing might happen before the need_resched
+ * cases where tracing might happen before the need_resched
* flag is checked. If this happens and the tracer calls
* preempt_enable (after a disable), a schedule might take place
* causing an infinite recursion.
*
- * To prevent this, we read the need_recshed flag before
- * disabling preemption. When we want to enable preemption we
- * check the flag, if it is set, then we call preempt_enable_no_resched.
- * Otherwise, we call preempt_enable.
+ * To prevent this, we read the need_resched flag before
+ * disabling preemption and store it. When we want to enable preemption
+ * we check the stored flag, if it is set, then we call
+ * preempt_enable_no_resched. Otherwise, we call preempt_enable.
*
- * The rational for doing the above is that if need resched is set
+ * The rationale for doing the above is that if need_resched is set
* and we have yet to reschedule, we are either in an atomic location
* (where we do not need to check for scheduling) or we are inside
* the scheduler and do not want to resched.
^ permalink raw reply [flat|nested] 13+ messages in thread
end of thread, other threads:[~2008-11-04 22:05 UTC | newest]
Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2008-11-04 4:15 [PATCH 0/3] ftrace: code consolidation Steven Rostedt
2008-11-04 4:15 ` [PATCH 1/3] ftrace: ftrace_preempt_disable Steven Rostedt
2008-11-04 9:10 ` Ingo Molnar
2008-11-04 21:48 ` [PATCH] ftrace: ftrace_preempt_disable comment fix Steven Rostedt
2008-11-04 21:52 ` [PATCH v2] " Steven Rostedt
2008-11-04 22:05 ` [PATCH v3] " Steven Rostedt
2008-11-04 4:15 ` [PATCH 2/3] ftrace: insert in the ftrace_preempt_disable functions Steven Rostedt
2008-11-04 4:15 ` [PATCH 3/3] ftrace: function tracer with irqs disabled Steven Rostedt
2008-11-04 8:07 ` Ingo Molnar
2008-11-04 8:17 ` Zhang, Yanmin
2008-11-04 9:04 ` Ingo Molnar
2008-11-04 14:44 ` Steven Rostedt
2008-11-04 16:43 ` Ingo Molnar
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).