* [PATCH v2] ring-buffer: Add offset of events in dump on mismatch
@ 2023-12-07 22:31 Steven Rostedt
2023-12-08 11:07 ` Masami Hiramatsu
0 siblings, 1 reply; 4+ messages in thread
From: Steven Rostedt @ 2023-12-07 22:31 UTC (permalink / raw)
To: LKML, Linux Trace Kernel
Cc: Masami Hiramatsu, Mark Rutland, Mathieu Desnoyers
From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
On bugs that have the ring buffer timestamp get out of sync, the config
CONFIG_RING_BUFFER_VALIDATE_TIME_DELTAS, that checks for it and if it is
detected it causes a dump of the bad sub buffer.
It shows each event and their timestamp as well as the delta in the event.
But it's also good to see the offset into the subbuffer for that event to
know if how close to the end it is.
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
Changes since v1: https://lore.kernel.org/linux-trace-kernel/20231207171613.0592087d@gandalf.local.home
- Add "0x" before the "%x" to make the print less confusing (Mathieu Desnoyers)
kernel/trace/ring_buffer.c | 12 ++++++++----
1 file changed, 8 insertions(+), 4 deletions(-)
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 8d2a4f00eca9..09d4b1aa8820 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -3424,23 +3424,27 @@ static void dump_buffer_page(struct buffer_data_page *bpage,
case RINGBUF_TYPE_TIME_EXTEND:
delta = rb_event_time_stamp(event);
ts += delta;
- pr_warn(" [%lld] delta:%lld TIME EXTEND\n", ts, delta);
+ pr_warn(" 0x%x: [%lld] delta:%lld TIME EXTEND\n",
+ e, ts, delta);
break;
case RINGBUF_TYPE_TIME_STAMP:
delta = rb_event_time_stamp(event);
ts = rb_fix_abs_ts(delta, ts);
- pr_warn(" [%lld] absolute:%lld TIME STAMP\n", ts, delta);
+ pr_warn(" 0x%x: [%lld] absolute:%lld TIME STAMP\n",
+ e, ts, delta);
break;
case RINGBUF_TYPE_PADDING:
ts += event->time_delta;
- pr_warn(" [%lld] delta:%d PADDING\n", ts, event->time_delta);
+ pr_warn(" 0x%x: [%lld] delta:%d PADDING\n",
+ e, ts, event->time_delta);
break;
case RINGBUF_TYPE_DATA:
ts += event->time_delta;
- pr_warn(" [%lld] delta:%d\n", ts, event->time_delta);
+ pr_warn(" 0x%x: [%lld] delta:%d\n",
+ e, ts, event->time_delta);
break;
default:
--
2.42.0
^ permalink raw reply related [flat|nested] 4+ messages in thread* Re: [PATCH v2] ring-buffer: Add offset of events in dump on mismatch
2023-12-07 22:31 [PATCH v2] ring-buffer: Add offset of events in dump on mismatch Steven Rostedt
@ 2023-12-08 11:07 ` Masami Hiramatsu
0 siblings, 0 replies; 4+ messages in thread
From: Masami Hiramatsu @ 2023-12-08 11:07 UTC (permalink / raw)
To: Steven Rostedt
Cc: LKML, Linux Trace Kernel, Masami Hiramatsu, Mark Rutland,
Mathieu Desnoyers
On Thu, 7 Dec 2023 17:31:08 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:
> From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
>
> On bugs that have the ring buffer timestamp get out of sync, the config
> CONFIG_RING_BUFFER_VALIDATE_TIME_DELTAS, that checks for it and if it is
> detected it causes a dump of the bad sub buffer.
>
> It shows each event and their timestamp as well as the delta in the event.
> But it's also good to see the offset into the subbuffer for that event to
> know if how close to the end it is.
>
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
Looks good to me.
Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Thanks!
> ---
> Changes since v1: https://lore.kernel.org/linux-trace-kernel/20231207171613.0592087d@gandalf.local.home
>
> - Add "0x" before the "%x" to make the print less confusing (Mathieu Desnoyers)
>
> kernel/trace/ring_buffer.c | 12 ++++++++----
> 1 file changed, 8 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index 8d2a4f00eca9..09d4b1aa8820 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -3424,23 +3424,27 @@ static void dump_buffer_page(struct buffer_data_page *bpage,
> case RINGBUF_TYPE_TIME_EXTEND:
> delta = rb_event_time_stamp(event);
> ts += delta;
> - pr_warn(" [%lld] delta:%lld TIME EXTEND\n", ts, delta);
> + pr_warn(" 0x%x: [%lld] delta:%lld TIME EXTEND\n",
> + e, ts, delta);
> break;
>
> case RINGBUF_TYPE_TIME_STAMP:
> delta = rb_event_time_stamp(event);
> ts = rb_fix_abs_ts(delta, ts);
> - pr_warn(" [%lld] absolute:%lld TIME STAMP\n", ts, delta);
> + pr_warn(" 0x%x: [%lld] absolute:%lld TIME STAMP\n",
> + e, ts, delta);
> break;
>
> case RINGBUF_TYPE_PADDING:
> ts += event->time_delta;
> - pr_warn(" [%lld] delta:%d PADDING\n", ts, event->time_delta);
> + pr_warn(" 0x%x: [%lld] delta:%d PADDING\n",
> + e, ts, event->time_delta);
> break;
>
> case RINGBUF_TYPE_DATA:
> ts += event->time_delta;
> - pr_warn(" [%lld] delta:%d\n", ts, event->time_delta);
> + pr_warn(" 0x%x: [%lld] delta:%d\n",
> + e, ts, event->time_delta);
> break;
>
> default:
> --
> 2.42.0
>
--
Masami Hiramatsu (Google) <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 4+ messages in thread
* [PATCH v2] ring-buffer: Add offset of events in dump on mismatch
@ 2023-12-11 18:06 Steven Rostedt
2023-12-11 18:07 ` Steven Rostedt
0 siblings, 1 reply; 4+ messages in thread
From: Steven Rostedt @ 2023-12-11 18:06 UTC (permalink / raw)
To: LKML, Linux Trace Kernel
Cc: Masami Hiramatsu, Mark Rutland, Mathieu Desnoyers
From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
On bugs that have the ring buffer timestamp get out of sync, the config
CONFIG_RING_BUFFER_VALIDATE_TIME_DELTAS, that checks for it and if it is
detected it causes a dump of the bad sub buffer.
It shows each event and their timestamp as well as the delta in the event.
But it's also good to see the offset into the subbuffer for that event to
know if how close to the end it is.
Also print where the last event actually ended compared to where it was
expected to end.
Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
Changes since v1: https://lore.kernel.org/linux-trace-kernel/20231207173108.484b912c@gandalf.local.home
- Also show where the last event added and where it expected to end.
kernel/trace/ring_buffer.c | 13 +++++++++----
1 file changed, 9 insertions(+), 4 deletions(-)
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index bc70cb9bbdb7..c28513624ab3 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -3429,29 +3429,34 @@ static void dump_buffer_page(struct buffer_data_page *bpage,
case RINGBUF_TYPE_TIME_EXTEND:
delta = rb_event_time_stamp(event);
ts += delta;
- pr_warn(" [%lld] delta:%lld TIME EXTEND\n", ts, delta);
+ pr_warn(" 0x%x: [%lld] delta:%lld TIME EXTEND\n",
+ e, ts, delta);
break;
case RINGBUF_TYPE_TIME_STAMP:
delta = rb_event_time_stamp(event);
ts = rb_fix_abs_ts(delta, ts);
- pr_warn(" [%lld] absolute:%lld TIME STAMP\n", ts, delta);
+ pr_warn(" 0x%x: [%lld] absolute:%lld TIME STAMP\n",
+ e, ts, delta);
break;
case RINGBUF_TYPE_PADDING:
ts += event->time_delta;
- pr_warn(" [%lld] delta:%d PADDING\n", ts, event->time_delta);
+ pr_warn(" 0x%x: [%lld] delta:%d PADDING\n",
+ e, ts, event->time_delta);
break;
case RINGBUF_TYPE_DATA:
ts += event->time_delta;
- pr_warn(" [%lld] delta:%d\n", ts, event->time_delta);
+ pr_warn(" 0x%x: [%lld] delta:%d\n",
+ e, ts, event->time_delta);
break;
default:
break;
}
}
+ pr_warn("expected end:%ld last event actually ended at:%d\n", tail, e);
}
static DEFINE_PER_CPU(atomic_t, checking);
--
2.42.0
^ permalink raw reply related [flat|nested] 4+ messages in thread* Re: [PATCH v2] ring-buffer: Add offset of events in dump on mismatch
2023-12-11 18:06 Steven Rostedt
@ 2023-12-11 18:07 ` Steven Rostedt
0 siblings, 0 replies; 4+ messages in thread
From: Steven Rostedt @ 2023-12-11 18:07 UTC (permalink / raw)
To: LKML, Linux Trace Kernel
Cc: Masami Hiramatsu, Mark Rutland, Mathieu Desnoyers
On Mon, 11 Dec 2023 13:06:14 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:
>
> case RINGBUF_TYPE_DATA:
> ts += event->time_delta;
> - pr_warn(" [%lld] delta:%d\n", ts, event->time_delta);
> + pr_warn(" 0x%x: [%lld] delta:%d\n",
> + e, ts, event->time_delta);
> break;
>
> default:
> break;
> }
> }
> + pr_warn("expected end:%ld last event actually ended at:%d\n", tail, e);
> }
>
Bah, all offsets were in hex, the above was supposed to be in hex too. I
sent out the wrong version.
Will send a v3 with that update.
-- Steve
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2023-12-11 18:06 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2023-12-07 22:31 [PATCH v2] ring-buffer: Add offset of events in dump on mismatch Steven Rostedt
2023-12-08 11:07 ` Masami Hiramatsu
-- strict thread matches above, loose matches on Subject: below --
2023-12-11 18:06 Steven Rostedt
2023-12-11 18:07 ` Steven Rostedt
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox