[RFC PATCH] tracing: Don't call wakeup() when committing the event

[RFC PATCH] tracing: Don't call wakeup() when committing the event

[Vaibhav Nagarnaik]

In using syscall tracing by concurrent processes, the wakeup() that is
called in the event commit function causes contention on the spin lock
of the waitqueue. I enabled sys_enter_getuid and sys_exit_getuid
tracepoints, and by running getuid_microbench from autotest in parallel
I found that the contention causes exponential latency increase in the
tracing path.

The autotest binary getuid_microbench calls getuid() in a tight loop for
the given number of iterations and measures the average time required to
complete a single invocation of syscall.

The patch here points to the problem and provides a naive solution to
start the discussion. It is not intended to be a definitive solution.

In the following example, the script enables the sys_enter_getuid and
sys_exit_getuid tracepoints and runs the getuid_microbench in parallel
with the given number of processes. The output clearly shows the latency
increase caused by contentions.

$ ~/getuid.sh 1
1000000 calls in 0.720974253 s (720.974253 ns/call)

$ ~/getuid.sh 2
1000000 calls in 1.166457554 s (1166.457554 ns/call)
1000000 calls in 1.168933765 s (1168.933765 ns/call)

$ ~/getuid.sh 3
1000000 calls in 1.783827516 s (1783.827516 ns/call)
1000000 calls in 1.795553270 s (1795.553270 ns/call)
1000000 calls in 1.796493376 s (1796.493376 ns/call)

$ ~/getuid.sh 4
1000000 calls in 4.483041796 s (4483.041796 ns/call)
1000000 calls in 4.484165388 s (4484.165388 ns/call)
1000000 calls in 4.484850762 s (4484.850762 ns/call)
1000000 calls in 4.485643576 s (4485.643576 ns/call)

$ ~/getuid.sh 5
1000000 calls in 6.497521653 s (6497.521653 ns/call)
1000000 calls in 6.502000236 s (6502.000236 ns/call)
1000000 calls in 6.501709115 s (6501.709115 ns/call)
1000000 calls in 6.502124100 s (6502.124100 ns/call)
1000000 calls in 6.502936358 s (6502.936358 ns/call)

After the patch, the latencies scale well and are exactly as expected.
$ ~/getuid.sh 1
1000000 calls in 0.626811320 s (626.811320 ns/call)

$ ~/getuid.sh 2
1000000 calls in 0.616566144 s (616.566144 ns/call)
1000000 calls in 0.622712754 s (622.712754 ns/call)

$ ~/getuid.sh 3
1000000 calls in 0.602886676 s (602.886676 ns/call)
1000000 calls in 0.612168691 s (612.168691 ns/call)
1000000 calls in 0.623516009 s (623.516009 ns/call)

$ ~/getuid.sh 4
1000000 calls in 0.614037455 s (614.037455 ns/call)
1000000 calls in 0.615070842 s (615.070842 ns/call)
1000000 calls in 0.615051941 s (615.051941 ns/call)
1000000 calls in 0.621556902 s (621.556902 ns/call)

$ ~/getuid.sh 5
1000000 calls in 0.605297117 s (605.297117 ns/call)
1000000 calls in 0.609545095 s (609.545095 ns/call)
1000000 calls in 0.610305369 s (610.305369 ns/call)
1000000 calls in 0.614056014 s (614.056014 ns/call)
1000000 calls in 0.622048279 s (622.048279 ns/call)

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 kernel/trace/trace_syscalls.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
index ee7b5a0..3eeac29 100644
--- a/kernel/trace/trace_syscalls.c
+++ b/kernel/trace/trace_syscalls.c
@@ -328,7 +328,7 @@ void ftrace_syscall_enter(void *ignore, struct pt_regs *regs, long id)
 
 	if (!filter_current_check_discard(buffer, sys_data->enter_event,
 					  entry, event))
-		trace_current_buffer_unlock_commit(buffer, event, 0, 0);
+		trace_nowake_buffer_unlock_commit(buffer, event, 0, 0);
 }
 
 void ftrace_syscall_exit(void *ignore, struct pt_regs *regs, long ret)
@@ -360,7 +360,7 @@ void ftrace_syscall_exit(void *ignore, struct pt_regs *regs, long ret)
 
 	if (!filter_current_check_discard(buffer, sys_data->exit_event,
 					  entry, event))
-		trace_current_buffer_unlock_commit(buffer, event, 0, 0);
+		trace_nowake_buffer_unlock_commit(buffer, event, 0, 0);
 }
 
 int reg_event_syscall_enter(struct ftrace_event_call *call)
-- 
1.7.3.1

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Frederic Weisbecker]

