| Message ID | 20210420130741.236848-6-kieran.bingham@ideasonboard.com |
|---|---|
| State | Accepted |
| Headers | show |
| Series |
|
| Related | show |
Hi Kieran, Thanks for the patch ! On 20/04/2021 15:07, 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@ideasonboard.com> > Reviewed-by: Jean-Michel Hautbois <jeanmichel.hautbois@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) > > 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)) >
Hi Kieran, Thank you for the patch. 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@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 ? The short function name has limited value, while the pretty function name is likely too long :-S 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. > 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))
Hi Laurent, On 20/04/2021 23:05, Laurent Pinchart wrote: > Hi Kieran, > > Thank you for the patch. > > 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@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. > 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... > 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. >> 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)) >
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@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))
Hi Laurent, On 23/04/2021 03:36, Laurent Pinchart wrote: > 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@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. 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)) >
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@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))
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@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)) >
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@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@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))
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))
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@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) include/libcamera/internal/log.h | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-)