[libcamera-devel] [PATCH 2/2] libcamera: log: Print the thread ID in the log

[Laurent Pinchart]

Hi Kieran,

On Mon, Jan 20, 2020 at 10:23:54AM +0000, Kieran Bingham wrote:
> On 18/01/2020 23:19, Niklas Söderlund wrote:
> > On 2020-01-18 23:33:48 +0200, Laurent Pinchart wrote:
> >> The current thread ID is useful when debugging concurrency issues. Print
> >> it in log messages. The syslog target is left out as the thread ID would
> >> have little use there, and partly duplicates the process ID.
> 
> An example print here would be nice to make it easy to see the effect,

I'll add

The log messages now look as follows.

[19:10:33.206560546] [22096] INFO Camera camera_manager.cpp:274 libcamera v0.0.0+993-32696686

> >> Signed-off-by: Laurent Pinchart <laurent.pinchart at ideasonboard.com>
> > 
> > Reviewed-by: Niklas Söderlund <niklas.soderlund at ragnatech.se>
> > 
> >> ---
> >>  src/libcamera/log.cpp | 4 +++-
> >>  1 file changed, 3 insertions(+), 1 deletion(-)
> >>
> >> diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
> >> index f4eb8c11adc3..1dac4666b435 100644
> >> --- a/src/libcamera/log.cpp
> >> +++ b/src/libcamera/log.cpp
> >> @@ -22,6 +22,7 @@
> >>  
> >>  #include <libcamera/logging.h>
> >>  
> >> +#include "thread.h"
> >>  #include "utils.h"
> >>  
> >>  /**
> >> @@ -196,7 +197,8 @@ void LogOutput::write(const LogMessage &msg)
> >>  		break;
> >>  	case LoggingTargetStream:
> >>  	case LoggingTargetFile:
> >> -		str = "[" + utils::time_point_to_string(msg.timestamp()) + "]"
> >> +		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
> 
> As we already have 2 characters to 'wrap' both the timestamp, and the
> thread ID, do we really need to add a third 'whitespace' separator?
> 
> The debug lines are already getting quite long... So we can argue both
> ways, padding is expensive, or lines are already so long - that the
> length doesn't matter...
> 
> It would be nice if we could keep our debug lines under 120 chars though
> (Purely arbitrary/selfish, That's my terminal width :-D)
> 
> Noting of course that I have another patch which expands the debug log
> level to normalise spelling against their other usages which expands
> this string by another character too ...
> 
> >> +		    + std::to_string(Thread::currentId()) + "]"
> 
> Should we print this with a fixed width?
> (Yes, I know that would cost extra characters of course)
> 
> In fact, I think I've argued myself out of this one.
> My rationale was to stop something like this:
> 
> > [80:48:31.722536024] DEBUG V4L2 v4l2_videodevice.cpp:1185 /dev/video0[cap]: Queueing buffer 0
> > [80:48:31.757739217] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video0[cap]: Dequeuing buffer 1
> 
> looking like this:
> 
> > [80:48:31.722536024] [1234] DEBUG V4L2 v4l2_videodevice.cpp:1185 /dev/video0[cap]: Queueing buffer 0
> > [80:48:31.757739217] [123] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video0[cap]: Dequeuing buffer 1
> 
> As keeping the alignment on the actual message is nicer. But perhaps we
> just need a log parser like Gstreamer provides.

I agree there are arguments both ways, and one of my annoyances with the
gstreamer log is indeed the line length. However, it's hard to be both
verbose and terse at the same time :-)

In this specific case, what would you pad the TID with ? Note that it
would have to be padded to 5 characters unconditionally. I'm tempted to
solve this issue latter, possibly as part of your patch that expands the
log level, turning it into a log line normalization patch ? We could
then discuss the matter separately from this issue.

> Discussion comments aside,
> 
> Reviewed-by: Kieran Bingham <kieran.bingham at ideasonboard.com>
> 
> >>  		    + log_severity_name(msg.severity()) + " "
> >>  		    + msg.category().name() + " " + msg.fileInfo() + " "
> >>  		    + msg.msg();

-- 
Regards,

Laurent Pinchart