On Tue, May 03, 2011 at 02:03:36PM -0700, Vaibhav Nagarnaik wrote:
> In using syscall tracing by concurrent processes, the wakeup() that is
> called in the event commit function causes contention on the spin lock
> of the waitqueue. I enabled sys_enter_getuid and sys_exit_getuid
> tracepoints, and by running getuid_microbench from autotest in parallel
> I found that the contention causes exponential latency increase in the
> tracing path.
> 
> The autotest binary getuid_microbench calls getuid() in a tight loop for
> the given number of iterations and measures the average time required to
> complete a single invocation of syscall.
> 
> The patch here points to the problem and provides a naive solution to
> start the discussion. It is not intended to be a definitive solution.

Right, so another solution could be to have per cpu waitqueues for
the per_cpu trace_pipe/trace_pipe_raw files, and one big for the main
trace_pipe file.

That involves two wake_up() calls but then it scales and you keep
the awakening.

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Vaibhav Nagarnaik]

On Tue, May 3, 2011 at 2:41 PM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> On Tue, May 03, 2011 at 02:03:36PM -0700, Vaibhav Nagarnaik wrote:
>> In using syscall tracing by concurrent processes, the wakeup() that is
>> called in the event commit function causes contention on the spin lock
>> of the waitqueue. I enabled sys_enter_getuid and sys_exit_getuid
>> tracepoints, and by running getuid_microbench from autotest in parallel
>> I found that the contention causes exponential latency increase in the
>> tracing path.
>>
>> The autotest binary getuid_microbench calls getuid() in a tight loop for
>> the given number of iterations and measures the average time required to
>> complete a single invocation of syscall.
>>
>> The patch here points to the problem and provides a naive solution to
>> start the discussion. It is not intended to be a definitive solution.
>
> Right, so another solution could be to have per cpu waitqueues for
> the per_cpu trace_pipe/trace_pipe_raw files, and one big for the main
> trace_pipe file.

That could be another way. But if there is still *one* common waitqueue for
the main trace file, we are still going to get contention on waking up that
common waitqueue.

Unless I am missing something, can you explain why there won't be contention
in your suggested solution?

>
> That involves two wake_up() calls but then it scales and you keep
> the awakening.
>

Vaibhav Nagarnaik

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Frederic Weisbecker]

On Tue, May 03, 2011 at 02:56:11PM -0700, Vaibhav Nagarnaik wrote:
> On Tue, May 3, 2011 at 2:41 PM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> > On Tue, May 03, 2011 at 02:03:36PM -0700, Vaibhav Nagarnaik wrote:
> >> In using syscall tracing by concurrent processes, the wakeup() that is
> >> called in the event commit function causes contention on the spin lock
> >> of the waitqueue. I enabled sys_enter_getuid and sys_exit_getuid
> >> tracepoints, and by running getuid_microbench from autotest in parallel
> >> I found that the contention causes exponential latency increase in the
> >> tracing path.
> >>
> >> The autotest binary getuid_microbench calls getuid() in a tight loop for
> >> the given number of iterations and measures the average time required to
> >> complete a single invocation of syscall.
> >>
> >> The patch here points to the problem and provides a naive solution to
> >> start the discussion. It is not intended to be a definitive solution.
> >
> > Right, so another solution could be to have per cpu waitqueues for
> > the per_cpu trace_pipe/trace_pipe_raw files, and one big for the main
> > trace_pipe file.
> 
> That could be another way. But if there is still *one* common waitqueue for
> the main trace file, we are still going to get contention on waking up that
> common waitqueue.
> 
> Unless I am missing something, can you explain why there won't be contention
> in your suggested solution?

Ah right, I missed that.

I wonder if we should have a lite version of wake_up() that checks
if the list of waiters is empty before locking the queue.
After all we don't care much about tight races for tracing.

Hm?

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Steven Rostedt]

On Wed, 2011-05-04 at 00:09 +0200, Frederic Weisbecker wrote:

> I wonder if we should have a lite version of wake_up() that checks
> if the list of waiters is empty before locking the queue.
> After all we don't care much about tight races for tracing.

Since tracing is a special case here, we probably could get away to just
do it ourselves. That is, have our own flag that determines if we should
wakeup or not.

-- Steve

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Frederic Weisbecker]

On Tue, May 03, 2011 at 06:47:32PM -0400, Steven Rostedt wrote:
> On Wed, 2011-05-04 at 00:09 +0200, Frederic Weisbecker wrote:
> 
> > I wonder if we should have a lite version of wake_up() that checks
> > if the list of waiters is empty before locking the queue.
> > After all we don't care much about tight races for tracing.
> 
> Since tracing is a special case here, we probably could get away to just
> do it ourselves. That is, have our own flag that determines if we should
> wakeup or not.

