Re: [PATCH 3/3] kbuffer: Update kbuf->next in kbuffer_refresh()

From: Vincent Donnefort <vdonnefort@google.com>
To: Steven Rostedt <rostedt@goodmis.org>
Cc: linux-trace-devel@vger.kernel.org
Subject: Re: [PATCH 3/3] kbuffer: Update kbuf->next in kbuffer_refresh()
Date: Mon, 8 Jan 2024 11:11:29 +0000	[thread overview]
Message-ID: <ZZvYYY5MI8l803Ad@google.com> (raw)
In-Reply-To: <ZZhuKFAkDHRLHlwt@google.com>

On Fri, Jan 05, 2024 at 09:01:28PM +0000, Vincent Donnefort wrote:
> On Fri, Jan 05, 2024 at 02:37:44PM -0500, Steven Rostedt wrote:
> > From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
> > 
> > If the kbuffer was read to completion, the kbuf->curr would equal both the
> > size and kbuf->next. The kbuffer_refresh() is to update the kbuf if more
> > data was added to the buffer. But if curr is at the end, the next pointer
> > was not updated, which is incorrect. The next pointer needs to be moved to
> > the end of the newly written event.
> > 
> > Update the pointers in kbuffer_refresh() just as if it was loaded new (but
> > still keeping curr at the correct location).
> > 
> > Link: https://lore.kernel.org/linux-trace-devel/ZZfJQTOyl0dHiTU-@google.com/
> > 
> > Reported-by: Vincent Donnefort <vdonnefort@google.com>
> > Fixes: 7a4d5b24 ("kbuffer: Add kbuffer_refresh() API")
> > Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> > ---
> >  src/kbuffer-parse.c | 14 ++++++++++++++
> >  1 file changed, 14 insertions(+)
> > 
> > diff --git a/src/kbuffer-parse.c b/src/kbuffer-parse.c
> > index 4801d432c58c..1e1d168b534c 100644
> > --- a/src/kbuffer-parse.c
> > +++ b/src/kbuffer-parse.c
> > @@ -299,6 +299,9 @@ void kbuffer_free(struct kbuffer *kbuf)
> >  	free(kbuf);
> >  }
> >  
> > +static unsigned int old_update_pointers(struct kbuffer *kbuf);
> > +static unsigned int update_pointers(struct kbuffer *kbuf);
> > +
> >  /**
> >   * kbuffer_refresh - update the meta data from the subbuffer
> >   * @kbuf; The kbuffer to update
> > @@ -309,13 +312,24 @@ void kbuffer_free(struct kbuffer *kbuf)
> >  int kbuffer_refresh(struct kbuffer *kbuf)
> >  {
> >  	unsigned long long flags;
> > +	unsigned int old_size;
> >  
> >  	if (!kbuf || !kbuf->subbuffer)
> >  		return -1;
> >  
> > +	old_size = kbuf->size;
> > +
> >  	flags = read_long(kbuf, kbuf->subbuffer + 8);
> >  	kbuf->size = (unsigned int)flags & COMMIT_MASK;
> >  
> > +	/* Update next to be the next element */
> > +	if (kbuf->size != old_size && kbuf->curr == old_size) {
> > +		if (kbuf->flags & KBUFFER_FL_OLD_FORMAT)
> > +			old_update_pointers(kbuf);
> > +		else
> > +			update_pointers(kbuf);
> > +	}
> > +
> >  	return 0;
> >  }
> 
> I've been trying the new stack but I see some weird unexpected events:
> 
> $ echo 3 > /sys/kernel/debug/tracing/trace_marker
> 
> <...>-5 44401.178473328 mmiotrace_rw: 0 0 0 0 0 0     // I clearly didn't enable this event
> <...>-208 44401.178473328       print: tracing_mark_write: 2
> 
> 
> Looking closer at the kbuf I see before the kbuffer_refresh()
> 
>   index = 244, curr = 272, next = 272, size = 272, start = 16
> 
> And after
> 
>   index = 280, curr = 272, next = 280, size = 312, start = 16
> 
> Could this index be the problem as this is used in kbuffer_read_event()?

Yeah it seems that the update_pointers() is not enough. 

kbuffer_next_event(kbuf, NULL) will make sure curr is also up to date and will
do the update until an event type we can read. With that change I don't see any
spurious "mmiotrace_rw" on the output.

> 
> >  
> > -- 
> > 2.42.0
> > 