Re: races when reserving an event in the unified trace buffer

[Jiaying Zhang <jiayingz@google.com>]

Hi Steve,

On Mon, Dec 22, 2008 at 3:02 PM, Steven Rostedt <srostedt@redhat.com> wrote:
> Hi Jiaying,
>
> Sorry for taking so long to reply.
No problem. Thanks for looking at it!

>
> 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.
Yes. This is more clear and simpler ;).

Jiaying

>
> -- Steve
>
>
>