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

[Kieran Bingham]

Hi Laurent,

On 20/01/2020 11:20, Laurent Pinchart wrote:
> 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.

I think for a thread ID it would probably just be whitespace padding.
Leading-Zero padding is an option, but not a friendly one.

Agreed though, I don't think it's an issue for this patch - lets get
these integrated.

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