[libcamera-devel] [PATCH v4 2/7] utils: raspberrypi: Add a DelayedControls log parser

[Kieran Bingham]

Hi Naush,

On 04/03/2021 08:17, Naushir Patuck wrote:
> This script will parse log output from the DelayedControls helper, when
> enabled with:
> 
> LIBCAMERA_LOG_LEVELS=DelayedControls:0
> 
> It tabulates all control queuing/writing/getting per frame and warns
> about potential issues related to frame delays not being account for, or
> writes that are lagging behind or missed.
> 
> Run with the following command:
> 
> python3 ./delayedctrls_parse.py <logfile>
> 
> Signed-off-by: Naushir Patuck <naush at raspberrypi.com>
> Tested-by: David Plowman <david.plowman at raspberrypi.com>
> Acked-by: Paul Elder <paul.elder at ideasonboard.com>

This patch has the following checkstyle warnings:

3ea0b3f4bee5670b4e46045836dee48928c3e1f2 utils: raspberrypi: Add a
DelayedControls log parser
---------------------------------------------------------------------------------------------
--- utils/raspberrypi/delayedctrls_parse.py
+++ utils/raspberrypi/delayedctrls_parse.py
#13: : W605 invalid escape sequence '\d'
+frame_re = re.compile('frame (\d+) started')
#29: : W605 invalid escape sequence '\d'
+    'Write': re.compile('Setting (.*?) to (\d+) at index (\d+)'),
#29: : W605 invalid escape sequence '\d'
+    'Write': re.compile('Setting (.*?) to (\d+) at index (\d+)'),
#31: : W605 invalid escape sequence '\d'
+    'Get': re.compile('Reading (.*?) to (\d+) at index (\d+)'),
#31: : W605 invalid escape sequence '\d'
+    'Get': re.compile('Reading (.*?) to (\d+) at index (\d+)'),
#32: : W605 invalid escape sequence '\d'
+    'Queue': re.compile('Queuing (.*?) to (\d+) at index (\d+)')
#32: : W605 invalid escape sequence '\d'
+    'Queue': re.compile('Queuing (.*?) to (\d+) at index (\d+)')
---
7 potential issues detected, please review


If you have pycodestyle installed (the pep8 update) you should get these
checks.


Prefixing the regex string with an 'r' fixes these.


