ring-buffer: fix uninitialized read_stamp

This fixes a scenario in which trace_pipe_raw will return events with invalid timestamps when events are copied out one at a time (instead of swapping out the reader page with a spare page). In this scenario, ring_buffer_read_page() uses cpu_buffer->read_stamp to keep track of the time of the earliest event. However, cpu_buffer->read_stamp was not always updated. The only function that sets read_stamp to a new valid value is rb_reset_reader_page(), which is called only by rb_get_reader_page(). rb_reset_reader_page() was not called when there is data immediately available on the page to read (read < rb_page_size()). This is the bug.

Setting the read_stamp on the first read from a page fixes the bug.

Tested: On certain lightly-loaded machines, repetitive reads from trace_pipe_raw without using splice() would sometimes result in invalid timestamps. Poisoning read_stamp in rb_init_page() with a negative value makes the problem more visible. After this fix, the invalid timstamps disappear.

Google-Bug-Id: 6410455

Signed-off-by David Sharp <[email protected]>

This fixes a scenario in which trace_pipe_raw will return events with invalid timestamps when events are copied out one at a time (instead of swapping out the reader page with a spare page). In this scenario, ring_buffer_read_page() uses cpu_buffer->read_stamp to keep track of the time of the earliest event. However, cpu_buffer->read_stamp was not always updated. The only function that sets read_stamp to a new valid value is rb_reset_reader_page(), which is called only by rb_get_reader_page(). rb_reset_reader_page() was not called when there is data immediately available on the page to read (read < rb_page_size()). This is the bug.

This fixes a scenario in which trace_pipe_raw will return events with invalid timestamps when events are copied out one at a time (instead of swapping out the reader page with a spare page). In this scenario, ring_buffer_read_page() uses cpu_buffer->read_stamp to keep track of the time of the earliest event. However, cpu_buffer->read_stamp was not always updated.

The only function that
sets read_stamp to a new valid value is rb_reset_reader_page(), which is called only by rb_get_reader_page().

rb_reset_reader_page() was not called when there
is data immediately available on the page to read (read < rb_page_size()). This is the bug.

I'm wondering if it would be better to just not do the swap, and return NULL when it is empty. This would also fix the problem, as the read_stamp will only be set when you actually have data.

Do you believe that this is an urgent fix and should be marked for stable, or do you think it can wait till 3.6? If you think it should be marked for stable, then it should be pushed for 3.5.

OK, I did look at this more.

Quoted 3 lines

 The only function that
sets read_stamp to a new valid value is rb_reset_reader_page(), which is called only by rb_get_reader_page().

Correct, which is the only way to get the reader page no matter how you read the buffer.

Quoted 3 lines

 rb_reset_reader_page() was not called when there
is data immediately available on the page to read (read < rb_page_size()). This is the bug.

It is not called?

but how did you get the reader_page without the swap in the first place?

When the ring buffer is first allocated the reader page is set to a zero'd page, making the "read" and "commit" both zero.

The first time rb_get_reader_page() is called, the compare of read < rb_page_size() (which is the commit field) fails (0 < 0 is false).

A swap from the writable ring buffer takes place and the cpu_buffer->read_stamp is updated.

Ah! I think this is where the bug you see happens. But your analysis is flawed.

If the ring buffer is currently empty, we swap an empty page for an empty page. But the writer ends up on the reader page preventing new swaps from taking place.

   commit_page == reader_page

If the writer starts writing, it will update the time stamp of the page. If your next read happens now, and it's just a single read, then you are correct that it will not update the read_stamp.

I'm wondering if it would be better to just not do the swap, and return NULL when it is empty. This would also fix the problem, as the read_stamp will only be set when you actually have data.

Or it may just be simpler to take your patch.

kernel/trace/ring_buffer.c +2 -0

+               goto out;
+
        /*
         * Reset the reader page to size zero.
         */

Quoted 3 lines · Steven Rostedt

Do you believe that this is an urgent fix and should be marked for stable, or do you think it can wait till 3.6? If you think it should be marked for stable, then it should be pushed for 3.5.

I think it should be considered for 3.5, since it affects the accuracy of the timestamps in very roughly 20% of traces read with read() on trace_pipe_raw. otoh, it only affects the first page or so on lightly loaded CPUs. Personally it doesn't make much difference to us what release it gets into.

Quoted 13 lines

OK, I did look at this more.

Quoted 3 lines

The only function that
sets read_stamp to a new valid value is rb_reset_reader_page(), which is called only by rb_get_reader_page().

Correct, which is the only way to get the reader page no matter how you read the buffer.

Quoted 3 lines

rb_reset_reader_page() was not called when there
is data immediately available on the page to read (read < rb_page_size()). This is the bug.

Quoted 1 line

It is not called?

Correct. I was able to add WARN_ONs that showed that it reached "out:" without reaching rb_reset_reader_page() first while still having a poison value in cpu_buffer->read_stamp.

Quoted 10 lines

but how did you get the reader_page without the swap in the first place?

When the ring buffer is first allocated the reader page is set to a zero'd page, making the "read" and "commit" both zero.

The first time rb_get_reader_page() is called, the compare of read < rb_page_size() (which is the commit field) fails (0 < 0 is false).

Quoted 5 lines

A swap from the writable ring buffer takes place and the cpu_buffer->read_stamp is updated.

Ah! I think this is where the bug you see happens. But your analysis is flawed.

I admit I didn't look into it that closely, so flaws are quite possible (also, I'm human).

Quoted 12 lines

If the ring buffer is currently empty, we swap an empty page for an empty page. But the writer ends up on the reader page preventing new swaps from taking place.

   commit_page == reader_page

If the writer starts writing, it will update the time stamp of the page. If your next read happens now, and it's just a single read, then you are correct that it will not update the read_stamp.

Quoted 3 lines

I'm wondering if it would be better to just not do the swap, and return NULL when it is empty. This would also fix the problem, as the read_stamp will only be set when you actually have data.

But we do have data... That's how we know we're getting invalid timestamps.

I don't quite understand what you're describing. Here's what I think is happening though:

When the ring buffer is reset, commit_page == tail_page == head_page.

rb_get_reader_page() will pick up the head page.

Then a few (less than
1 page worth) writes happen, on the tail_page which is currently (or soon to be) also the reader_page. Now read == 0, but rb_page_size(reader) is however many bytes have been written to the page.

So we have valid data on the reader page, but read_stamp has not been set yet.

Quoted 3 lines

Or it may just be simpler to take your patch.

Please? :)

Quoted 12 lines

Does something like this work for you. Note, this is totally untested!

-- Steve

kernel/trace/ring_buffer.c +0 -0

index ad0239b..5943044 100644
@@ -3246,6 +3246,10 @@ rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer)
       if (cpu_buffer->commit_page == cpu_buffer->reader_page)
               goto out;
 

kernel/trace/ring_buffer.c rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer) · line 3249

Quoted 1 line

kernel/trace/ring_buffer.c +1 -0

+       /* Don't bother swapping if the ring buffer is empty */

This doesn't make sense, since the ring buffer isn't empty in this scenario. (I didn't bother testing it.)

kernel/trace/ring_buffer.c rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer) · line 3250

Quoted 2 lines

kernel/trace/ring_buffer.c +1 -0

+       if (rb_num_of_entries(cpu_buffer) == 0)

Did you mean rb_page_entries(something?)

Quoted 8 lines

kernel/trace/ring_buffer.c +2 -0

+               goto out;
+
       /*
        * Reset the reader page to size zero.
        */

Quoted 16 lines · David Sharp

Quoted 14 lines · Steven Rostedt

OK, I did look at this more.

Quoted 3 lines

 The only function that
sets read_stamp to a new valid value is rb_reset_reader_page(), which is called only by rb_get_reader_page().

Correct, which is the only way to get the reader page no matter how you read the buffer.

Quoted 3 lines

 rb_reset_reader_page() was not called when there
is data immediately available on the page to read (read < rb_page_size()). This is the bug.

It is not called?

Quoted 3 lines

Correct. I was able to add WARN_ONs that showed that it reached "out:" without reaching rb_reset_reader_page() first while still having a poison value in cpu_buffer->read_stamp.

NO! You didn't understand what I wrote. The writer can not get onto the reader page without a swap! The reader page is not part of the main ring buffer.

Quoted 5 lines

Quoted 2 lines

Ah! I think this is where the bug you see happens. But your analysis is flawed.

I admit I didn't look into it that closely, so flaws are quite possible (also, I'm human).

I didn't mean to offend, as this is not something that can be easily picked up.

Quoted 14 lines

Quoted 13 lines

If the ring buffer is currently empty, we swap an empty page for an empty page. But the writer ends up on the reader page preventing new swaps from taking place.

   commit_page == reader_page

If the writer starts writing, it will update the time stamp of the page. If your next read happens now, and it's just a single read, then you are correct that it will not update the read_stamp.

I'm wondering if it would be better to just not do the swap, and return NULL when it is empty. This would also fix the problem, as the read_stamp will only be set when you actually have data.

Quoted 1 line

But we do have data... That's how we know we're getting invalid timestamps.

I bet this never happens if you add a little data and then do a read. I only happens when you read from an empty ring buffer, then do a small write, and then read again. That's where it will get you.

Quoted 6 lines

I don't quite understand what you're describing. Here's what I think is happening though:

When the ring buffer is reset, commit_page == tail_page == head_page.

And at this moment, the writer is off the reader page and will not be on the reader page. The only way to get date at this point is if you do a swap.

Quoted 1 line

rb_get_reader_page() will pick up the head page.

Right. But this requires a read to happen. If you never do a read, then rb_get_reader_page will not pick up the head page. The problem is when you read from an empty ring buffer.

Quoted 5 lines

 Then a few (less than
1 page worth) writes happen, on the tail_page which is currently (or soon to be) also the reader_page. Now read == 0, but rb_page_size(reader) is however many bytes have been written to the page.

Correct.

Quoted 2 lines

