Steven,
I have workloads for oprofile that trigger warnings like this:
------------[ cut here ]------------
WARNING: at /dev/shm/.source/linux/kernel/trace/ring_buffer.c:2289 rb_advance_reader+0x2e/0xc5()
Hardware name: Anaheim
Modules linked in:
Pid: 29, comm: events/2 Tainted: G W 2.6.31-rc3-oprofile-x86_64-standard-00059-g5050dc2 #1
Call Trace:
[<ffffffff8106776f>] ? rb_advance_reader+0x2e/0xc5
[<ffffffff81039ffe>] warn_slowpath_common+0x77/0x8f
[<ffffffff8103a025>] warn_slowpath_null+0xf/0x11
[<ffffffff8106776f>] rb_advance_reader+0x2e/0xc5
[<ffffffff81068bda>] ring_buffer_consume+0xa0/0xd2
[<ffffffff81326933>] op_cpu_buffer_read_entry+0x21/0x9e
[<ffffffff810be3af>] ? __find_get_block+0x4b/0x165
[<ffffffff8132749b>] sync_buffer+0xa5/0x401
[<ffffffff810be3af>] ? __find_get_block+0x4b/0x165
[<ffffffff81326c1b>] ? wq_sync_buffer+0x0/0x78
[<ffffffff81326c76>] wq_sync_buffer+0x5b/0x78
[<ffffffff8104aa30>] worker_thread+0x113/0x1ac
[<ffffffff8104dd95>] ? autoremove_wake_function+0x0/0x38
[<ffffffff8104a91d>] ? worker_thread+0x0/0x1ac
[<ffffffff8104dc9a>] kthread+0x88/0x92
[<ffffffff8100bdba>] child_rip+0xa/0x20
[<ffffffff8104dc12>] ? kthread+0x0/0x92
[<ffffffff8100bdb0>] ? child_rip+0x0/0x20
---[ end trace f561c0a58fcc89bd ]---
I am wondering when this may happen. It seems the following code in
rb_get_reader_page() triggers this:
/* check if we caught up to the tail */
reader = NULL;
if (cpu_buffer->commit_page == cpu_buffer->reader_page)
goto out;
It is very hard to find out the conditions for equal commit and reader
pages.
Maybe you have any idea or could shortly explain the use of head,
tail, commit and reader page pointers? When an overrun happens?
(... or point me to some documentation.)
Thanks,
-Robert
--
Advanced Micro Devices, Inc.
Operating System Research Center
email: [email protected]
Hi Robert,
On Mon, 27 Jul 2009, Robert Richter wrote:
> Steven,
>
> I have workloads for oprofile that trigger warnings like this:
>
> ------------[ cut here ]------------
> WARNING: at /dev/shm/.source/linux/kernel/trace/ring_buffer.c:2289 rb_advance_reader+0x2e/0xc5()
So this is this code:
reader = rb_get_reader_page(cpu_buffer);
/* This function should not be called when buffer is empty */
if (RB_WARN_ON(cpu_buffer, !reader))
return;
> Hardware name: Anaheim
> Modules linked in:
> Pid: 29, comm: events/2 Tainted: G W 2.6.31-rc3-oprofile-x86_64-standard-00059-g5050dc2 #1
> Call Trace:
> [<ffffffff8106776f>] ? rb_advance_reader+0x2e/0xc5
> [<ffffffff81039ffe>] warn_slowpath_common+0x77/0x8f
> [<ffffffff8103a025>] warn_slowpath_null+0xf/0x11
> [<ffffffff8106776f>] rb_advance_reader+0x2e/0xc5
> [<ffffffff81068bda>] ring_buffer_consume+0xa0/0xd2
> [<ffffffff81326933>] op_cpu_buffer_read_entry+0x21/0x9e
> [<ffffffff810be3af>] ? __find_get_block+0x4b/0x165
> [<ffffffff8132749b>] sync_buffer+0xa5/0x401
> [<ffffffff810be3af>] ? __find_get_block+0x4b/0x165
> [<ffffffff81326c1b>] ? wq_sync_buffer+0x0/0x78
> [<ffffffff81326c76>] wq_sync_buffer+0x5b/0x78
> [<ffffffff8104aa30>] worker_thread+0x113/0x1ac
> [<ffffffff8104dd95>] ? autoremove_wake_function+0x0/0x38
> [<ffffffff8104a91d>] ? worker_thread+0x0/0x1ac
> [<ffffffff8104dc9a>] kthread+0x88/0x92
> [<ffffffff8100bdba>] child_rip+0xa/0x20
> [<ffffffff8104dc12>] ? kthread+0x0/0x92
> [<ffffffff8100bdb0>] ? child_rip+0x0/0x20
> ---[ end trace f561c0a58fcc89bd ]---
>
> I am wondering when this may happen. It seems the following code in
> rb_get_reader_page() triggers this:
>
> /* check if we caught up to the tail */
> reader = NULL;
> if (cpu_buffer->commit_page == cpu_buffer->reader_page)
> goto out;
So you see that rb_advance_reader is called while the commit_page is the
same as the reader page? Which means that there's nothing left in the
buffer. This is interesting? Because in ring_buffer_consume we have:
event = rb_buffer_peek(buffer, cpu, ts);
if (!event)
goto out_unlock;
rb_advance_reader(cpu_buffer);
Where rb_buffer_peak checks to see if there's anything in the buffer, if
there is, it returns an event, but does not increment the pointer. What
you see is that we got an event, but then the event went away? Is there
something else that could have read this buffer? You are not reading this
from an NMI or something?
Or do you see any other WARN ONs happening? This would cause the locks to
not be taken for reads.
>
> It is very hard to find out the conditions for equal commit and reader
> pages.
>
> Maybe you have any idea or could shortly explain the use of head,
> tail, commit and reader page pointers? When an overrun happens?
> (... or point me to some documentation.)
OK, I'll do it here, but there is documentation already posted, but I'm
too lazy to search for it (writing it is easier ;-)
The ring buffer is made up of 3 pointers. New writes go to the tail
pointer, and new reads, read from the head pointer.
To prevent races with the writer over writing the reader as the reader is
reading the buffer, the reader is given a separate page. When a read wants
to read the buffer, it swaps a blank page with the "head" page of the
buffer. If there is less then a page worth of data in the ring buffer, the
writer will also be on this page. When the write goes to the next page, it
simply moves back into the ring buffer because the next pointer of the
reader page points back into the ring buffer.
Since the write side is mosly lockless (and is totally lockless for the 32
queue), when a writer wants data it must first reserve space in the ring
buffer. Then the writer may copy directly into the ring buffer, and then
it "commits" it. This is where the commit pointer comes from. The
reserving of space from the ring buffer moves the tail. But the commit
pointer points to the last committed entry is. That is, data that the
reader can read. We can not allow a reader to read part of the ring buffer
that the writer has yet to write to.
When the writer is done and commits the changes, the commit pointer goes
to the end of that entry. This allows interrupts to preempt another
writer, but it will not overwrite the data of the preempted writer. A
write that interrupted another write will reserve data at the tail after
the data that was already reserved.
The head, tail and commit pointers are made up in two. There is a page and
index pointer. The page pointer points to the page and the index points to
the index in that page. A commit page pointer points to the page that
holds the commit and the commit index pointer points to the index in that
page.
To make things easier, if the writer wraps the ring buffer and comes back
to the head page, it will move the entire page.
The code you pointed out that shows the the reader == commit page, means
that there was less than a page worth of data when the reader swapped the
page from the buffer and the writer (or at least the commit page) was on
the page that was swapped. Thus the commit page is the same as the reader
page.
The conditions before hand checked to see if there was data left on the
page to read. If there was, then it would return the reader page, but when
the reader index == the commit index it means that there is no more data
left to read on that page and returns NULL.
This is strange because it is the same code that the peak uses, but the
previous call found something?
-- Steve
Steve,
thanks for your detailed description. I found the root cause for the
warning, a patch is on the way. See also my comments below.
On 27.07.09 17:24:29, Steven Rostedt wrote:
>
> Hi Robert,
>
>
> On Mon, 27 Jul 2009, Robert Richter wrote:
>
> > Steven,
> >
> > I have workloads for oprofile that trigger warnings like this:
> >
> > ------------[ cut here ]------------
> > WARNING: at /dev/shm/.source/linux/kernel/trace/ring_buffer.c:2289 rb_advance_reader+0x2e/0xc5()
>
> So this is this code:
>
> reader = rb_get_reader_page(cpu_buffer);
>
> /* This function should not be called when buffer is empty */
> if (RB_WARN_ON(cpu_buffer, !reader))
> return;
>
>
> > Hardware name: Anaheim
> > Modules linked in:
> > Pid: 29, comm: events/2 Tainted: G W 2.6.31-rc3-oprofile-x86_64-standard-00059-g5050dc2 #1
> > Call Trace:
> > [<ffffffff8106776f>] ? rb_advance_reader+0x2e/0xc5
> > [<ffffffff81039ffe>] warn_slowpath_common+0x77/0x8f
> > [<ffffffff8103a025>] warn_slowpath_null+0xf/0x11
> > [<ffffffff8106776f>] rb_advance_reader+0x2e/0xc5
> > [<ffffffff81068bda>] ring_buffer_consume+0xa0/0xd2
> > [<ffffffff81326933>] op_cpu_buffer_read_entry+0x21/0x9e
> > [<ffffffff810be3af>] ? __find_get_block+0x4b/0x165
> > [<ffffffff8132749b>] sync_buffer+0xa5/0x401
> > [<ffffffff810be3af>] ? __find_get_block+0x4b/0x165
> > [<ffffffff81326c1b>] ? wq_sync_buffer+0x0/0x78
> > [<ffffffff81326c76>] wq_sync_buffer+0x5b/0x78
> > [<ffffffff8104aa30>] worker_thread+0x113/0x1ac
> > [<ffffffff8104dd95>] ? autoremove_wake_function+0x0/0x38
> > [<ffffffff8104a91d>] ? worker_thread+0x0/0x1ac
> > [<ffffffff8104dc9a>] kthread+0x88/0x92
> > [<ffffffff8100bdba>] child_rip+0xa/0x20
> > [<ffffffff8104dc12>] ? kthread+0x0/0x92
> > [<ffffffff8100bdb0>] ? child_rip+0x0/0x20
> > ---[ end trace f561c0a58fcc89bd ]---
> >
> > I am wondering when this may happen. It seems the following code in
> > rb_get_reader_page() triggers this:
> >
> > /* check if we caught up to the tail */
> > reader = NULL;
> > if (cpu_buffer->commit_page == cpu_buffer->reader_page)
> > goto out;
>
> So you see that rb_advance_reader is called while the commit_page is the
> same as the reader page? Which means that there's nothing left in the
> buffer. This is interesting? Because in ring_buffer_consume we have:
>
> event = rb_buffer_peek(buffer, cpu, ts);
> if (!event)
> goto out_unlock;
>
> rb_advance_reader(cpu_buffer);
>
> Where rb_buffer_peak checks to see if there's anything in the buffer, if
> there is, it returns an event, but does not increment the pointer. What
> you see is that we got an event, but then the event went away? Is there
> something else that could have read this buffer? You are not reading this
> from an NMI or something?
There was only one thread reading from the buffer. Writes did go
always to the _other_ write buffer, and the buffer switch was only
made by the reading thread. So there is no one else using the buffers.
>
> Or do you see any other WARN ONs happening? This would cause the locks to
> not be taken for reads.
No, also no other warnings, also with lockdep enabled.
>
>
> >
> > It is very hard to find out the conditions for equal commit and reader
> > pages.
> >
> > Maybe you have any idea or could shortly explain the use of head,
> > tail, commit and reader page pointers? When an overrun happens?
> > (... or point me to some documentation.)
>
> OK, I'll do it here, but there is documentation already posted, but I'm
> too lazy to search for it (writing it is easier ;-)
>
> The ring buffer is made up of 3 pointers. New writes go to the tail
> pointer, and new reads, read from the head pointer.
>
> To prevent races with the writer over writing the reader as the reader is
> reading the buffer, the reader is given a separate page. When a read wants
> to read the buffer, it swaps a blank page with the "head" page of the
> buffer. If there is less then a page worth of data in the ring buffer, the
> writer will also be on this page. When the write goes to the next page, it
> simply moves back into the ring buffer because the next pointer of the
> reader page points back into the ring buffer.
>
> Since the write side is mosly lockless (and is totally lockless for the 32
> queue), when a writer wants data it must first reserve space in the ring
> buffer. Then the writer may copy directly into the ring buffer, and then
> it "commits" it. This is where the commit pointer comes from. The
> reserving of space from the ring buffer moves the tail. But the commit
> pointer points to the last committed entry is. That is, data that the
> reader can read. We can not allow a reader to read part of the ring buffer
> that the writer has yet to write to.
>
> When the writer is done and commits the changes, the commit pointer goes
> to the end of that entry. This allows interrupts to preempt another
> writer, but it will not overwrite the data of the preempted writer. A
> write that interrupted another write will reserve data at the tail after
> the data that was already reserved.
>
> The head, tail and commit pointers are made up in two. There is a page and
> index pointer. The page pointer points to the page and the index points to
> the index in that page. A commit page pointer points to the page that
> holds the commit and the commit index pointer points to the index in that
> page.
>
> To make things easier, if the writer wraps the ring buffer and comes back
> to the head page, it will move the entire page.
>
> The code you pointed out that shows the the reader == commit page, means
> that there was less than a page worth of data when the reader swapped the
> page from the buffer and the writer (or at least the commit page) was on
> the page that was swapped. Thus the commit page is the same as the reader
> page.
>
> The conditions before hand checked to see if there was data left on the
> page to read. If there was, then it would return the reader page, but when
> the reader index == the commit index it means that there is no more data
> left to read on that page and returns NULL.
>
> This is strange because it is the same code that the peak uses, but the
> previous call found something?
What I finally found out: rb_buffer_peek() was returning an event and
simultaneously advancing the reader. This is in case of padding events
and caused the 2nd rb_advance_reader() call to warn.
A patch is out now. I have a 2nd patch sent out too with some little
code rework.
Steve, thanks for your support.
-Robert
--
Advanced Micro Devices, Inc.
Operating System Research Center
email: [email protected]
When calling rb_buffer_peek() from ring_buffer_consume() and a padding
event is returned, the function rb_advance_reader() is called
twice. This may lead to missing samples or under high workloads to the
warning below. This patch fixes this. If a padding event is returned
by rb_buffer_peek() it will be consumed by the calling function now.
Also, I simplified some code in ring_buffer_consume().
------------[ cut here ]------------
WARNING: at /dev/shm/.source/linux/kernel/trace/ring_buffer.c:2289 rb_advance_reader+0x2e/0xc5()
Hardware name: Anaheim
Modules linked in:
Pid: 29, comm: events/2 Tainted: G W 2.6.31-rc3-oprofile-x86_64-standard-00059-g5050dc2 #1
Call Trace:
[<ffffffff8106776f>] ? rb_advance_reader+0x2e/0xc5
[<ffffffff81039ffe>] warn_slowpath_common+0x77/0x8f
[<ffffffff8103a025>] warn_slowpath_null+0xf/0x11
[<ffffffff8106776f>] rb_advance_reader+0x2e/0xc5
[<ffffffff81068bda>] ring_buffer_consume+0xa0/0xd2
[<ffffffff81326933>] op_cpu_buffer_read_entry+0x21/0x9e
[<ffffffff810be3af>] ? __find_get_block+0x4b/0x165
[<ffffffff8132749b>] sync_buffer+0xa5/0x401
[<ffffffff810be3af>] ? __find_get_block+0x4b/0x165
[<ffffffff81326c1b>] ? wq_sync_buffer+0x0/0x78
[<ffffffff81326c76>] wq_sync_buffer+0x5b/0x78
[<ffffffff8104aa30>] worker_thread+0x113/0x1ac
[<ffffffff8104dd95>] ? autoremove_wake_function+0x0/0x38
[<ffffffff8104a91d>] ? worker_thread+0x0/0x1ac
[<ffffffff8104dc9a>] kthread+0x88/0x92
[<ffffffff8100bdba>] child_rip+0xa/0x20
[<ffffffff8104dc12>] ? kthread+0x0/0x92
[<ffffffff8100bdb0>] ? child_rip+0x0/0x20
---[ end trace f561c0a58fcc89bd ]---
Cc: Steven Rostedt <[email protected]>
Cc: <[email protected]>
Signed-off-by: Robert Richter <[email protected]>
---
kernel/trace/ring_buffer.c | 10 ++++------
1 files changed, 4 insertions(+), 6 deletions(-)
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index bf27bb7..6eb8b97 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2383,7 +2383,6 @@ rb_buffer_peek(struct ring_buffer *buffer, int cpu, u64 *ts)
* the box. Return the padding, and we will release
* the current locks, and try again.
*/
- rb_advance_reader(cpu_buffer);
return event;
case RINGBUF_TYPE_TIME_EXTEND:
@@ -2519,6 +2518,8 @@ ring_buffer_peek(struct ring_buffer *buffer, int cpu, u64 *ts)
if (dolock)
spin_lock(&cpu_buffer->reader_lock);
event = rb_buffer_peek(buffer, cpu, ts);
+ if (event && event->type_len == RINGBUF_TYPE_PADDING)
+ rb_advance_reader(cpu_buffer);
if (dolock)
spin_unlock(&cpu_buffer->reader_lock);
local_irq_restore(flags);
@@ -2590,12 +2591,9 @@ ring_buffer_consume(struct ring_buffer *buffer, int cpu, u64 *ts)
spin_lock(&cpu_buffer->reader_lock);
event = rb_buffer_peek(buffer, cpu, ts);
- if (!event)
- goto out_unlock;
-
- rb_advance_reader(cpu_buffer);
+ if (event)
+ rb_advance_reader(cpu_buffer);
- out_unlock:
if (dolock)
spin_unlock(&cpu_buffer->reader_lock);
local_irq_restore(flags);
--
1.6.3.3