| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20150903150826.37e00803@gandalf.local.home>
Date: Thu, 3 Sep 2015 15:08:26 -0400
From: Steven Rostedt <rostedt@...dmis.org>
To: LKML <linux-kernel@...r.kernel.org>
Cc: Ingo Molnar <mingo@...nel.org>
Subject: [for-next][PATCH] ring-buffer: Revert "ring-buffer: Get timestamp
after event is allocated"
One of my updates that was suppose to go into mainline in this merge
window has a bug in it that causes the ring-buffer timestamp to slip
out of sync. I haven't found the actual bug, but as this is holding up
other changes, I'm reverting it. The patch hasn't made it into
mainline, but other changes come after it that has been sitting in
linux-next, and I don't want to rebase. This revert has been through my
other tests.
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next
Head SHA1: b7dc42fd79390c074e2bff3b172b585d5c2d80c2
Steven Rostedt (Red Hat) (1):
ring-buffer: Revert "ring-buffer: Get timestamp after event is allocated"
----
kernel/trace/ring_buffer.c | 156 +++++++++++++++------------------------------
1 file changed, 50 insertions(+), 106 deletions(-)
---------------------------
commit b7dc42fd79390c074e2bff3b172b585d5c2d80c2
Author: Steven Rostedt (Red Hat) <rostedt@...dmis.org>
Date: Thu Sep 3 08:57:12 2015 -0400
ring-buffer: Revert "ring-buffer: Get timestamp after event is allocated"
The commit a4543a2fa9ef31 "ring-buffer: Get timestamp after event is
allocated" is needed for some future work. But after adding it, there is a
race somewhere that causes the saved timestamp to have a slight shift, and
get ahead of the actual timestamp and make it look like time goes backwards.
I'm still looking into why this happens, but in the mean time, this is
holding up other work to get in. I'm reverting the change for now (which
makes the problem go away), and will add it back after I know what is wrong
and fix it.
Signed-off-by: Steven Rostedt <rostedt@...dmis.org>
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 1cce0fbf92ce..fc347f8b1bca 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2141,8 +2141,6 @@ rb_reset_tail(struct ring_buffer_per_cpu *cpu_buffer,
local_sub(length, &tail_page->write);
}
-static inline void rb_end_commit(struct ring_buffer_per_cpu *cpu_buffer);
-
/*
* This is the slow path, force gcc not to inline it.
*/
@@ -2157,16 +2155,6 @@ rb_move_tail(struct ring_buffer_per_cpu *cpu_buffer,
int ret;
u64 ts;
- /*
- * If the event had a timestamp attached to it, remove it.
- * The first event on a page (nested or not) always uses
- * the full timestamp of the new page.
- */
- if (info->add_timestamp) {
- info->add_timestamp = 0;
- info->length -= RB_LEN_TIME_EXTEND;
- }
-
next_page = tail_page;
rb_inc_page(cpu_buffer, &next_page);
@@ -2253,11 +2241,6 @@ rb_move_tail(struct ring_buffer_per_cpu *cpu_buffer,
rb_reset_tail(cpu_buffer, tail, info);
- /* Commit what we have for now to update timestamps */
- rb_end_commit(cpu_buffer);
- /* rb_end_commit() decs committing */
- local_inc(&cpu_buffer->committing);
-
/* fail and let the caller try again */
return ERR_PTR(-EAGAIN);
@@ -2287,6 +2270,9 @@ rb_add_time_stamp(struct ring_buffer_event *event, u64 delta)
return skip_time_extend(event);
}
+static inline int rb_event_is_commit(struct ring_buffer_per_cpu *cpu_buffer,
+ struct ring_buffer_event *event);
+
/**
* rb_update_event - update event type and data
* @event: the event to update
@@ -2298,7 +2284,7 @@ rb_add_time_stamp(struct ring_buffer_event *event, u64 delta)
* and with this, we can determine what to place into the
* data field.
*/
-static void __always_inline
+static void
rb_update_event(struct ring_buffer_per_cpu *cpu_buffer,
struct ring_buffer_event *event,
struct rb_event_info *info)
@@ -2306,6 +2292,10 @@ rb_update_event(struct ring_buffer_per_cpu *cpu_buffer,
unsigned length = info->length;
u64 delta = info->delta;
+ /* Only a commit updates the timestamp */
+ if (unlikely(!rb_event_is_commit(cpu_buffer, event)))
+ delta = 0;
+
/*
* If we need to add a timestamp, then we
* add it to the start of the resevered space.
@@ -2685,13 +2675,8 @@ EXPORT_SYMBOL_GPL(ring_buffer_unlock_commit);
static noinline void
rb_handle_timestamp(struct ring_buffer_per_cpu *cpu_buffer,
- struct ring_buffer_event *event,
struct rb_event_info *info)
{
- struct ring_buffer_event *padding;
- int length;
- int size;
-
WARN_ONCE(info->delta > (1ULL << 59),
KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s",
(unsigned long long)info->delta,
@@ -2701,61 +2686,7 @@ rb_handle_timestamp(struct ring_buffer_per_cpu *cpu_buffer,
"If you just came from a suspend/resume,\n"
"please switch to the trace global clock:\n"
" echo global > /sys/kernel/debug/tracing/trace_clock\n");
-
- /*
- * Discarding this event to add a timestamp in front, but
- * we still need to update the length of it to perform the discard.
- */
- rb_update_event(cpu_buffer, event, info);
-
- if (rb_try_to_discard(cpu_buffer, event)) {
- info->add_timestamp = 1;
- /*
- * The time delta since the last event is too big to
- * hold in the time field of the event, then we append a
- * TIME EXTEND event ahead of the data event.
- */
- info->length += RB_LEN_TIME_EXTEND;
- return;
- }
-
- /*
- * Humpf! An event came in after this one, and because it is not a
- * commit, it will have a delta of zero, thus, it will take on
- * the timestamp of the previous commit, which happened a long time
- * ago (we need to add a timestamp, remember?).
- * We need to add the timestamp here. A timestamp is a fixed size
- * of 8 bytes. That means the rest of the event needs to be
- * padding.
- */
- size = info->length - RB_LEN_TIME_EXTEND;
-
- /* The padding will have a delta of 1 */
- if (size)
- info->delta--;
-
- padding = rb_add_time_stamp(event, info->delta);
-
- if (size) {
- length = info->length;
- info->delta = 0;
- info->length = size;
- rb_update_event(cpu_buffer, padding, info);
-
- rb_event_discard(padding);
-
- /* Still visible, need to update write_stamp */
- rb_update_write_stamp(cpu_buffer, event);
-
- /* Still need to commit the padding. */
- rb_end_commit(cpu_buffer);
-
- /* rb_end_commit() decs committing */
- local_inc(&cpu_buffer->committing);
-
- /* The next iteration still uses the original length */
- info->length = length;
- }
+ info->add_timestamp = 1;
}
static struct ring_buffer_event *
@@ -2765,7 +2696,14 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
struct ring_buffer_event *event;
struct buffer_page *tail_page;
unsigned long tail, write;
- bool is_commit;
+
+ /*
+ * If the time delta since the last event is too big to
+ * hold in the time field of the event, then we append a
+ * TIME EXTEND event ahead of the data event.
+ */
+ if (unlikely(info->add_timestamp))
+ info->length += RB_LEN_TIME_EXTEND;
tail_page = info->tail_page = cpu_buffer->tail_page;
write = local_add_return(info->length, &tail_page->write);
@@ -2774,43 +2712,32 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
write &= RB_WRITE_MASK;
tail = write - info->length;
- /* See if we shot pass the end of this buffer page */
- if (unlikely(write > BUF_PAGE_SIZE))
- return rb_move_tail(cpu_buffer, tail, info);
-
- /* We reserved something on the buffer */
- event = __rb_page_index(tail_page, tail);
-
/*
* If this is the first commit on the page, then it has the same
- * timestamp as the page itself, otherwise we need to figure out
- * the delta.
+ * timestamp as the page itself.
*/
- info->ts = rb_time_stamp(cpu_buffer->buffer);
- is_commit = rb_event_is_commit(cpu_buffer, event);
-
- /* Commits are special (non nested events) */
- info->delta = is_commit ? info->ts - cpu_buffer->write_stamp : 0;
-
- if (!tail) {
- /*
- * If this is the first commit on the page, set the
- * page to its timestamp.
- */
- tail_page->page->time_stamp = info->ts;
+ if (!tail)
info->delta = 0;
- } else if (unlikely(test_time_stamp(info->delta)) &&
- !info->add_timestamp) {
- rb_handle_timestamp(cpu_buffer, event, info);
- return ERR_PTR(-EAGAIN);
- }
+ /* See if we shot pass the end of this buffer page */
+ if (unlikely(write > BUF_PAGE_SIZE))
+ return rb_move_tail(cpu_buffer, tail, info);
+ /* We reserved something on the buffer */
+
+ event = __rb_page_index(tail_page, tail);
kmemcheck_annotate_bitfield(event, bitfield);
rb_update_event(cpu_buffer, event, info);
local_inc(&tail_page->entries);
+ /*
+ * If this is the first commit on the page, then update
+ * its timestamp.
+ */
+ if (!tail)
+ tail_page->page->time_stamp = info->ts;
+
/* account for these added bytes */
local_add(info->length, &cpu_buffer->entries_bytes);
@@ -2825,6 +2752,7 @@ rb_reserve_next_event(struct ring_buffer *buffer,
struct ring_buffer_event *event;
struct rb_event_info info;
int nr_loops = 0;
+ u64 diff;
rb_start_commit(cpu_buffer);
@@ -2842,9 +2770,12 @@ rb_reserve_next_event(struct ring_buffer *buffer,
return NULL;
}
#endif
+
info.length = rb_calculate_event_length(length);
- info.add_timestamp = 0;
again:
+ info.add_timestamp = 0;
+ info.delta = 0;
+
/*
* We allow for interrupts to reenter here and do a trace.
* If one does, it will cause this original code to loop
@@ -2857,6 +2788,19 @@ rb_reserve_next_event(struct ring_buffer *buffer,
if (RB_WARN_ON(cpu_buffer, ++nr_loops > 1000))
goto out_fail;
+ info.ts = rb_time_stamp(cpu_buffer->buffer);
+ diff = info.ts - cpu_buffer->write_stamp;
+
+ /* make sure this diff is calculated here */
+ barrier();
+
+ /* Did the write stamp get updated already? */
+ if (likely(info.ts >= cpu_buffer->write_stamp)) {
+ info.delta = diff;
+ if (unlikely(test_time_stamp(info.delta)))
+ rb_handle_timestamp(cpu_buffer, &info);
+ }
+
event = __rb_reserve_next(cpu_buffer, &info);
if (unlikely(PTR_ERR(event) == -EAGAIN))
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists