Re: [PATCH 3/5] logger: Log to the FTrace buffer if tracing is enabled

[Laurent Pinchart]

Hi Kieran,

On Friday 25 Nov 2016 18:10:10 Kieran Bingham wrote:
> On 25/11/16 17:40, Laurent Pinchart wrote:
> > On Friday 25 Nov 2016 13:59:14 Kieran Bingham wrote:
> >> From: Kieran Bingham 
> >> 
> >> Extend the logger such that it will detect the tracing system, and also
> >> append print statement to this ring buffer.
> >> 
> >> This provides the relevant logging output interspersed in the ftrace
> >> logs for an effective solution to identifying the actions that caused
> >> the traces to occur
> >> 
> >> Signed-off-by: Kieran Bingham 
> >> ---
> >> 
> >>  scripts/logger.sh | 13 -
> >>  1 file changed, 12 insertions(+), 1 deletion(-)
> >> 
> >> diff --git a/scripts/logger.sh b/scripts/logger.sh
> >> index 8123f0c9f6e3..8412b0ba9a08 100755
> >> --- a/scripts/logger.sh
> >> +++ b/scripts/logger.sh
> >> @@ -6,6 +6,17 @@ now() {
> >> 
> >>  label=${1:+ [$1]}
> >> 
> >> +TRACE_MARKER=/sys/kernel/debug/tracing/trace_marker
> >> +if [ -e $TRACE_MARKER ]; then
> >> +  extra_log_files=$TRACE_MARKER
> >> +fi
> >> +
> >> 
> >>  while read line ; do
> >> 
> >> -  echo "$(now)$label $line"
> >> +  newline="$(now)$label $line"
> >> +
> >> +  echo "$newline"
> >> +
> >> +  for f in $extra_log_files; do
> >> +  echo "$newline" >> $f;
> > 
> > As the tracer adds a timestamp, should you echo "$label $line" only here ?
> 
> Hrm, yes it is possibly a little bit redundant...
> 
> My only argument would be that it will be a 'different' timestamp to the
> one logged by logger.sh.
> 
> Inspection of a recent log shows a difference of around 40-50 ms, which
> will be the latency between capturing the time in $(now) and passing the
> buffer to the kernel.
> 
> At this level though, the logger.sh is already susceptible to scheduler
> jitter anyway, so I'm not too worried about 40 ms. But anyone reading
> the logs will have to be aware of that extra latency.

If you think we should keep the timestamp I'm fine with that.

> >> +  done;
> >> 
> >>  done

-- 
Regards,

Laurent Pinchart

Re: [PATCH 3/5] logger: Log to the FTrace buffer if tracing is enabled

[Kieran Bingham]

Hi Laurent,

On 25/11/16 17:40, Laurent Pinchart wrote:
> Hi Kieran,
> 
> Thank you for the patch.
> 
> On Friday 25 Nov 2016 13:59:14 Kieran Bingham wrote:
>> From: Kieran Bingham 
>>
>> Extend the logger such that it will detect the tracing system, and also
>> append print statement to this ring buffer.
>>
>> This provides the relevant logging output interspersed in the ftrace
>> logs for an effective solution to identifying the actions that caused
>> the traces to occur
>>
>> Signed-off-by: Kieran Bingham 
>> ---
>>  scripts/logger.sh | 13 -
>>  1 file changed, 12 insertions(+), 1 deletion(-)
>>
>> diff --git a/scripts/logger.sh b/scripts/logger.sh
>> index 8123f0c9f6e3..8412b0ba9a08 100755
>> --- a/scripts/logger.sh
>> +++ b/scripts/logger.sh
>> @@ -6,6 +6,17 @@ now() {
>>
>>  label=${1:+ [$1]}
>>
>> +TRACE_MARKER=/sys/kernel/debug/tracing/trace_marker
>> +if [ -e $TRACE_MARKER ]; then
>> +extra_log_files=$TRACE_MARKER
>> +fi
>> +
>>  while read line ; do
>> -echo "$(now)$label $line"
>> +newline="$(now)$label $line"
>> +
>> +echo "$newline"
>> +
>> +for f in $extra_log_files; do
>> +echo "$newline" >> $f;
> 
> As the tracer adds a timestamp, should you echo "$label $line" only here ?

Hrm, yes it is possibly a little bit redundant...

My only argument would be that it will be a 'different' timestamp to the
one logged by logger.sh.

Inspection of a recent log shows a difference of around 40-50 ms, which
will be the latency between capturing the time in $(now) and passing the
buffer to the kernel.

At this level though, the logger.sh is already susceptible to scheduler
jitter anyway, so I'm not too worried about 40 ms. But anyone reading
the logs will have to be aware of that extra latency.


> 
>> +done;
>>  done
> 

Re: [PATCH 3/5] logger: Log to the FTrace buffer if tracing is enabled

[Laurent Pinchart]

Hi Kieran,

Thank you for the patch.

On Friday 25 Nov 2016 13:59:14 Kieran Bingham wrote:
> From: Kieran Bingham 
> 
> Extend the logger such that it will detect the tracing system, and also
> append print statement to this ring buffer.
> 
> This provides the relevant logging output interspersed in the ftrace
> logs for an effective solution to identifying the actions that caused
> the traces to occur
> 
> Signed-off-by: Kieran Bingham 
> ---
>  scripts/logger.sh | 13 -
>  1 file changed, 12 insertions(+), 1 deletion(-)
> 
> diff --git a/scripts/logger.sh b/scripts/logger.sh
> index 8123f0c9f6e3..8412b0ba9a08 100755
> --- a/scripts/logger.sh
> +++ b/scripts/logger.sh
> @@ -6,6 +6,17 @@ now() {
> 
>  label=${1:+ [$1]}
> 
> +TRACE_MARKER=/sys/kernel/debug/tracing/trace_marker
> +if [ -e $TRACE_MARKER ]; then
> + extra_log_files=$TRACE_MARKER
> +fi
> +
>  while read line ; do
> - echo "$(now)$label $line"
> + newline="$(now)$label $line"
> +
> + echo "$newline"
> +
> + for f in $extra_log_files; do
> + echo "$newline" >> $f;

As the tracer adds a timestamp, should you echo "$label $line" only here ?

> + done;
>  done

-- 
Regards,

Laurent Pinchart