2023-12-07 22:16:07

by Steven Rostedt

Subject: [PATCH] ring-buffer: Add offset of events in dump on mismatch

From: "Steven Rostedt (Google)" <[email protected]>

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) <[email protected]>
---
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..b10deb8a5647 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(" %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(" %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(" %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(" %x: [%lld] delta:%d\n",
+ e, ts, event->time_delta);
break;

default:
--
2.42.0

2023-12-07 22:19:59

by Mathieu Desnoyers

Subject: Re: [PATCH] ring-buffer: Add offset of events in dump on mismatch

On 2023-12-07 17:16, Steven Rostedt wrote:

[...]

> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index 8d2a4f00eca9..b10deb8a5647 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(" %x: [%lld] delta:%lld TIME EXTEND\n",

Please prefix hex values with "0x", as in:

pr_warn(" 0x%x: [%lld] delta:%lld TIME EXTEND\n"

Otherwise it can be confusing.

Thanks,

Mathieu

--
Mathieu Desnoyers
EfficiOS Inc.
https://www.efficios.com

2023-12-07 22:28:21

by Steven Rostedt

Subject: Re: [PATCH] ring-buffer: Add offset of events in dump on mismatch

On Thu, 7 Dec 2023 17:19:24 -0500
Mathieu Desnoyers <[email protected]> wrote:

> On 2023-12-07 17:16, Steven Rostedt wrote:
>
> [...]
>
> > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> > index 8d2a4f00eca9..b10deb8a5647 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(" %x: [%lld] delta:%lld TIME EXTEND\n",
>
> Please prefix hex values with "0x", as in:
>
> pr_warn(" 0x%x: [%lld] delta:%lld TIME EXTEND\n"
>
> Otherwise it can be confusing.
>

Heh, sure. I'm so use to looking at hex for the ring buffer offsets, that I
seldom add the 0x in my debug anymore. But as this is permanent, and not
just a one off print, I'll make the update and post a v2.

Thanks,

-- Steve