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

[Naushir Patuck]

Hi Kieran,

On Fri, 12 Mar 2021 at 13:12, Kieran Bingham <
kieran.bingham at ideasonboard.com> wrote:

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

Will do!


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

Happy for you to fixup when merging if it is convenient.

Regards,
Naush



>
>
> > 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libcamera.org/pipermail/libcamera-devel/attachments/20210312/280806c8/attachment.htm>