So we have valid data on the reader page, but read_stamp has not been set yet.

Yep

Quoted 2 lines

Quoted 2 lines

Quoted 3 lines

Quoted 1 line

Or it may just be simpler to take your patch.

Please? :)

Now I think you may understand my patch.

Quoted 13 lines · Steven Rostedt

Quoted 12 lines

Does something like this work for you. Note, this is totally untested!

-- Steve

kernel/trace/ring_buffer.c +0 -0

index ad0239b..5943044 100644
@@ -3246,6 +3246,10 @@ rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer)
        if (cpu_buffer->commit_page == cpu_buffer->reader_page)
                goto out;
 

Quoted 4 lines

kernel/trace/ring_buffer.c rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer) · line 3249

Quoted 1 line

kernel/trace/ring_buffer.c +1 -0

+       /* Don't bother swapping if the ring buffer is empty */

This doesn't make sense, since the ring buffer isn't empty in this scenario. (I didn't bother testing it.)

Yes it is! If you never did a read on the empty buffer, the *only* way to get what was written is to do the swap.

The problem you are seeing is that you did a read on an empty buffer before writing. In this case the swap happens but all we have is an empty page with the write pointer (commit and tail) on it. When a write happens, and you do another read, *then* we do not do the swap and you get the stale time stamp.

Thus, if you never let the first swap happen, you wont get into this scenario that you read and do not update the read_stamp.

Quoted 3 lines

Quoted 2 lines

kernel/trace/ring_buffer.c +1 -0

+       if (rb_num_of_entries(cpu_buffer) == 0)

Quoted 1 line

Did you mean rb_page_entries(something?)

Nope, I meant the actual ring buffer. If the ring buffer is empty, do not perform the swap. Because we only update the read stamp when we perform a swap, and it takes a write to happen before the page's timestamp is updated. If we do the swap before any writes happen, we get an invalid timestamp from the page.

Now do you understand?

-- Steve

Quoted 8 lines

Quoted 8 lines

kernel/trace/ring_buffer.c +2 -0

+               goto out;
+
        /*
         * Reset the reader page to size zero.
         */

Quoted 2 lines · Steven Rostedt

Now I think you may understand my patch.

Yeah, mostly. At least enough that I think it's worth testing. But Monday.

Quoted 20 lines

Quoted 20 lines · Steven Rostedt

Quoted 19 lines

Does something like this work for you. Note, this is totally untested!

-- Steve

kernel/trace/ring_buffer.c +4 -0

index ad0239b..5943044 100644
@@ -3246,6 +3246,10 @@ rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer)
        if (cpu_buffer->commit_page == cpu_buffer->reader_page)
                goto out;
 
+       /* Don't bother swapping if the ring buffer is empty */
+       if (rb_num_of_entries(cpu_buffer) == 0)
+               goto out;
+
        /*
         * Reset the reader page to size zero.
         */

Quoted 5 lines · David Sharp

Quoted 2 lines · Steven Rostedt

Now I think you may understand my patch.

Yeah, mostly. At least enough that I think it's worth testing. But Monday.

I got around to testing your patch today, and it fixes the issue. No bad-looking timestamps in 40 runs, whereas could reproduce within 3 runs before. Do you want me to send you a fresh patch, or just use the one you have?

Quoted 21 lines

Quoted 21 lines

Quoted 21 lines · Steven Rostedt

Quoted 19 lines

Does something like this work for you. Note, this is totally untested!

-- Steve

kernel/trace/ring_buffer.c +4 -0

index ad0239b..5943044 100644
@@ -3246,6 +3246,10 @@ rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer)
       if (cpu_buffer->commit_page == cpu_buffer->reader_page)
               goto out;
 
+       /* Don't bother swapping if the ring buffer is empty */
+       if (rb_num_of_entries(cpu_buffer) == 0)
+               goto out;
+
       /*
        * Reset the reader page to size zero.
        */

Quoted 5 lines · David Sharp

Quoted 4 lines · David Sharp

Quoted 2 lines · Steven Rostedt

Now I think you may understand my patch.

Quoted 6 lines

Quoted 1 line

Yeah, mostly. At least enough that I think it's worth testing. But Monday.

I got around to testing your patch today, and it fixes the issue. No bad-looking timestamps in 40 runs, whereas could reproduce within 3 runs before. Do you want me to send you a fresh patch, or just use the one you have?

I rather use this one for two reasons.

1) it limits the places where read_stamp is updated. And I rather not add an update because "it fixes an anomaly".

2) I think it is wrong to force the writer on the reader page when no write has been made. There's some side effects that this causes. One is that if you do a read with no write, and then do nothing, it forces the writer on that page. Now if a lot of writes happen (function tracing), the writes that were on the reader page are never overwritten when the buffer is full. Then you get a page of very old data, followed by a buffer full of new data.

I just meant, do you want me to send you a version of your patch with my description (I'll update it, obviously), or do it yourself.

I have always disliked that page of very old data, so I'm really happy that this will get rid of it. As I recall, you once claimed this was a "feature". :)