From 4be4e74032336522691bf2e751e40ae679cc885b Mon Sep 17 00:00:00 2001 From: Jason Behmer Date: Mon, 1 Apr 2019 15:15:13 -0700 Subject: [PATCH] Adding TIME_STAMP events to all nested events. --- kernel/trace/ring_buffer.c | 96 +++++++++++++++++++++++++++----------- 1 file changed, 70 insertions(+), 26 deletions(-) diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c index 41b6f96e5366..07a408ed7248 100644 --- a/kernel/trace/ring_buffer.c +++ b/kernel/trace/ring_buffer.c @@ -425,7 +425,8 @@ struct rb_event_info { u64 delta; unsigned long length; struct buffer_page *tail_page; - int add_timestamp; + bool add_time_extend; + bool add_time_stamp; }; /* @@ -2313,15 +2314,12 @@ rb_move_tail(struct ring_buffer_per_cpu *cpu_buffer, /* Slow path, do not inline */ static noinline struct ring_buffer_event * -rb_add_time_stamp(struct ring_buffer_event *event, u64 delta, bool abs) +rb_add_time_extend(struct ring_buffer_event *event, u64 delta) { - if (abs) - event->type_len = RINGBUF_TYPE_TIME_STAMP; - else - event->type_len = RINGBUF_TYPE_TIME_EXTEND; + event->type_len = RINGBUF_TYPE_TIME_EXTEND; /* Not the first event on the page, or not delta? */ - if (abs || rb_event_index(event)) { + if (rb_event_index(event)) { event->time_delta = delta & TS_MASK; event->array[0] = delta >> TS_SHIFT; } else { @@ -2333,6 +2331,21 @@ rb_add_time_stamp(struct ring_buffer_event *event, u64 delta, bool abs) return skip_time_extend(event); } +/* Slow path, do not inline */ +static noinline struct ring_buffer_event * +rb_add_time_stamp(struct ring_buffer_event *event, u64 timestamp) +{ + event->type_len = RINGBUF_TYPE_TIME_STAMP; + /* + * Store a full timestamp in the time_delta field and the first data + * element. + */ + event->time_delta = timestamp & TS_MASK; + event->array[0] = timestamp >> TS_SHIFT; + + return skip_time_extend(event); +} + static inline bool rb_event_is_commit(struct ring_buffer_per_cpu *cpu_buffer, struct ring_buffer_event *event); @@ -2360,15 +2373,17 @@ rb_update_event(struct ring_buffer_per_cpu *cpu_buffer, delta = 0; /* - * If we need to add a timestamp, then we + * If we need to add a TIME_EXTEND or TIME_STAMP, then we * add it to the start of the reserved space. */ - if (unlikely(info->add_timestamp)) { - bool abs = ring_buffer_time_stamp_abs(cpu_buffer->buffer); - - event = rb_add_time_stamp(event, info->delta, abs); + if (unlikely(info->add_time_extend)) { + event = rb_add_time_extend(event, info->delta); length -= RB_LEN_TIME_EXTEND; delta = 0; + } else if (unlikely(info->add_time_stamp)) { + event = rb_add_time_stamp(event, info->delta); + length -= RB_LEN_TIME_STAMP; + delta = 0; } event->time_delta = delta; @@ -2520,6 +2535,14 @@ rb_set_commit_to_write(struct ring_buffer_per_cpu *cpu_buffer) goto again; } +static __always_inline bool +rb_commit_is_write(struct ring_buffer_per_cpu *cpu_buffer) +{ + return cpu_buffer->commit_page == cpu_buffer->tail_page && + rb_commit_index(cpu_buffer) == rb_page_write(cpu_buffer->commit_page); + +} + static __always_inline void rb_end_commit(struct ring_buffer_per_cpu *cpu_buffer) { unsigned long commits; @@ -2805,19 +2828,23 @@ EXPORT_SYMBOL_GPL(ring_buffer_unlock_commit); static noinline void rb_handle_timestamp(struct ring_buffer_per_cpu *cpu_buffer, - struct rb_event_info *info) + struct rb_event_info *info, int abs) { WARN_ONCE(info->delta > (1ULL << 59), - KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s", + KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu abs=%d\n%s", (unsigned long long)info->delta, (unsigned long long)info->ts, (unsigned long long)cpu_buffer->write_stamp, + abs, sched_clock_stable() ? "" : "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" "or add trace_clock=global to the kernel command line\n"); - info->add_timestamp = 1; + if (abs) + info->add_time_stamp = true; + else + info->add_time_extend = true; } static struct ring_buffer_event * @@ -2828,13 +2855,20 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer, struct buffer_page *tail_page; unsigned long tail, write; - /* - * 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)) + if (unlikely(info->add_time_extend)) + /* + * 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. + */ info->length += RB_LEN_TIME_EXTEND; + else if (unlikely(info->add_time_stamp)) + /* + * If using absolute time stamps for this event, then we append + * a TIME STAMP event ahead of the data event to fit the full + * timestamp. + */ + info->length += RB_LEN_TIME_STAMP; /* Don't let the compiler play games with cpu_buffer->tail_page */ tail_page = info->tail_page = READ_ONCE(cpu_buffer->tail_page); @@ -2848,7 +2882,7 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer, * If this is the first commit on the page, then it has the same * timestamp as the page itself. */ - if (!tail && !ring_buffer_time_stamp_abs(cpu_buffer->buffer)) + if (!tail && !unlikely(info->add_time_stamp)) info->delta = 0; /* See if we shot pass the end of this buffer page */ @@ -2904,7 +2938,8 @@ rb_reserve_next_event(struct ring_buffer *buffer, info.length = rb_calculate_event_length(length); again: - info.add_timestamp = 0; + info.add_time_extend = false; + info.add_time_stamp = false; info.delta = 0; /* @@ -2927,19 +2962,28 @@ rb_reserve_next_event(struct ring_buffer *buffer, if (ring_buffer_time_stamp_abs(buffer)) { info.delta = info.ts; - rb_handle_timestamp(cpu_buffer, &info); + rb_handle_timestamp(cpu_buffer, &info, true); + } else if (!rb_commit_is_write(cpu_buffer)) { + /* + * Use absolute timestamps for nested events, where we can't + * compute a delta. + */ + info.delta = info.ts; + rb_handle_timestamp(cpu_buffer, &info, true); } else /* 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); + rb_handle_timestamp(cpu_buffer, &info, false); } event = __rb_reserve_next(cpu_buffer, &info); if (unlikely(PTR_ERR(event) == -EAGAIN)) { - if (info.add_timestamp) + if (info.add_time_extend) info.length -= RB_LEN_TIME_EXTEND; + else if (info.add_time_stamp) + info.length -= RB_LEN_TIME_STAMP; goto again; } -- 2.21.0.392.gf8f6787159e-goog