[libcamera-devel] [PATCH] libcamera: log: Print the function name in log

Laurent Pinchart laurent.pinchart at ideasonboard.com
Sat Aug 17 16:37:55 CEST 2019


Hi Niklas,

On Sat, Aug 17, 2019 at 03:45:56PM +0200, Niklas Söderlund wrote:
> On 2019-08-12 18:18:03 +0300, Laurent Pinchart wrote:
> > On Mon, Aug 12, 2019 at 02:49:19PM +0200, Jacopo Mondi wrote:
> > > Add the function name to the log tag.
> > > 
> > > With this patch applied, the log format looks like:
> > > INFO Camera camera_manager.cpp - start():83 libcamera v0.0.0+655-ddf32590
> > 
> > I think I would prefer keeping the line number associated with the file:
> > 
> > INFO Camera camera_manager.cpp:83 - start() libcamera v0.0.0+655-ddf32590
> 
> I agree with Laurent here, I like to line number to be kept together 
> with the file name.
> 
> > or maybe
> > 
> > INFO Camera start() (camera_manager.cpp:83) libcamera v0.0.0+655-ddf32590
> > 
> > ?
> > 
> > I'm a bit bothered by the missing class name to be honest, as it makes
> > the function name less useful without the context. The filename helps,
> > but then does the function name alone bring much added value ? What's
> > everybody's experience when reading logs, would the function name alone
> > improve readability even if it increases the length of the lines ?
> 
> I must admit when I read logs from C++ I only look at the file.cpp:line 
> marking and ignore the function name as without the class name it's not 
> so useful for me. I'm not bothered by it being in the output and I have 
> little concern about the length of the log lines, provided the file+line 
> information is early enough on the line.
> 
> That being said and to add to the bikesheeding, if the function name is 
> to be printed I think it could be useful to print it in its class 
> context.  My suggested log line would be something like:
> 
> INFO Camera camera_manager.cpp:83 CameraManager::start(): libcamera v0.0.0+655-ddf32590

The problem is that compilers don't offer a __class__ equivalent to
__func__ :-S There's a gcc-specific __PRETTY_FUNCTION__ that prints the
full name, including the namespace and arguments, which we could then
parse to extract the class name, but I'm not sure it's worse it.

> I do not (yet) find the Log categories super useful so I would be open 
> to discuss dropping them, but then again I'm not bothered by them and 
> maybe they can be useful for log filtering going forward.

I find them marginally useful in the log message itself, but for
filtering I think they are (or at least will be), if nothing else at
least to avoid printing a very large number of V4L2 QBUF/DQBUF or
request completion messages.

