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

[Jean-Michel Hautbois]

Hi Naushir,

This is very helpful !

On 04/03/2021 09: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>
Tested-by: Jean-Michel Hautbois <jeanmichel.hautbois at ideasonboard.com>

> ---
>  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
> +}
> +
> +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))
>