[libcamera-devel] [PATCH v4 5/6] libcamera: internal: log: Report function on asserts

[Laurent Pinchart]

On Tue, Apr 27, 2021 at 08:58:53AM +0100, Kieran Bingham wrote:
> On 27/04/2021 07:58, Laurent Pinchart wrote:
> > On Mon, Apr 26, 2021 at 09:44:59AM +0100, Kieran Bingham wrote:
> >> On 23/04/2021 03:36, Laurent Pinchart wrote:
> >>> On Thu, Apr 22, 2021 at 11:17:39AM +0100, Kieran Bingham wrote:
> >>>> On 20/04/2021 23:05, Laurent Pinchart wrote:
> >>>>> On Tue, Apr 20, 2021 at 02:07:40PM +0100, Kieran Bingham wrote:
> >>>>>> Report the function which fails an assertion as well as the actual
> >>>>>> assertion.
> >>>>>>
> >>>>>> This now reports as:
> >>>>>>
> >>>>>> [30:08:53.218816270] [226567] FATAL default request.cpp:150 assertion "d" failed in reuse()
> >>>>>> rather than:
> >>>>>> [30:11:05.271888926] [228531] FATAL default request.cpp:150 assertion "d" failed
> >>>>>>
> >>>>>> Signed-off-by: Kieran Bingham <kieran.bingham at ideasonboard.com>
> >>>>>>
> >>>>>> ---
> >>>>>> We could use __PRETTY_FUNCTION__ instead to get:
> >>>>>> [30:17:16.736265045] [232054] FATAL default request.cpp:150 assertion "d" failed in void libcamera::Request::reuse(libcamera::Request::ReuseFlag)
> >>>>>
> >>>>> Is this feature useful for an ASSERT() only, or should we print the
> >>>>> function name in all log messages ?
> >>>>
> >>>> At the moment, I didn't want to change for all, as it makes everything
> >>>> longer.
> >>>>
> >>>> What I liked about having the ASSERT say the function name is it helps
> >>>> quickly identify the assertion failure.
> >>>>
> >>>> For instance, there may be multiple identical /equivalent assertions in
> >>>> lots of functions through a module.
> >>>>
> >>>> When it happens, I want to know quickly which one it was.
> >>>>
> >>>> For example, the Assertions added into request, as demonstrated above
> >>>> would give the same print for 6 ASSERTs with only the line number as a
> >>>> difference.
> >>>>
> >>>> That's much easier to parse if it states /which/ instance of the assert
> >>>> failed, without relying on a further lookup to get the initial feel for
> >>>> what went wrong.
> >>>
> >>> My workflow would be to then immediately jump to that function to dig
> >>> deeper, which the line number would allow me to do as easily. Printing
> >>> the function name will tell me what function has thrown the assert a few
> >>> seconds earlier, which seems a short amount of time (time is relative
> >>> though :-)). Your mileage may vary though, and if this really makes it 
> >>> easier for you, I'm sure it could also help other developers, so I'm not
> >>> opposed to the change. As it doesn't match my personal experience, I'd 
> >>> just like to avoid merging it with an illusion that it will help, to 
> >>> only realize later that it doesn't. I trust your judgement and your 
> >>> confidence, so you can decide if you want to carry the change locally 
> >>> for a bit to test it, or merge it now. We can also consider merging it 
> >>> to see if it helps other developers and revert it later if everybody 
> >>> ends up not using this feature. Up to you.
> >>>
> >>>>> The short function name has limited
> >>>>> value, while the pretty function name is likely too long :-S
> >>>>
> >>>> The 'too long' is why I have chosen the short version...
> >>>
> >>> Would be nice to have a __SHORT_PRETTY_FUNCTION__ that would print
> >>> "Request::reuse()". The compiler should magically understand that we
> >>> don't need the namespace to be printed if it's just "libcamera" :-)
> >>>
> >>>>> Given that debugging an assertion failure involves open the source
> >>>>> anyway, I wonder if there's an actual value in printing the function
> >>>>> name as we have the file name and line number.
> >>>>
> >>>> Sure - but not always if you're already deep into debugging something.
> >>>>
> >>>> Imagine you throw a handful of extra assertions in, across a set of
> >>>> functions and what you are trying to do is rapidly narrow down the
> >>>> cause... function names help there to save a manual lookup process.
> >>>
> >>> My personal experience is that line numbers are more important, as I
> >>> usually end up throwing log messages in different places in the same
> >>> function. Again, your mileage may very well vary, my data point is just
> >>> that, a single data point.
> >>
> >> Yes, but please remember lots of people are different. Some people
> >> recognise numbers better than words, and some people follow words better
> >> than numbers ... All we're doing here is adding an extra word to a
> >> hopefully rare debug print.
> > 
> > There's no need to convince me :-) As I've said, I wanted to make sure
> > that you had really tested this as helping your debugging experience, as
> > opposed to only thinking it could improve it without actually testing
> > it. As you say you have, that's enough for me, I trust you, and I'm fine
> > with the change.
> 
> A tag of some form would convince me of that ;-)

Reviewed-by: Laurent Pinchart <laurent.pinchart at ideasonboard.com>

> >> I'm in the later camp. A word will help me prepare my brain for where to
> >> search.
> >>
> >> I might tell you that I live in <street>, Filton, Bristol, which is a
> >> close approximation to where I live, and not quite as detailed as
> >>
> >>   51.50080108642578, -2.5474119186401367 (not my actual address)
> >>
> >> And for commencing the journey in either case the reader will likely
> >> have to look up the exact destination, but a lot more information is
> >> conveyed with the words than the numbers pre-lookup ...
> >>
> >> Of course you might then say but my house has a numerical address, which
> >> indeed it does, lets call it 100 stop()street, v4l2_device()town....
> >>
> >> The line number helps provide the final destination address, but to me,
> >> the function name is the street name. Perhaps not always essential, but
> >> a very useful reference point.
> >>
> >> And certainly if you have lots of debug prints in the same function,
> >> then the line number matters. But we already have the line number, so
> >> I'm not going to argue over the value of that ;-)
> >>
> >>>>>>  include/libcamera/internal/log.h | 7 ++++---
> >>>>>>  1 file changed, 4 insertions(+), 3 deletions(-)
> >>>>>>
> >>>>>> diff --git a/include/libcamera/internal/log.h b/include/libcamera/internal/log.h
> >>>>>> index be0bab3c1272..b66bf55bc57d 100644
> >>>>>> --- a/include/libcamera/internal/log.h
> >>>>>> +++ b/include/libcamera/internal/log.h
> >>>>>> @@ -117,9 +117,10 @@ LogMessage _log(const LogCategory *category, LogSeverity severity,
> >>>>>>  #endif /* __DOXYGEN__ */
> >>>>>>  
> >>>>>>  #ifndef NDEBUG
> >>>>>> -#define ASSERT(condition) static_cast<void>(({				\
> >>>>>> -	if (!(condition))						\
> >>>>>> -		LOG(Fatal) << "assertion \"" #condition "\" failed";	\
> >>>>>> +#define ASSERT(condition) static_cast<void>(({                          \
> >>>>>> +	if (!(condition))                                               \
> >>>>>> +		LOG(Fatal) << "assertion \"" #condition "\" failed in " \
> >>>>>> +			   << __func__ << "()";                         \
> >>>>>>  }))
> >>>>>>  #else
> >>>>>>  #define ASSERT(condition) static_cast<void>(false && (condition))

-- 
Regards,

Laurent Pinchart