If you're happy, and there' turns out to be no need to repost
 (I'm hoping not) I'll apply the following fix:



> diff --git a/utils/raspberrypi/delayedctrls_parse.py b/utils/raspberrypi/delayedctrls_parse.py
> index 3965b86daaaf..e38145d8e98e 100644
> --- a/utils/raspberrypi/delayedctrls_parse.py
> +++ b/utils/raspberrypi/delayedctrls_parse.py
> @@ -10,7 +10,7 @@ infile = sys.argv[1]
>  insplit = os.path.splitext(infile)
>  outfile = insplit[0] + '_parsed' + insplit[1]
>  
> -frame_re = re.compile('frame (\d+) started')
> +frame_re = re.compile(r'frame (\d+) started')
>  
>  delays = {
>      'Analogue Gain': 1,
> (1/2) Stage this hunk [y,n,q,a,d,j,J,g,/,e,?]? y
> @@ -26,10 +26,10 @@ ctrl_action = {
>  }
>  
>  ctrl_re = {
> -    'Write': re.compile('Setting (.*?) to (\d+) at index (\d+)'),
> -    'No-op': re.compile('Queue is empty, (.*?) (.*?) (.*?)'),
> -    'Get': re.compile('Reading (.*?) to (\d+) at index (\d+)'),
> -    'Queue': re.compile('Queuing (.*?) to (\d+) at index (\d+)')
> +    'Write': re.compile(r'Setting (.*?) to (\d+) at index (\d+)'),
> +    'No-op': re.compile(r'Queue is empty, (.*?) (.*?) (.*?)'),
> +    'Get': re.compile(r'Reading (.*?) to (\d+) at index (\d+)'),
> +    'Queue': re.compile(r'Queuing (.*?) to (\d+) at index (\d+)')
>  }
>  
>  frame_num = -1






> ---
>  utils/raspberrypi/delayedctrls_parse.py | 111 ++++++++++++++++++++++++
>  1 file changed, 111 insertions(+)
>  create mode 100644 utils/raspberrypi/delayedctrls_parse.py
> 
> diff --git a/utils/raspberrypi/delayedctrls_parse.py b/utils/raspberrypi/delayedctrls_parse.py
> new file mode 100644
> index 000000000000..3965b86daaaf
> --- /dev/null
> +++ b/utils/raspberrypi/delayedctrls_parse.py
> @@ -0,0 +1,111 @@
> +import re
> +import sys
> +import os
> +
> +if len(sys.argv) != 2:
> +    print("Usage: {} <infile>".format(sys.argv[0]))
> +    sys.exit()
> +
> +infile = sys.argv[1]
> +insplit = os.path.splitext(infile)
> +outfile = insplit[0] + '_parsed' + insplit[1]
> +
> +frame_re = re.compile('frame (\d+) started')
> +
> +delays = {
> +    'Analogue Gain': 1,
> +    'Exposure': 2,
> +    'Vertical Blanking': 2
> +}

Are these sensor dependant ?

Otherwise, with the raw string prefix,

Reviewed-by: Kieran Bingham <kieran.bingham at ideasonboard.com>

> +
> +ctrl_action = {
> +    'Write': {},
> +    'Get': {},
> +    'Queue': {},
> +    'No-op': {}
> +}
> +
> +ctrl_re = {
> +    'Write': re.compile('Setting (.*?) to (\d+) at index (\d+)'),
> +    'No-op': re.compile('Queue is empty, (.*?) (.*?) (.*?)'),
> +    'Get': re.compile('Reading (.*?) to (\d+) at index (\d+)'),
> +    'Queue': re.compile('Queuing (.*?) to (\d+) at index (\d+)')
> +}
> +
> +frame_num = -1
> +
> +max_delay = 0
> +for k, d in delays.items():
> +    if max_delay < d:
> +        max_delay = d
> +
> +with open(infile) as f:
> +    lines = f.readlines()
> +
> +for line in lines:
> +    r = frame_re.search(line)
> +    if r:
> +        frame_num = int(r.group(1))
> +
> +    for (key, re) in ctrl_re.items():
> +        r = re.search(line)
> +        if r:
> +            ctrl_action[key][(frame_num, r.group(1))] = (r.group(2), r.group(3))
> +
> +with open(outfile, 'wt') as f:
> +    queueIndex = 1
> +    f.write('{:<10}{:<15}{:<12}{:<18}{}\n'.format('Frame', 'Action', 'Gain', 'Exposure', 'Vblank'))
> +    for frame in range(0, frame_num + 1):
> +        for (k, a) in ctrl_action.items():
> +            str = '{:<10}{:<10}'.format(frame, k)
> +
> +            for c in delays.keys():
> +                # Tabulate all results
> +                str += '{:>5} {:<10}'.format(a[(frame, c)][0] if (frame, c) in a.keys() else '---',
> +                                             '[' + (a[(frame, c)][1] if (frame, c) in a.keys() else '-') + ']')
> +
> +            f.write(str.strip() + '\n')
> +
> +# Test the write -> get matches the set delay.
> +for (frame, c) in ctrl_action['Write'].keys():
> +    set_value = ctrl_action['Write'][(frame, c)][0]
> +    delay_frame = frame + delays[c]
> +    if (delay_frame <= frame_num):
> +        if (delay_frame, c) in ctrl_action['Get']:
> +            get_value = ctrl_action['Get'][(delay_frame, c)][0]
> +            if get_value != set_value:
> +                print('Error: {} written at frame {} to value {} != {} at frame {}'
> +                      .format(c, frame, set_value, get_value, delay_frame))
> +        else:
> +            print('Warning: {} written at frame {} to value {} did not get logged on frame {} - dropped frame?'
> +                  .format(c, frame, set_value, delay_frame))
> +
> +# Test the queue -> write matches the set delay.
> +for (frame, c) in ctrl_action['Queue'].keys():
> +    set_value = ctrl_action['Queue'][(frame, c)][0]
> +    delay_frame = frame + max_delay - delays[c] + 1
> +    if (delay_frame <= frame_num):
> +        if (delay_frame, c) in ctrl_action['Write']:
> +            write_value = ctrl_action['Write'][(delay_frame, c)][0]
> +            if write_value != set_value:
> +                print('Info: {} queued at frame {} to value {} != {} written at frame {}'
> +                      ' - lagging behind or double queue on a single frame!'
> +                      .format(c, frame, set_value, write_value, delay_frame))
> +        else:
> +            print('Warning: {} queued at frame {} to value {} did not get logged on frame {} - dropped frame?'
> +                  .format(c, frame, set_value, delay_frame))
> +
> +# Test the get -> write matches the set delay going backwards.
> +for (frame, c) in ctrl_action['Get'].keys():
> +    get_value = ctrl_action['Get'][(frame, c)][0]
> +    delay_frame = frame - delays[c]
> +    if (delay_frame >= 6):
> +        if (delay_frame, c) in ctrl_action['Write']:
> +            write_value = ctrl_action['Write'][(delay_frame, c)][0]
> +            if get_value != write_value:
> +                print('Info: {} got at frame {} to value {} != {} written at frame {}'
> +                      ' - lagging behind or double queue on a single frame!'
> +                      .format(c, frame, get_value, write_value, delay_frame))
> +        else:
> +            print('Warning: {} got at frame {} to value {} did not get written on frame {}'
> +                  .format(c, frame, get_value, delay_frame))
> 

-- 
Regards
--
Kieran