[PATCH i-g-t] lib/igt_core: Free log_buffer entries on exit

[Vivekanandan, Balasubramani]

On 07.11.2024 12:36, Lucas De Marchi wrote:
> On Thu, Nov 07, 2024 at 06:31:45PM +0100, Kamil Konieczny wrote:
> > Hi Lucas,
> > On 2024-11-06 at 23:02:08 -0800, Lucas De Marchi wrote:
> > > Make sure the buffer entries are released, otherwise valgrind output
> > > becomes each used entry as still reachable on exit (up to 256).
> > > 
> > > Test:
> > > 	# valgrind --leak-check=full  ./build/tests/xe_live_ktest  --r xe_mocs
> > > 
> > > Before:
> > > 	==16082== LEAK SUMMARY:
> > > 	==16082==    definitely lost: 0 bytes in 0 blocks
> > > 	==16082==    indirectly lost: 0 bytes in 0 blocks
> > > 	==16082==      possibly lost: 0 bytes in 0 blocks
> > > 	==16082==    still reachable: 33,473 bytes in 59 blocks
> > > 
> > > After:
> > > 	==15992== LEAK SUMMARY:
> > > 	==15992==    definitely lost: 0 bytes in 0 blocks
> > > 	==15992==    indirectly lost: 0 bytes in 0 blocks
> > > 	==15992==      possibly lost: 0 bytes in 0 blocks
> > > 	==15992==    still reachable: 31,083 bytes in 42 blocks
> > 
> > Thank you for a patch, there are still some blocks left,
> > maybe because that buffer is a ring? e.g. it could have
> > end < start
> 
> no, those blocks are other things.
> 
> Note that we are looping with a uint8_t. When we have start == 250
> and end == 2 (impossible due to how we place log messages, but just for
> illustration), it's expected to free the positions [250, 255], [0, 1].
> 
> Some more context explanation of this change.
> 
> I sent this because the first leaks I was seeing were related to libkmod
> and as the libkmod maintainer I was curious if it was a leak in libkmod
> that was getting masked by us not releasing its ctx. It was not, and
> just releasing the ctx (see
> https://patchwork.freedesktop.org/patch/623301/?series=140746&rev=3)
> made those go away.  While doing that and running other more log-heavy
> tests, I was getting a flood of these 256 blocks, so I fixed that just
> to get them out of the way of what I was really after.
> 
> Looking back to this patch, not sure there's much value as whatever
> binary using it is already on its way out.
> 
> > 
> > > 
> > > Signed-off-by: Lucas De Marchi <lucas.demarchi at intel.com>
> > > ---
> > >  lib/igt_core.c | 15 ++++++++++++---
> > >  1 file changed, 12 insertions(+), 3 deletions(-)
> > > 
> > > diff --git a/lib/igt_core.c b/lib/igt_core.c
> > > index 407f7b551..879d1ecd8 100644
> > > --- a/lib/igt_core.c
> > > +++ b/lib/igt_core.c
> > > @@ -469,11 +469,21 @@ static void _igt_log_buffer_append(char *line)
> > >  	pthread_mutex_unlock(&log_buffer_mutex);
> > >  }
> > > 
> > > +static void _igt_log_buffer_reset_locked(void)
> > > +{
> > > +	for (; log_buffer.start != log_buffer.end; log_buffer.start++) {
> > > +		free(log_buffer.entries[log_buffer.start]);
> > > +		log_buffer.entries[log_buffer.start] = NULL;
> > > +	}
> > 
> > Here you should use the same loop as in _dump, so
> > 
> > 	i = log_buffer.start;
> > 	do {
> > 		// do ops here
> > 		i++;
> >        } while (i != log_buffer.start && i != log_buffer.end);
> 
> there's an off-by-one bug in this loop that I didn't want to reproduce
> here: if we never ever logged anything, at the beggining start == end == 0,
> and in the first check i == 1. Which means we will print (or free in
> this case) the 256 entries. Oops.  I think we always log at least the
> test name, so it's not a bug we reproduce.
> 
> > 
> > Or even simpler, init with NULLs and then just free all?
> 
> it's a static variable, it's already zero initialized.
> 
> > For example, if start=2, end=1, there is still a valid pointer
> > at end==1
> 
> no, end marks where the *next* entry will be. At the beginning we have:
> 
> start == end == 0. There are no entries in the ringbuffer.
> 
> After the first logged message:
> start == 0, end == 1.
> 
> If the ringbuffer ever wraps, then we will always have:
> 
> start == x + 1; end == x, or
> start == 0; end == 255

When the ringbuffer wraps to the beginning, the end would now be
pointing to a valid address of a allocated memory. It needs to be freed
while reseting the buffer.
The condition in your for loop 'log_buffer.start != log_buffer.end'
skips freeing the buffer at log_buffer.end.

Regards,
Bala

> 
> Except for when dumping the contents, this ringbuffer doesn't have any
> consumer incrementing the start AFAICS.
> 
> > 
> > Or do one more ops for case 'end < start'
> 
> in the wrap case, see above. The key of the implementation is that we
> are using a uint8_t and relying on it wrapping back to 0, so we can just
> increment the head until it reaches the tail.
> 
> As said above, there isn't much value in this patch other than "let's
> get it right", so consider it optional.
> 
> 
> Lucas De Marchi
> 
> > 
> > Regards,
> > Kamil
> > 
> > > +
> > > +	log_buffer.start = log_buffer.end = 0;
> > > +}
> > > +
> > >  static void _igt_log_buffer_reset(void)
> > >  {
> > >  	pthread_mutex_lock(&log_buffer_mutex);
> > > 
> > > -	log_buffer.start = log_buffer.end = 0;
> > > +	_igt_log_buffer_reset_locked();
> > > 
> > >  	pthread_mutex_unlock(&log_buffer_mutex);
> > >  }
> > > @@ -624,8 +634,7 @@ static void _igt_log_buffer_dump(void)
> > >  		i++;
> > >  	} while (i != log_buffer.start && i != log_buffer.end);
> > > 
> > > -	/* reset the buffer */
> > > -	log_buffer.start = log_buffer.end = 0;
> > > +	_igt_log_buffer_reset_locked();
> > > 
> > >  	_log_line_fprintf(stderr, "****  END  ****\n");
> > >  	pthread_mutex_unlock(&log_buffer_mutex);
> > > --
> > > 2.47.0
> > >