Messages in this thread | | | Subject | Re: races when reserving an event in the unified trace buffer | From | Steven Rostedt <> | Date | Mon, 22 Dec 2008 18:02:47 -0500 |
| |
Hi Jiaying,
Sorry for taking so long to reply.
On Fri, 2008-12-12 at 16:26 -0800, Jiaying Zhang wrote: > Hi Steve, > > I am doing some load testing with our kernel tracing prototype > that uses the unified trace buffer for managing its data. I sometimes > saw kernel stack dump caused by the following checking in > function __rb_reserve_next: > if (unlikely(next_page == cpu_buffer->commit_page)) { > WARN_ON_ONCE(1); > goto out_unlock; > } > The comments above the code say the problem is caused by > "an interrupt storm that made it all the way around the buffer". > But I think there is race here that a single interrupt can cause > the check to fail. Suppose this is what happens: > An event is traced and calls __rb_reserve_next. Right after it > gets the current tail_page (line tail_page = cpu_buffer->tail_page;), > an interrupt happens that is also traced. The interrupt also takes > the same tail_page. The interrupt event moves the tail_page > forward if the tail_page is full. Note that the interrupt event gets > the old 'write' value because the first event has not updated that yet.
Good catch.
> So the interrupt event may also update the commit_page if it is > the same as the tail_page. As a result, the above check would > fail after the interrupt finishes and the first event resumes its execution. > > I have seen the problem happens frequently under heavy loads > on a multi-core machine. Interestingly, I also saw the above > warning that might actually be caused by an interrupt storm. > I was using 64k buffer size and am not sure whether it is possible > for so many interrupts to happen in a short time window. > > I think we can use the time_stamp to distinguish the two cases. > Also, in either case, it seems bad to leave the tail_page->write with > an invalid value because it can cause problem when a reader > reads the page. Here is my proposed fix for the problem: > > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c > index 7f69cfe..1500f78 100644 > --- a/kernel/trace/ring_buffer.c > +++ b/kernel/trace/ring_buffer.c > @@ -982,8 +982,11 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer, > * it all the way around the buffer, bail, and warn > * about it. > */ > - if (unlikely(next_page == cpu_buffer->commit_page)) { > + if (unlikely(next_page == cpu_buffer->commit_page) && > + tail_page->time_stamp > next_page->time_stamp) { > WARN_ON_ONCE(1); > + if (tail <= BUF_PAGE_SIZE) > + local_set(&tail_page->write, tail);
Actually what we probably should do instead, is simply record the commit page first:
+ commit_page = cpu_buffer->commit_page; + barrier(); tail_page = cpu_buffer->tail_page; write = local_add_return(length, &tail_page->write);
And then we could test next_page == commit_page instead.
-- Steve
| |