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

[Laurent Pinchart]

Hi Kieran,

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.

> >>  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