Yep, agreed.

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Vaibhav Nagarnaik]

On Tue, May 3, 2011 at 4:08 PM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> On Tue, May 03, 2011 at 06:47:32PM -0400, Steven Rostedt wrote:
>> On Wed, 2011-05-04 at 00:09 +0200, Frederic Weisbecker wrote:
>>
>> > I wonder if we should have a lite version of wake_up() that checks
>> > if the list of waiters is empty before locking the queue.
>> > After all we don't care much about tight races for tracing.
>>
>> Since tracing is a special case here, we probably could get away to just
>> do it ourselves. That is, have our own flag that determines if we should
>> wakeup or not.
>
> Yep, agreed.
>
How about this? Check if the waitqueue is active and if true, operate on the
trace_wait queue.

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 06f4458..e03ee24 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -353,7 +353,7 @@ void trace_wake_up(void)
 {
 	int cpu;

-	if (trace_flags & TRACE_ITER_BLOCK)
+	if (trace_flags & TRACE_ITER_BLOCK || !waitqueue_active(&trace_wait))
 		return;
 	/*
 	 * The runqueue_is_locked() can fail, but this is the best we

Vaibhav Nagarnaik

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Frederic Weisbecker]

On Tue, May 03, 2011 at 04:27:22PM -0700, Vaibhav Nagarnaik wrote:
> On Tue, May 3, 2011 at 4:08 PM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> > On Tue, May 03, 2011 at 06:47:32PM -0400, Steven Rostedt wrote:
> >> On Wed, 2011-05-04 at 00:09 +0200, Frederic Weisbecker wrote:
> >>
> >> > I wonder if we should have a lite version of wake_up() that checks
> >> > if the list of waiters is empty before locking the queue.
> >> > After all we don't care much about tight races for tracing.
> >>
> >> Since tracing is a special case here, we probably could get away to just
> >> do it ourselves. That is, have our own flag that determines if we should
> >> wakeup or not.
> >
> > Yep, agreed.
> >
> How about this? Check if the waitqueue is active and if true, operate on the
> trace_wait queue.
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 06f4458..e03ee24 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -353,7 +353,7 @@ void trace_wake_up(void)
>  {
>  	int cpu;
> 
> -	if (trace_flags & TRACE_ITER_BLOCK)
> +	if (trace_flags & TRACE_ITER_BLOCK || !waitqueue_active(&trace_wait))
>  		return;
>  	/*
>  	 * The runqueue_is_locked() can fail, but this is the best we
> 

Hehe, seems it should work :)

Acked-by: Frederic Weisbecker <fweisbec@gmail.com>

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Vaibhav Nagarnaik]

On Tue, May 3, 2011 at 3:47 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 2011-05-04 at 00:09 +0200, Frederic Weisbecker wrote:
>
>> I wonder if we should have a lite version of wake_up() that checks
>> if the list of waiters is empty before locking the queue.
>> After all we don't care much about tight races for tracing.
>
> Since tracing is a special case here, we probably could get away to just
> do it ourselves. That is, have our own flag that determines if we should
> wakeup or not.

I had another question looking at the implementation of
ftrace_raw_event_##call in include/trace/ftrace.h.

All the raw trace events are traced through this function and it does not
call wakeup() on the trace_wait waitqueue. How do the current implementations
of readers handle tracing anything other than syscalls? Since wakeup() will
never get called, do the readers never poll on the waitqueue?

I understand from the logs that due to hard lockups while tracing sched
events, this new API was added. But does this mean that the tracing waitqueues
functionality is not being used by the readers?


>
> -- Steve
>
>
>

Vaibhav Nagarnaik

Re: [RFC PATCH] tracing: Don't call wakeup() when committing the event

[Vaibhav Nagarnaik]

On Tue, May 3, 2011 at 4:35 PM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> On Tue, May 03, 2011 at 04:27:22PM -0700, Vaibhav Nagarnaik wrote:
>> How about this? Check if the waitqueue is active and if true, operate on the
>> trace_wait queue.
>>
>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>> index 06f4458..e03ee24 100644
>> --- a/kernel/trace/trace.c
>> +++ b/kernel/trace/trace.c
>> @@ -353,7 +353,7 @@ void trace_wake_up(void)
>>  {
>>       int cpu;
>>
>> -     if (trace_flags & TRACE_ITER_BLOCK)
>> +     if (trace_flags & TRACE_ITER_BLOCK || !waitqueue_active(&trace_wait))
>>               return;
>>       /*
>>        * The runqueue_is_locked() can fail, but this is the best we
>>
>
> Hehe, seems it should work :)
>
> Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
>
Thanks for reviewing the change. I have sent an updated patch with a better
commit message and your Ack.

Vaibhav Nagarnaik