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

[Laurent Pinchart]

Hi Kieran,

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.

> 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