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

[Kieran Bingham]

Hi Laurent,

On 18/01/2020 23:19, Niklas Söderlund wrote:
> Hi Laurent,
> 
> Thanks for your work.
> 
> 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,

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


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
>>
>> _______________________________________________
>> libcamera-devel mailing list
>> libcamera-devel at lists.libcamera.org
>> https://lists.libcamera.org/listinfo/libcamera-devel
> 

-- 
Regards
--
Kieran