> > > Compared to:
> > > INFO Camera camera_manager.cpp:83 libcamera v0.0.0+654-a6799dc5
> > > 
> > > Signed-off-by: Jacopo Mondi <jacopo at jmondi.org>
> > > ---
> > >  src/libcamera/include/log.h | 19 +++++++++---------
> > >  src/libcamera/log.cpp       | 40 ++++++++++++++++++++++---------------
> > >  2 files changed, 34 insertions(+), 25 deletions(-)
> > > 
> > > diff --git a/src/libcamera/include/log.h b/src/libcamera/include/log.h
> > > index 9b203f97e304..e65d20af1ca9 100644
> > > --- a/src/libcamera/include/log.h
> > > +++ b/src/libcamera/include/log.h
> > > @@ -50,9 +50,9 @@ const LogCategory &_LOG_CATEGORY(name)()				\
> > >  class LogMessage
> > >  {
> > >  public:
> > > -	LogMessage(const char *fileName, unsigned int line,
> > > +	LogMessage(const char *fileName, const char *func, unsigned int line,
> > 
> > Should we name the new parameter funcName to match fileName ? Or rename
> > fileName to file ?
> > 
> > I would prefer keeping the file name and line number grouped, and thus
> > adding the func parameter either as the first parameter of the function,
> > or as the third one.
> > 
> > Same comments for all other functions or macros.
> > 
> > >  		   LogSeverity severity);
> > > -	LogMessage(const char *fileName, unsigned int line,
> > > +	LogMessage(const char *fileName, const char *func, unsigned int line,
> > >  		   const LogCategory &category, LogSeverity severity);
> > >  	LogMessage(const LogMessage &) = delete;
> > >  	LogMessage(LogMessage &&);
> > > @@ -67,7 +67,7 @@ public:
> > >  	const std::string msg() const { return msgStream_.str(); }
> > >  
> > >  private:
> > > -	void init(const char *fileName, unsigned int line);
> > > +	void init(const char *fileName, const char* func, unsigned int line);
> > >  
> > >  	std::ostringstream msgStream_;
> > >  	const LogCategory &category_;
> > > @@ -84,24 +84,25 @@ public:
> > >  protected:
> > >  	virtual std::string logPrefix() const = 0;
> > >  
> > > -	LogMessage _log(const char *file, unsigned int line,
> > > +	LogMessage _log(const char *file, const char *func, unsigned int line,
> > >  			LogSeverity severity) const;
> > > -	LogMessage _log(const char *file, unsigned int line,
> > > +	LogMessage _log(const char *file, const char *func, unsigned int line,
> > >  			const LogCategory &category,
> > >  			LogSeverity severity) const;
> > >  };
> > >  
> > > -LogMessage _log(const char *file, unsigned int line, LogSeverity severity);
> > > -LogMessage _log(const char *file, unsigned int line,
> > > +LogMessage _log(const char *file, const char *func, unsigned int line,
> > > +		LogSeverity severity);
> > > +LogMessage _log(const char *file, const char *func, unsigned int line,
> > >  		const LogCategory &category, LogSeverity severity);
> > >  
> > >  #ifndef __DOXYGEN__
> > >  #define _LOG_CATEGORY(name) logCategory##name
> > >  
> > >  #define _LOG1(severity) \
> > > -	_log(__FILE__, __LINE__, Log##severity).stream()
> > > +	_log(__FILE__, __func__, __LINE__, Log##severity).stream()
> > >  #define _LOG2(category, severity) \
> > > -	_log(__FILE__, __LINE__, _LOG_CATEGORY(category)(), Log##severity).stream()
> > > +	_log(__FILE__, __func__, __LINE__, _LOG_CATEGORY(category)(), Log##severity).stream()
> > >  
> > >  /*
> > >   * Expand the LOG() macro to _LOG1() or _LOG2() based on the number of
> > > diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
> > > index 91f7c3ee5157..fa9a16452f25 100644
> > > --- a/src/libcamera/log.cpp
> > > +++ b/src/libcamera/log.cpp
> > > @@ -720,6 +720,7 @@ const LogCategory &LogCategory::defaultCategory()
> > >  /**
> > >   * \brief Construct a log message for the default category
> > >   * \param[in] fileName The file name where the message is logged from
> > > + * \param[in] func The function name where the message is logged from
> > >   * \param[in] line The line number where the message is logged from
> > >   * \param[in] severity The log message severity, controlling how the message
> > >   * will be displayed
> > > @@ -728,16 +729,17 @@ const LogCategory &LogCategory::defaultCategory()
> > >   * \a severity argument sets the message severity to control whether it will be
> > >   * output or dropped.
> > >   */
> > > -LogMessage::LogMessage(const char *fileName, unsigned int line,
> > > +LogMessage::LogMessage(const char *fileName, const char *func ,unsigned int line,
> > >  		       LogSeverity severity)
> > >  	: category_(LogCategory::defaultCategory()), severity_(severity)
> > >  {
> > > -	init(fileName, line);
> > > +	init(fileName, func, line);
> > >  }
> > >  
> > >  /**
> > >   * \brief Construct a log message for a given category
> > >   * \param[in] fileName The file name where the message is logged from
> > > + * \param[in] func The function name where the message is logged from
> > >   * \param[in] line The line number where the message is logged from
> > >   * \param[in] category The log message category, controlling how the message
> > >   * will be displayed
> > > @@ -748,11 +750,11 @@ LogMessage::LogMessage(const char *fileName, unsigned int line,
> > >   * \a severity argument sets the message severity to control whether it will be
> > >   * output or dropped.
> > >   */
> > > -LogMessage::LogMessage(const char *fileName, unsigned int line,
> > > +LogMessage::LogMessage(const char *fileName, const char *func, unsigned int line,
> > >  		       const LogCategory &category, LogSeverity severity)
> > >  	: category_(category), severity_(severity)
> > >  {
> > > -	init(fileName, line);
> > > +	init(fileName, func, line);
> > >  }
> > >  
> > >  /**
> > > @@ -774,13 +776,14 @@ LogMessage::LogMessage(LogMessage &&other)
> > >  	other.severity_ = LogInvalid;
> > >  }
> > >  
> > > -void LogMessage::init(const char *fileName, unsigned int line)
> > > +void LogMessage::init(const char *fileName, const char *func, unsigned int line)
> > >  {
> > >  	/* Log the timestamp, severity and file information. */
> > >  	clock_gettime(CLOCK_MONOTONIC, &timestamp_);
> > >  
> > >  	std::ostringstream ossFileInfo;
> > > -	ossFileInfo << utils::basename(fileName) << ":" << line;
> > > +	ossFileInfo << utils::basename(fileName) << " - "
> > > +		    << func << "():" << line;
> > >  	fileInfo_ = ossFileInfo.str();
> > >  }
> > >  
> > > @@ -868,6 +871,7 @@ Loggable::~Loggable()
> > >  /**
> > >   * \brief Create a temporary LogMessage object to log a message
> > >   * \param[in] fileName The file name where the message is logged from
> > > + * \param[in] func The function name where the message is logged from
> > >   * \param[in] line The line number where the message is logged from
> > >   * \param[in] severity The log message severity
> > >   *
> > > @@ -876,10 +880,10 @@ Loggable::~Loggable()
> > >   *
> > >   * \return A log message
> > >   */
> > > -LogMessage Loggable::_log(const char *fileName, unsigned int line,
> > > -			  LogSeverity severity) const
> > > +LogMessage Loggable::_log(const char *fileName, const char *func,
> > > +			  unsigned int line, LogSeverity severity) const
> > >  {
> > > -	LogMessage msg(fileName, line, severity);
> > > +	LogMessage msg(fileName, func, line, severity);
> > >  
> > >  	msg.stream() << logPrefix() << ": ";
> > >  	return msg;
> > > @@ -888,6 +892,7 @@ LogMessage Loggable::_log(const char *fileName, unsigned int line,
> > >  /**
> > >   * \brief Create a temporary LogMessage object to log a message
> > >   * \param[in] fileName The file name where the message is logged from
> > > + * \param[in] func The function name where the message is logged from
> > >   * \param[in] line The line number where the message is logged from
> > >   * \param[in] category The log message category
> > >   * \param[in] severity The log message severity
> > > @@ -897,11 +902,11 @@ LogMessage Loggable::_log(const char *fileName, unsigned int line,
> > >   *
> > >   * \return A log message
> > >   */
> > > -LogMessage Loggable::_log(const char *fileName, unsigned int line,
> > > -			  const LogCategory &category,
> > > +LogMessage Loggable::_log(const char *fileName, const char *func,
> > > +			  unsigned int line, const LogCategory &category,
> > >  			  LogSeverity severity) const
> > >  {
> > > -	LogMessage msg(fileName, line, category, severity);
> > > +	LogMessage msg(fileName, func, line, category, severity);
> > >  
> > >  	msg.stream() << logPrefix() << ": ";
> > >  	return msg;
> > > @@ -910,6 +915,7 @@ LogMessage Loggable::_log(const char *fileName, unsigned int line,
> > >  /**
> > >   * \brief Create a temporary LogMessage object to log a message
> > >   * \param[in] fileName The file name where the message is logged from
> > > + * \param[in] func The function name where the message is logged from
> > >   * \param[in] line The line number where the message is logged from
> > >   * \param[in] severity The log message severity
> > >   *
> > > @@ -918,14 +924,16 @@ LogMessage Loggable::_log(const char *fileName, unsigned int line,
> > >   *
> > >   * \return A log message
> > >   */
> > > -LogMessage _log(const char *fileName, unsigned int line, LogSeverity severity)
> > > +LogMessage _log(const char *fileName, const char *func,
> > > +		unsigned int line, LogSeverity severity)
> > >  {
> > > -	return LogMessage(fileName, line, severity);
> > > +	return LogMessage(fileName, func, line, severity);
> > >  }
> > >  
> > >  /**
> > >   * \brief Create a temporary LogMessage object to log a message
> > >   * \param[in] fileName The file name where the message is logged from
> > > + * \param[in] func The function name where the message is logged from
> > >   * \param[in] line The line number where the message is logged from
> > >   * \param[in] category The log message category
> > >   * \param[in] severity The log message severity
> > > @@ -935,10 +943,10 @@ LogMessage _log(const char *fileName, unsigned int line, LogSeverity severity)
> > >   *
> > >   * \return A log message
> > >   */
> > > -LogMessage _log(const char *fileName, unsigned int line,
> > > +LogMessage _log(const char *fileName, const char *func, unsigned int line,
> > >  		const LogCategory &category, LogSeverity severity)
> > >  {
> > > -	return LogMessage(fileName, line, category, severity);
> > > +	return LogMessage(fileName, func, line, category, severity);
> > >  }
> > >  
> > >  /**

-- 
Regards,

Laurent Pinchart


More information about the libcamera-devel mailing list