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

[Kieran Bingham]

Hi Laurent,

On 27/04/2021 07:58, Laurent Pinchart wrote:
> 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.


A tag of some form would convince me of that ;-)

--
Kieran



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