[{"id":15561,"web_url":"https://patchwork.libcamera.org/comment/15561/","msgid":"","date":"2021-03-09T09:55:17","subject":"Re: [libcamera-devel] [PATCH v4 2/7] utils: raspberrypi: Add a\n\tDelayedControls log parser","submitter":{"id":75,"url":"https://patchwork.libcamera.org/api/people/75/","name":"Jean-Michel Hautbois","email":"jeanmichel.hautbois@ideasonboard.com"},"content":"Hi Naushir,\n\nThis is very helpful !\n\nOn 04/03/2021 09:17, Naushir Patuck wrote:\n> This script will parse log output from the DelayedControls helper, when\n> enabled with:\n> \n> LIBCAMERA_LOG_LEVELS=DelayedControls:0\n> \n> It tabulates all control queuing/writing/getting per frame and warns\n> about potential issues related to frame delays not being account for, or\n> writes that are lagging behind or missed.\n> \n> Run with the following command:\n> \n> python3 ./delayedctrls_parse.py \n> \n> Signed-off-by: Naushir Patuck \n> Tested-by: David Plowman \n> Acked-by: Paul Elder \nTested-by: Jean-Michel Hautbois \n\n> ---\n> utils/raspberrypi/delayedctrls_parse.py | 111 ++++++++++++++++++++++++\n> 1 file changed, 111 insertions(+)\n> create mode 100644 utils/raspberrypi/delayedctrls_parse.py\n> \n> diff --git a/utils/raspberrypi/delayedctrls_parse.py b/utils/raspberrypi/delayedctrls_parse.py\n> new file mode 100644\n> index 000000000000..3965b86daaaf\n> --- /dev/null\n> +++ b/utils/raspberrypi/delayedctrls_parse.py\n> @@ -0,0 +1,111 @@\n> +import re\n> +import sys\n> +import os\n> +\n> +if len(sys.argv) != 2:\n> + print(\"Usage: {} \".format(sys.argv[0]))\n> + sys.exit()\n> +\n> +infile = sys.argv[1]\n> +insplit = os.path.splitext(infile)\n> +outfile = insplit[0] + '_parsed' + insplit[1]\n> +\n> +frame_re = re.compile('frame (\\d+) started')\n> +\n> +delays = {\n> + 'Analogue Gain': 1,\n> + 'Exposure': 2,\n> + 'Vertical Blanking': 2\n> +}\n> +\n> +ctrl_action = {\n> + 'Write': {},\n> + 'Get': {},\n> + 'Queue': {},\n> + 'No-op': {}\n> +}\n> +\n> +ctrl_re = {\n> + 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n> + 'No-op': re.compile('Queue is empty, (.*?) (.*?) (.*?)'),\n> + 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n> + 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n> +}\n> +\n> +frame_num = -1\n> +\n> +max_delay = 0\n> +for k, d in delays.items():\n> + if max_delay < d:\n> + max_delay = d\n> +\n> +with open(infile) as f:\n> + lines = f.readlines()\n> +\n> +for line in lines:\n> + r = frame_re.search(line)\n> + if r:\n> + frame_num = int(r.group(1))\n> +\n> + for (key, re) in ctrl_re.items():\n> + r = re.search(line)\n> + if r:\n> + ctrl_action[key][(frame_num, r.group(1))] = (r.group(2), r.group(3))\n> +\n> +with open(outfile, 'wt') as f:\n> + queueIndex = 1\n> + f.write('{:<10}{:<15}{:<12}{:<18}{}\\n'.format('Frame', 'Action', 'Gain', 'Exposure', 'Vblank'))\n> + for frame in range(0, frame_num + 1):\n> + for (k, a) in ctrl_action.items():\n> + str = '{:<10}{:<10}'.format(frame, k)\n> +\n> + for c in delays.keys():\n> + # Tabulate all results\n> + str += '{:>5} {:<10}'.format(a[(frame, c)][0] if (frame, c) in a.keys() else '---',\n> + '[' + (a[(frame, c)][1] if (frame, c) in a.keys() else '-') + ']')\n> +\n> + f.write(str.strip() + '\\n')\n> +\n> +# Test the write -> get matches the set delay.\n> +for (frame, c) in ctrl_action['Write'].keys():\n> + set_value = ctrl_action['Write'][(frame, c)][0]\n> + delay_frame = frame + delays[c]\n> + if (delay_frame <= frame_num):\n> + if (delay_frame, c) in ctrl_action['Get']:\n> + get_value = ctrl_action['Get'][(delay_frame, c)][0]\n> + if get_value != set_value:\n> + print('Error: {} written at frame {} to value {} != {} at frame {}'\n> + .format(c, frame, set_value, get_value, delay_frame))\n> + else:\n> + print('Warning: {} written at frame {} to value {} did not get logged on frame {} - dropped frame?'\n> + .format(c, frame, set_value, delay_frame))\n> +\n> +# Test the queue -> write matches the set delay.\n> +for (frame, c) in ctrl_action['Queue'].keys():\n> + set_value = ctrl_action['Queue'][(frame, c)][0]\n> + delay_frame = frame + max_delay - delays[c] + 1\n> + if (delay_frame <= frame_num):\n> + if (delay_frame, c) in ctrl_action['Write']:\n> + write_value = ctrl_action['Write'][(delay_frame, c)][0]\n> + if write_value != set_value:\n> + print('Info: {} queued at frame {} to value {} != {} written at frame {}'\n> + ' - lagging behind or double queue on a single frame!'\n> + .format(c, frame, set_value, write_value, delay_frame))\n> + else:\n> + print('Warning: {} queued at frame {} to value {} did not get logged on frame {} - dropped frame?'\n> + .format(c, frame, set_value, delay_frame))\n> +\n> +# Test the get -> write matches the set delay going backwards.\n> +for (frame, c) in ctrl_action['Get'].keys():\n> + get_value = ctrl_action['Get'][(frame, c)][0]\n> + delay_frame = frame - delays[c]\n> + if (delay_frame >= 6):\n> + if (delay_frame, c) in ctrl_action['Write']:\n> + write_value = ctrl_action['Write'][(delay_frame, c)][0]\n> + if get_value != write_value:\n> + print('Info: {} got at frame {} to value {} != {} written at frame {}'\n> + ' - lagging behind or double queue on a single frame!'\n> + .format(c, frame, get_value, write_value, delay_frame))\n> + else:\n> + print('Warning: {} got at frame {} to value {} did not get written on frame {}'\n> + .format(c, frame, get_value, delay_frame))\n>","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 53677BD80C\n\tfor ;\n\tTue, 9 Mar 2021 09:55:19 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 0E79B68A9F;\n\tTue, 9 Mar 2021 10:55:19 +0100 (CET)","from perceval.ideasonboard.com (perceval.ideasonboard.com\n\t[213.167.242.64])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 15C1D6051F\n\tfor ;\n\tTue, 9 Mar 2021 10:55:18 +0100 (CET)","from [IPv6:2a01:e0a:169:7140:eb55:7706:22b:1e57] (unknown\n\t[IPv6:2a01:e0a:169:7140:eb55:7706:22b:1e57])\n\tby perceval.ideasonboard.com (Postfix) with ESMTPSA id C7C0FE9;\n\tTue, 9 Mar 2021 10:55:17 +0100 (CET)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (1024-bit key;\n\tunprotected) header.d=ideasonboard.com header.i=@ideasonboard.com\n\theader.b=\"cInwUJab\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=ideasonboard.com;\n\ts=mail; t=1615283717;\n\tbh=65+wjdlLV3lQbrMO7uG23dsjeQw+qggHWDq94ORCYhg=;\n\th=Subject:To:References:From:Date:In-Reply-To:From;\n\tb=cInwUJabwjS86vHY+/Xl3Q/8MpDeo1TKDuoO19Aj8SUk/NLtVBhFBIW+33gF629g0\n\tmM8+XzO2gP96GAuFc/xglYvQrbgISXP3RH9xm8c2H9Zfjpl4Eh9UOzmuhsz9AbgULm\n\tpadCJT5bFkWkiSgdKW0M4oB0P6mwjlYw4LcNvC8Y=","To":"Naushir Patuck ,\n\tlibcamera-devel@lists.libcamera.org","References":"<20210304081728.1058394-1-naush@raspberrypi.com>\n\t<20210304081728.1058394-3-naush@raspberrypi.com>","From":"Jean-Michel Hautbois ","Message-ID":"","Date":"Tue, 9 Mar 2021 10:55:17 +0100","User-Agent":"Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101\n\tThunderbird/78.7.1","MIME-Version":"1.0","In-Reply-To":"<20210304081728.1058394-3-naush@raspberrypi.com>","Content-Language":"en-US","Subject":"Re: [libcamera-devel] [PATCH v4 2/7] utils: raspberrypi: Add a\n\tDelayedControls log parser","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Content-Type":"text/plain; charset=\"us-ascii\"","Content-Transfer-Encoding":"7bit","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}},{"id":15612,"web_url":"https://patchwork.libcamera.org/comment/15612/","msgid":"<285da1dd-29b7-049f-5826-898e80583572@ideasonboard.com>","date":"2021-03-12T13:11:58","subject":"Re: [libcamera-devel] [PATCH v4 2/7] utils: raspberrypi: Add a\n\tDelayedControls log parser","submitter":{"id":4,"url":"https://patchwork.libcamera.org/api/people/4/","name":"Kieran Bingham","email":"kieran.bingham@ideasonboard.com"},"content":"Hi Naush,\n\nOn 04/03/2021 08:17, Naushir Patuck wrote:\n> This script will parse log output from the DelayedControls helper, when\n> enabled with:\n> \n> LIBCAMERA_LOG_LEVELS=DelayedControls:0\n> \n> It tabulates all control queuing/writing/getting per frame and warns\n> about potential issues related to frame delays not being account for, or\n> writes that are lagging behind or missed.\n> \n> Run with the following command:\n> \n> python3 ./delayedctrls_parse.py \n> \n> Signed-off-by: Naushir Patuck \n> Tested-by: David Plowman \n> Acked-by: Paul Elder \n\nThis patch has the following checkstyle warnings:\n\n3ea0b3f4bee5670b4e46045836dee48928c3e1f2 utils: raspberrypi: Add a\nDelayedControls log parser\n---------------------------------------------------------------------------------------------\n--- utils/raspberrypi/delayedctrls_parse.py\n+++ utils/raspberrypi/delayedctrls_parse.py\n#13: : W605 invalid escape sequence '\\d'\n+frame_re = re.compile('frame (\\d+) started')\n#29: : W605 invalid escape sequence '\\d'\n+ 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n#29: : W605 invalid escape sequence '\\d'\n+ 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n#31: : W605 invalid escape sequence '\\d'\n+ 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n#31: : W605 invalid escape sequence '\\d'\n+ 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n#32: : W605 invalid escape sequence '\\d'\n+ 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n#32: : W605 invalid escape sequence '\\d'\n+ 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n---\n7 potential issues detected, please review\n\n\nIf you have pycodestyle installed (the pep8 update) you should get these\nchecks.\n\n\nPrefixing the regex string with an 'r' fixes these.\n\n\nIf you're happy, and there' turns out to be no need to repost\n (I'm hoping not) I'll apply the following fix:\n\n\n\n> diff --git a/utils/raspberrypi/delayedctrls_parse.py b/utils/raspberrypi/delayedctrls_parse.py\n> index 3965b86daaaf..e38145d8e98e 100644\n> --- a/utils/raspberrypi/delayedctrls_parse.py\n> +++ b/utils/raspberrypi/delayedctrls_parse.py\n> @@ -10,7 +10,7 @@ infile = sys.argv[1]\n> insplit = os.path.splitext(infile)\n> outfile = insplit[0] + '_parsed' + insplit[1]\n> \n> -frame_re = re.compile('frame (\\d+) started')\n> +frame_re = re.compile(r'frame (\\d+) started')\n> \n> delays = {\n> 'Analogue Gain': 1,\n> (1/2) Stage this hunk [y,n,q,a,d,j,J,g,/,e,?]? y\n> @@ -26,10 +26,10 @@ ctrl_action = {\n> }\n> \n> ctrl_re = {\n> - 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n> - 'No-op': re.compile('Queue is empty, (.*?) (.*?) (.*?)'),\n> - 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n> - 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n> + 'Write': re.compile(r'Setting (.*?) to (\\d+) at index (\\d+)'),\n> + 'No-op': re.compile(r'Queue is empty, (.*?) (.*?) (.*?)'),\n> + 'Get': re.compile(r'Reading (.*?) to (\\d+) at index (\\d+)'),\n> + 'Queue': re.compile(r'Queuing (.*?) to (\\d+) at index (\\d+)')\n> }\n> \n> frame_num = -1\n\n\n\n\n\n\n> ---\n> utils/raspberrypi/delayedctrls_parse.py | 111 ++++++++++++++++++++++++\n> 1 file changed, 111 insertions(+)\n> create mode 100644 utils/raspberrypi/delayedctrls_parse.py\n> \n> diff --git a/utils/raspberrypi/delayedctrls_parse.py b/utils/raspberrypi/delayedctrls_parse.py\n> new file mode 100644\n> index 000000000000..3965b86daaaf\n> --- /dev/null\n> +++ b/utils/raspberrypi/delayedctrls_parse.py\n> @@ -0,0 +1,111 @@\n> +import re\n> +import sys\n> +import os\n> +\n> +if len(sys.argv) != 2:\n> + print(\"Usage: {} \".format(sys.argv[0]))\n> + sys.exit()\n> +\n> +infile = sys.argv[1]\n> +insplit = os.path.splitext(infile)\n> +outfile = insplit[0] + '_parsed' + insplit[1]\n> +\n> +frame_re = re.compile('frame (\\d+) started')\n> +\n> +delays = {\n> + 'Analogue Gain': 1,\n> + 'Exposure': 2,\n> + 'Vertical Blanking': 2\n> +}\n\nAre these sensor dependant ?\n\nOtherwise, with the raw string prefix,\n\nReviewed-by: Kieran Bingham \n\n> +\n> +ctrl_action = {\n> + 'Write': {},\n> + 'Get': {},\n> + 'Queue': {},\n> + 'No-op': {}\n> +}\n> +\n> +ctrl_re = {\n> + 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n> + 'No-op': re.compile('Queue is empty, (.*?) (.*?) (.*?)'),\n> + 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n> + 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n> +}\n> +\n> +frame_num = -1\n> +\n> +max_delay = 0\n> +for k, d in delays.items():\n> + if max_delay < d:\n> + max_delay = d\n> +\n> +with open(infile) as f:\n> + lines = f.readlines()\n> +\n> +for line in lines:\n> + r = frame_re.search(line)\n> + if r:\n> + frame_num = int(r.group(1))\n> +\n> + for (key, re) in ctrl_re.items():\n> + r = re.search(line)\n> + if r:\n> + ctrl_action[key][(frame_num, r.group(1))] = (r.group(2), r.group(3))\n> +\n> +with open(outfile, 'wt') as f:\n> + queueIndex = 1\n> + f.write('{:<10}{:<15}{:<12}{:<18}{}\\n'.format('Frame', 'Action', 'Gain', 'Exposure', 'Vblank'))\n> + for frame in range(0, frame_num + 1):\n> + for (k, a) in ctrl_action.items():\n> + str = '{:<10}{:<10}'.format(frame, k)\n> +\n> + for c in delays.keys():\n> + # Tabulate all results\n> + str += '{:>5} {:<10}'.format(a[(frame, c)][0] if (frame, c) in a.keys() else '---',\n> + '[' + (a[(frame, c)][1] if (frame, c) in a.keys() else '-') + ']')\n> +\n> + f.write(str.strip() + '\\n')\n> +\n> +# Test the write -> get matches the set delay.\n> +for (frame, c) in ctrl_action['Write'].keys():\n> + set_value = ctrl_action['Write'][(frame, c)][0]\n> + delay_frame = frame + delays[c]\n> + if (delay_frame <= frame_num):\n> + if (delay_frame, c) in ctrl_action['Get']:\n> + get_value = ctrl_action['Get'][(delay_frame, c)][0]\n> + if get_value != set_value:\n> + print('Error: {} written at frame {} to value {} != {} at frame {}'\n> + .format(c, frame, set_value, get_value, delay_frame))\n> + else:\n> + print('Warning: {} written at frame {} to value {} did not get logged on frame {} - dropped frame?'\n> + .format(c, frame, set_value, delay_frame))\n> +\n> +# Test the queue -> write matches the set delay.\n> +for (frame, c) in ctrl_action['Queue'].keys():\n> + set_value = ctrl_action['Queue'][(frame, c)][0]\n> + delay_frame = frame + max_delay - delays[c] + 1\n> + if (delay_frame <= frame_num):\n> + if (delay_frame, c) in ctrl_action['Write']:\n> + write_value = ctrl_action['Write'][(delay_frame, c)][0]\n> + if write_value != set_value:\n> + print('Info: {} queued at frame {} to value {} != {} written at frame {}'\n> + ' - lagging behind or double queue on a single frame!'\n> + .format(c, frame, set_value, write_value, delay_frame))\n> + else:\n> + print('Warning: {} queued at frame {} to value {} did not get logged on frame {} - dropped frame?'\n> + .format(c, frame, set_value, delay_frame))\n> +\n> +# Test the get -> write matches the set delay going backwards.\n> +for (frame, c) in ctrl_action['Get'].keys():\n> + get_value = ctrl_action['Get'][(frame, c)][0]\n> + delay_frame = frame - delays[c]\n> + if (delay_frame >= 6):\n> + if (delay_frame, c) in ctrl_action['Write']:\n> + write_value = ctrl_action['Write'][(delay_frame, c)][0]\n> + if get_value != write_value:\n> + print('Info: {} got at frame {} to value {} != {} written at frame {}'\n> + ' - lagging behind or double queue on a single frame!'\n> + .format(c, frame, get_value, write_value, delay_frame))\n> + else:\n> + print('Warning: {} got at frame {} to value {} did not get written on frame {}'\n> + .format(c, frame, get_value, delay_frame))\n>","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 9AE78BD80C\n\tfor ;\n\tFri, 12 Mar 2021 13:12:16 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id D4A5A68C68;\n\tFri, 12 Mar 2021 14:12:15 +0100 (CET)","from perceval.ideasonboard.com (perceval.ideasonboard.com\n\t[IPv6:2001:4b98:dc2:55:216:3eff:fef7:d647])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id C671C68AA1\n\tfor ;\n\tFri, 12 Mar 2021 14:12:13 +0100 (CET)","from [192.168.0.20]\n\t(cpc89244-aztw30-2-0-cust3082.18-1.cable.virginm.net [86.31.172.11])\n\tby perceval.ideasonboard.com (Postfix) with ESMTPSA id 47208A2A;\n\tFri, 12 Mar 2021 14:12:13 +0100 (CET)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (1024-bit key;\n\tunprotected) header.d=ideasonboard.com header.i=@ideasonboard.com\n\theader.b=\"Ib14cx7y\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=ideasonboard.com;\n\ts=mail; t=1615554733;\n\tbh=2QSHedPKZo+GWh2V3HnvH8PSOmu1RqVbfbnyNkW+0i0=;\n\th=Reply-To:Subject:To:References:From:Date:In-Reply-To:From;\n\tb=Ib14cx7yTpsQFWKcWQcfa+pL20KGp8L0TyAAonxMyEdav6pbJ4EvSWb9OkVsfClLX\n\t1G0+BDynT4vynbI12Mu45JLGlkDALMAitJOKpmo1Mqs4IFXbTfnTWE+D4iBFIhW4Sy\n\tJWQhhCfmsDzQjksDJfmGbJiYU8elHcqgFvbhu+6s=","To":"Naushir Patuck ,\n\tlibcamera-devel@lists.libcamera.org","References":"<20210304081728.1058394-1-naush@raspberrypi.com>\n\t<20210304081728.1058394-3-naush@raspberrypi.com>","From":"Kieran Bingham ","Autocrypt":"addr=kieran.bingham@ideasonboard.com; keydata=\n\tmQINBFYE/WYBEACs1PwjMD9rgCu1hlIiUA1AXR4rv2v+BCLUq//vrX5S5bjzxKAryRf0uHat\n\tV/zwz6hiDrZuHUACDB7X8OaQcwhLaVlq6byfoBr25+hbZG7G3+5EUl9cQ7dQEdvNj6V6y/SC\n\trRanWfelwQThCHckbobWiQJfK9n7rYNcPMq9B8e9F020LFH7Kj6YmO95ewJGgLm+idg1Kb3C\n\tpotzWkXc1xmPzcQ1fvQMOfMwdS+4SNw4rY9f07Xb2K99rjMwZVDgESKIzhsDB5GY465sCsiQ\n\tcSAZRxqE49RTBq2+EQsbrQpIc8XiffAB8qexh5/QPzCmR4kJgCGeHIXBtgRj+nIkCJPZvZtf\n\tKr2EAbc6tgg6DkAEHJb+1okosV09+0+TXywYvtEop/WUOWQ+zo+Y/OBd+8Ptgt1pDRyOBzL8\n\tRXa8ZqRf0Mwg75D+dKntZeJHzPRJyrlfQokngAAs4PaFt6UfS+ypMAF37T6CeDArQC41V3ko\n\tlPn1yMsVD0p+6i3DPvA/GPIksDC4owjnzVX9kM8Zc5Cx+XoAN0w5Eqo4t6qEVbuettxx55gq\n\t8K8FieAjgjMSxngo/HST8TpFeqI5nVeq0/lqtBRQKumuIqDg+Bkr4L1V/PSB6XgQcOdhtd36\n\tOe9X9dXB8YSNt7VjOcO7BTmFn/Z8r92mSAfHXpb07YJWJosQOQARAQABtDBLaWVyYW4gQmlu\n\tZ2hhbSA8a2llcmFuLmJpbmdoYW1AaWRlYXNvbmJvYXJkLmNvbT6JAlcEEwEKAEECGwMFCwkI\n\tBwIGFQgJCgsCBBYCAwECHgECF4ACGQEWIQSQLdeYP70o/eNy1HqhHkZyEKRh/QUCXWTtygUJ\n\tCyJXZAAKCRChHkZyEKRh/f8dEACTDsbLN2nioNZMwyLuQRUAFcXNolDX48xcUXsWS2QjxaPm\n\tVsJx8Uy8aYkS85mdPBh0C83OovQR/OVbr8AxhGvYqBs3nQvbWuTl/+4od7DfK2VZOoKBAu5S\n\tQK2FYuUcikDqYcFWJ8DQnubxfE8dvzojHEkXw0sA4igINHDDFX3HJGZtLio+WpEFQtCbfTAG\n\tYZslasz1YZRbwEdSsmO3/kqy5eMnczlm8a21A3fKUo3g8oAZEFM+f4DUNzqIltg31OAB/kZS\n\tenKZQ/SWC8PmLg/ZXBrReYakxXtkP6w3FwMlzOlhGxqhIRNiAJfXJBaRhuUWzPOpEDE9q5YJ\n\tBmqQL2WJm1VSNNVxbXJHpaWMH1sA2R00vmvRrPXGwyIO0IPYeUYQa3gsy6k+En/aMQJd27dp\n\taScf9am9PFICPY5T4ppneeJLif2lyLojo0mcHOV+uyrds9XkLpp14GfTkeKPdPMrLLTsHRfH\n\tfA4I4OBpRrEPiGIZB/0im98MkGY/Mu6qxeZmYLCcgD6qz4idOvfgVOrNh+aA8HzIVR+RMW8H\n\tQGBN9f0E3kfwxuhl3omo6V7lDw8XOdmuWZNC9zPq1UfryVHANYbLGz9KJ4Aw6M+OgBC2JpkD\n\thXMdHUkC+d20dwXrwHTlrJi1YNp6rBc+xald3wsUPOZ5z8moTHUX/uPA/qhGsbkCDQRWBP1m\n\tARAAzijkb+Sau4hAncr1JjOY+KyFEdUNxRy+hqTJdJfaYihxyaj0Ee0P0zEi35CbE6lgU0Uz\n\ttih9fiUbSV3wfsWqg1Ut3/5rTKu7kLFp15kF7eqvV4uezXRD3Qu4yjv/rMmEJbbD4cTvGCYI\n\td6MDC417f7vK3hCbCVIZSp3GXxyC1LU+UQr3fFcOyCwmP9vDUR9JV0BSqHHxRDdpUXE26Dk6\n\tmhf0V1YkspE5St814ETXpEus2urZE5yJIUROlWPIL+hm3NEWfAP06vsQUyLvr/GtbOT79vXl\n\tEn1aulcYyu20dRRxhkQ6iILaURcxIAVJJKPi8dsoMnS8pB0QW12AHWuirPF0g6DiuUfPmrA5\n\tPKe56IGlpkjc8cO51lIxHkWTpCMWigRdPDexKX+Sb+W9QWK/0JjIc4t3KBaiG8O4yRX8ml2R\n\t+rxfAVKM6V769P/hWoRGdgUMgYHFpHGSgEt80OKK5HeUPy2cngDUXzwrqiM5Sz6Od0qw5pCk\n\tNlXqI0W/who0iSVM+8+RmyY0OEkxEcci7rRLsGnM15B5PjLJjh1f2ULYkv8s4SnDwMZ/kE04\n\t/UqCMK/KnX8pwXEMCjz0h6qWNpGwJ0/tYIgQJZh6bqkvBrDogAvuhf60Sogw+mH8b+PBlx1L\n\toeTK396wc+4c3BfiC6pNtUS5GpsPMMjYMk7kVvEAEQEAAYkCPAQYAQoAJgIbDBYhBJAt15g/\n\tvSj943LUeqEeRnIQpGH9BQJdizzIBQkLSKZiAAoJEKEeRnIQpGH9eYgQAJpjaWNgqNOnMTmD\n\tMJggbwjIotypzIXfhHNCeTkG7+qCDlSaBPclcPGYrTwCt0YWPU2TgGgJrVhYT20ierN8LUvj\n\t6qOPTd+Uk7NFzL65qkh80ZKNBFddx1AabQpSVQKbdcLb8OFs85kuSvFdgqZwgxA1vl4TFhNz\n\tPZ79NAmXLackAx3sOVFhk4WQaKRshCB7cSl+RIng5S/ThOBlwNlcKG7j7W2MC06BlTbdEkUp\n\tECzuuRBv8wX4OQl+hbWbB/VKIx5HKlLu1eypen/5lNVzSqMMIYkkZcjV2SWQyUGxSwq0O/sx\n\tS0A8/atCHUXOboUsn54qdxrVDaK+6jIAuo8JiRWctP16KjzUM7MO0/+4zllM8EY57rXrj48j\n\tsbEYX0YQnzaj+jO6kJtoZsIaYR7rMMq9aUAjyiaEZpmP1qF/2sYenDx0Fg2BSlLvLvXM0vU8\n\tpQk3kgDu7kb/7PRYrZvBsr21EIQoIjXbZxDz/o7z95frkP71EaICttZ6k9q5oxxA5WC6sTXc\n\tMW8zs8avFNuA9VpXt0YupJd2ijtZy2mpZNG02fFVXhIn4G807G7+9mhuC4XG5rKlBBUXTvPU\n\tAfYnB4JBDLmLzBFavQfvonSfbitgXwCG3vS+9HEwAjU30Bar1PEOmIbiAoMzuKeRm2LVpmq4\n\tWZw01QYHU/GUV/zHJSFk","Organization":"Ideas on Board","Message-ID":"<285da1dd-29b7-049f-5826-898e80583572@ideasonboard.com>","Date":"Fri, 12 Mar 2021 13:11:58 +0000","User-Agent":"Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101\n\tThunderbird/68.10.0","MIME-Version":"1.0","In-Reply-To":"<20210304081728.1058394-3-naush@raspberrypi.com>","Content-Language":"en-GB","Subject":"Re: [libcamera-devel] [PATCH v4 2/7] utils: raspberrypi: Add a\n\tDelayedControls log parser","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Reply-To":"kieran.bingham@ideasonboard.com","Content-Type":"text/plain; charset=\"us-ascii\"","Content-Transfer-Encoding":"7bit","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}},{"id":15623,"web_url":"https://patchwork.libcamera.org/comment/15623/","msgid":"","date":"2021-03-12T14:05:23","subject":"Re: [libcamera-devel] [PATCH v4 2/7] utils: raspberrypi: Add a\n\tDelayedControls log parser","submitter":{"id":34,"url":"https://patchwork.libcamera.org/api/people/34/","name":"Naushir Patuck","email":"naush@raspberrypi.com"},"content":"Hi Kieran,\n\nOn Fri, 12 Mar 2021 at 13:12, Kieran Bingham <\nkieran.bingham@ideasonboard.com> wrote:\n\n> Hi Naush,\n>\n> On 04/03/2021 08:17, Naushir Patuck wrote:\n> > This script will parse log output from the DelayedControls helper, when\n> > enabled with:\n> >\n> > LIBCAMERA_LOG_LEVELS=DelayedControls:0\n> >\n> > It tabulates all control queuing/writing/getting per frame and warns\n> > about potential issues related to frame delays not being account for, or\n> > writes that are lagging behind or missed.\n> >\n> > Run with the following command:\n> >\n> > python3 ./delayedctrls_parse.py \n> >\n> > Signed-off-by: Naushir Patuck \n> > Tested-by: David Plowman \n> > Acked-by: Paul Elder \n>\n> This patch has the following checkstyle warnings:\n>\n> 3ea0b3f4bee5670b4e46045836dee48928c3e1f2 utils: raspberrypi: Add a\n> DelayedControls log parser\n>\n> ---------------------------------------------------------------------------------------------\n> --- utils/raspberrypi/delayedctrls_parse.py\n> +++ utils/raspberrypi/delayedctrls_parse.py\n> #13: : W605 invalid escape sequence '\\d'\n> +frame_re = re.compile('frame (\\d+) started')\n> #29: : W605 invalid escape sequence '\\d'\n> + 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n> #29: : W605 invalid escape sequence '\\d'\n> + 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n> #31: : W605 invalid escape sequence '\\d'\n> + 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n> #31: : W605 invalid escape sequence '\\d'\n> + 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n> #32: : W605 invalid escape sequence '\\d'\n> + 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n> #32: : W605 invalid escape sequence '\\d'\n> + 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n> ---\n> 7 potential issues detected, please review\n>\n>\n> If you have pycodestyle installed (the pep8 update) you should get these\n> checks.\n>\n\nWill do!\n\n\n>\n>\n> Prefixing the regex string with an 'r' fixes these.\n>\n>\n> If you're happy, and there' turns out to be no need to repost\n> (I'm hoping not) I'll apply the following fix:\n>\n\nHappy for you to fixup when merging if it is convenient.\n\nRegards,\nNaush\n\n\n\n>\n>\n> > diff --git a/utils/raspberrypi/delayedctrls_parse.py\n> b/utils/raspberrypi/delayedctrls_parse.py\n> > index 3965b86daaaf..e38145d8e98e 100644\n> > --- a/utils/raspberrypi/delayedctrls_parse.py\n> > +++ b/utils/raspberrypi/delayedctrls_parse.py\n> > @@ -10,7 +10,7 @@ infile = sys.argv[1]\n> > insplit = os.path.splitext(infile)\n> > outfile = insplit[0] + '_parsed' + insplit[1]\n> >\n> > -frame_re = re.compile('frame (\\d+) started')\n> > +frame_re = re.compile(r'frame (\\d+) started')\n> >\n> > delays = {\n> > 'Analogue Gain': 1,\n> > (1/2) Stage this hunk [y,n,q,a,d,j,J,g,/,e,?]? y\n> > @@ -26,10 +26,10 @@ ctrl_action = {\n> > }\n> >\n> > ctrl_re = {\n> > - 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n> > - 'No-op': re.compile('Queue is empty, (.*?) (.*?) (.*?)'),\n> > - 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n> > - 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n> > + 'Write': re.compile(r'Setting (.*?) to (\\d+) at index (\\d+)'),\n> > + 'No-op': re.compile(r'Queue is empty, (.*?) (.*?) (.*?)'),\n> > + 'Get': re.compile(r'Reading (.*?) to (\\d+) at index (\\d+)'),\n> > + 'Queue': re.compile(r'Queuing (.*?) to (\\d+) at index (\\d+)')\n> > }\n> >\n> > frame_num = -1\n>\n>\n>\n>\n>\n>\n> > ---\n> > utils/raspberrypi/delayedctrls_parse.py | 111 ++++++++++++++++++++++++\n> > 1 file changed, 111 insertions(+)\n> > create mode 100644 utils/raspberrypi/delayedctrls_parse.py\n> >\n> > diff --git a/utils/raspberrypi/delayedctrls_parse.py\n> b/utils/raspberrypi/delayedctrls_parse.py\n> > new file mode 100644\n> > index 000000000000..3965b86daaaf\n> > --- /dev/null\n> > +++ b/utils/raspberrypi/delayedctrls_parse.py\n> > @@ -0,0 +1,111 @@\n> > +import re\n> > +import sys\n> > +import os\n> > +\n> > +if len(sys.argv) != 2:\n> > + print(\"Usage: {} \".format(sys.argv[0]))\n> > + sys.exit()\n> > +\n> > +infile = sys.argv[1]\n> > +insplit = os.path.splitext(infile)\n> > +outfile = insplit[0] + '_parsed' + insplit[1]\n> > +\n> > +frame_re = re.compile('frame (\\d+) started')\n> > +\n> > +delays = {\n> > + 'Analogue Gain': 1,\n> > + 'Exposure': 2,\n> > + 'Vertical Blanking': 2\n> > +}\n>\n> Are these sensor dependant ?\n>\n> Otherwise, with the raw string prefix,\n>\n> Reviewed-by: Kieran Bingham \n>\n> > +\n> > +ctrl_action = {\n> > + 'Write': {},\n> > + 'Get': {},\n> > + 'Queue': {},\n> > + 'No-op': {}\n> > +}\n> > +\n> > +ctrl_re = {\n> > + 'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n> > + 'No-op': re.compile('Queue is empty, (.*?) (.*?) (.*?)'),\n> > + 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n> > + 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')\n> > +}\n> > +\n> > +frame_num = -1\n> > +\n> > +max_delay = 0\n> > +for k, d in delays.items():\n> > + if max_delay < d:\n> > + max_delay = d\n> > +\n> > +with open(infile) as f:\n> > + lines = f.readlines()\n> > +\n> > +for line in lines:\n> > + r = frame_re.search(line)\n> > + if r:\n> > + frame_num = int(r.group(1))\n> > +\n> > + for (key, re) in ctrl_re.items():\n> > + r = re.search(line)\n> > + if r:\n> > + ctrl_action[key][(frame_num, r.group(1))] = (r.group(2),\n> r.group(3))\n> > +\n> > +with open(outfile, 'wt') as f:\n> > + queueIndex = 1\n> > + f.write('{:<10}{:<15}{:<12}{:<18}{}\\n'.format('Frame', 'Action',\n> 'Gain', 'Exposure', 'Vblank'))\n> > + for frame in range(0, frame_num + 1):\n> > + for (k, a) in ctrl_action.items():\n> > + str = '{:<10}{:<10}'.format(frame, k)\n> > +\n> > + for c in delays.keys():\n> > + # Tabulate all results\n> > + str += '{:>5} {:<10}'.format(a[(frame, c)][0] if\n> (frame, c) in a.keys() else '---',\n> > + '[' + (a[(frame, c)][1] if\n> (frame, c) in a.keys() else '-') + ']')\n> > +\n> > + f.write(str.strip() + '\\n')\n> > +\n> > +# Test the write -> get matches the set delay.\n> > +for (frame, c) in ctrl_action['Write'].keys():\n> > + set_value = ctrl_action['Write'][(frame, c)][0]\n> > + delay_frame = frame + delays[c]\n> > + if (delay_frame <= frame_num):\n> > + if (delay_frame, c) in ctrl_action['Get']:\n> > + get_value = ctrl_action['Get'][(delay_frame, c)][0]\n> > + if get_value != set_value:\n> > + print('Error: {} written at frame {} to value {} != {}\n> at frame {}'\n> > + .format(c, frame, set_value, get_value,\n> delay_frame))\n> > + else:\n> > + print('Warning: {} written at frame {} to value {} did not\n> get logged on frame {} - dropped frame?'\n> > + .format(c, frame, set_value, delay_frame))\n> > +\n> > +# Test the queue -> write matches the set delay.\n> > +for (frame, c) in ctrl_action['Queue'].keys():\n> > + set_value = ctrl_action['Queue'][(frame, c)][0]\n> > + delay_frame = frame + max_delay - delays[c] + 1\n> > + if (delay_frame <= frame_num):\n> > + if (delay_frame, c) in ctrl_action['Write']:\n> > + write_value = ctrl_action['Write'][(delay_frame, c)][0]\n> > + if write_value != set_value:\n> > + print('Info: {} queued at frame {} to value {} != {}\n> written at frame {}'\n> > + ' - lagging behind or double queue on a single\n> frame!'\n> > + .format(c, frame, set_value, write_value,\n> delay_frame))\n> > + else:\n> > + print('Warning: {} queued at frame {} to value {} did not\n> get logged on frame {} - dropped frame?'\n> > + .format(c, frame, set_value, delay_frame))\n> > +\n> > +# Test the get -> write matches the set delay going backwards.\n> > +for (frame, c) in ctrl_action['Get'].keys():\n> > + get_value = ctrl_action['Get'][(frame, c)][0]\n> > + delay_frame = frame - delays[c]\n> > + if (delay_frame >= 6):\n> > + if (delay_frame, c) in ctrl_action['Write']:\n> > + write_value = ctrl_action['Write'][(delay_frame, c)][0]\n> > + if get_value != write_value:\n> > + print('Info: {} got at frame {} to value {} != {}\n> written at frame {}'\n> > + ' - lagging behind or double queue on a single\n> frame!'\n> > + .format(c, frame, get_value, write_value,\n> delay_frame))\n> > + else:\n> > + print('Warning: {} got at frame {} to value {} did not get\n> written on frame {}'\n> > + .format(c, frame, get_value, delay_frame))\n> >\n>\n> --\n> Regards\n> --\n> Kieran\n>","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 0D9DDBD80C\n\tfor ;\n\tFri, 12 Mar 2021 14:05:45 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id B8DDF68C6B;\n\tFri, 12 Mar 2021 15:05:44 +0100 (CET)","from mail-lf1-x12b.google.com (mail-lf1-x12b.google.com\n\t[IPv6:2a00:1450:4864:20::12b])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id E8B3468C68\n\tfor ;\n\tFri, 12 Mar 2021 15:05:42 +0100 (CET)","by mail-lf1-x12b.google.com with SMTP id p21so45871941lfu.11\n\tfor ;\n\tFri, 12 Mar 2021 06:05:42 -0800 (PST)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (2048-bit key;\n\tunprotected) header.d=raspberrypi.com header.i=@raspberrypi.com\n\theader.b=\"WcUUALAj\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=raspberrypi.com; s=google;\n\th=mime-version:references:in-reply-to:from:date:message-id:subject:to\n\t:cc; bh=6o4K2xPdNpGufE/YRkOIAQ4CYMFoXFGOiq8njQgAdCQ=;\n\tb=WcUUALAjDZ1WZoK2NZpMEn8HeSDYqbcDXxevFikbKryyhVUoTcJetms25IEVBJGWU6\n\tOa+vzCWuz2Wrfg0cM9eLCQZNiETAEZZblgtQOks/fEWtRHvO1ZeCDLqqg68nMwopvV6V\n\t3ldVId7JDTU1A/ZTF41Cffc+sH2EsxvdLe3MP6Q8ss2lQxBcETAKrqoaszMCHk6/7Ssz\n\tTEs1v2wILVAcubEjakt2/fWIp0VNa6R/tOm6Qi2BSQuFcRXS9N5NJfAGiVB2ul+8Mq9D\n\thYAFF1K+59pdoYdU9nIjAKKdjUFq4yEVzknbYLPMyUak5cYwcRC3foGyV7N7RTaQHRbh\n\teqXQ==","X-Google-DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=1e100.net; s=20161025;\n\th=x-gm-message-state:mime-version:references:in-reply-to:from:date\n\t:message-id:subject:to:cc;\n\tbh=6o4K2xPdNpGufE/YRkOIAQ4CYMFoXFGOiq8njQgAdCQ=;\n\tb=kvk7l5k/SF1ge3JrhKViD+bFy8aQbIi57mK1H8Fml3fKrj996N9ddELr/9OfagydGr\n\tcvk8SgzYqZ/olL8tN70bFzXztuUozAgy2LYfKSMdbikAnwZE528fP9Ms3nI2Meog4miq\n\t8R0060V050a0bLrml95tQqfDttju8pEsC6+nluQ2ue9wgkmUAOsP1Vg01ps8FAPl/E7k\n\tgDmN2yIXmqE+ENAGFQm6NQI+aXA9Kdl+UgKQlA5uDb6V/pbbV2EvQT/99VYK7uPhwLz6\n\tRAQMQpVrmkiF/qs37kajPah4RWzb6DZv64QYanpw9133Z2+i4EOEGmJ9jPAX1lcnJJVa\n\tYcvQ==","X-Gm-Message-State":"AOAM532SSwNMNNNqvwJLGDSkCKsZvcRGLT06HsvONmjx5nWwf1gE2kJn\n\tROaTiu2jYf0/YztymCiHQ6x/b8TQS+Ou/gTAUYGqr373K+A=","X-Google-Smtp-Source":"ABdhPJxdrx/wnsUp9A6Jl4gZMgHhdCG6xgxDzKj/+lxDDa/8KDJP9p5+pw97amciquoIm7f8BRNd0hJ/jg+GBQ5DxxE=","X-Received":"by 2002:ac2:43d4:: with SMTP id\n\tu20mr5334246lfl.210.1615557940789; \n\tFri, 12 Mar 2021 06:05:40 -0800 (PST)","MIME-Version":"1.0","References":"<20210304081728.1058394-1-naush@raspberrypi.com>\n\t<20210304081728.1058394-3-naush@raspberrypi.com>\n\t<285da1dd-29b7-049f-5826-898e80583572@ideasonboard.com>","In-Reply-To":"<285da1dd-29b7-049f-5826-898e80583572@ideasonboard.com>","From":"Naushir Patuck ","Date":"Fri, 12 Mar 2021 14:05:23 +0000","Message-ID":"","To":"Kieran Bingham ","Subject":"Re: [libcamera-devel] [PATCH v4 2/7] utils: raspberrypi: Add a\n\tDelayedControls log parser","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Cc":"libcamera devel ","Content-Type":"multipart/mixed;\n\tboundary=\"===============6135837142600100281==\"","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}}]