[libcamera-devel,v2,2/5] utils: raspberrypi: Add a DelayedControls log parser
diff mbox series

Message ID 20210216085342.1012717-3-naush@raspberrypi.com
State Superseded
Delegated to: Niklas Söderlund
Headers show
Series
  • DelayedControls updates and fixes
Related show

Commit Message

Naushir Patuck Feb. 16, 2021, 8:53 a.m. UTC 
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@raspberrypi.com>
---
 utils/raspberrypi/delayedctrls_parse.py | 98 +++++++++++++++++++++++++
 1 file changed, 98 insertions(+)
 create mode 100644 utils/raspberrypi/delayedctrls_parse.py

Comments

Paul Elder March 1, 2021, 8:42 a.m. UTC | #1 
Hi Naush,

On Tue, Feb 16, 2021 at 08:53:39AM +0000, 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@raspberrypi.com>

I'm thinking that in the future it would be better to move debug output
of this type to tracepoints instead of logging, to avoid cluttering up
the log with such frequent debug messages.

Until we make that change though, I think this script is useful.

> ---
>  utils/raspberrypi/delayedctrls_parse.py | 98 +++++++++++++++++++++++++
>  1 file changed, 98 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..20c92fb620e6
> --- /dev/null
> +++ b/utils/raspberrypi/delayedctrls_parse.py
> @@ -0,0 +1,98 @@
> +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+)')}

I think these should be expanded, like:

delays = {
    'Analogue Gain': 1,
    'Exposure': 2,
    'Vertical Blanking': 2
}


Acked-by: Paul Elder <paul.elder@ideasonboard.com>

> +
> +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))
> -- 
> 2.25.1
> 
> _______________________________________________
> libcamera-devel mailing list
> libcamera-devel@lists.libcamera.org
> https://lists.libcamera.org/listinfo/libcamera-devel

Patch
diff mbox series 

diff --git a/utils/raspberrypi/delayedctrls_parse.py b/utils/raspberrypi/delayedctrls_parse.py
new file mode 100644
index 000000000000..20c92fb620e6
--- /dev/null
+++ b/utils/raspberrypi/delayedctrls_parse.py
@@ -0,0 +1,98 @@ 
+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))