[{"id":15346,"web_url":"https://patchwork.libcamera.org/comment/15346/","msgid":"<20210301084213.GB3084@pyrite.rasen.tech>","date":"2021-03-01T08:42:13","subject":"Re: [libcamera-devel] [PATCH v2 2/5] utils: raspberrypi: Add a\n\tDelayedControls log parser","submitter":{"id":17,"url":"https://patchwork.libcamera.org/api/people/17/","name":"Paul Elder","email":"paul.elder@ideasonboard.com"},"content":"Hi Naush,\n\nOn Tue, Feb 16, 2021 at 08:53:39AM +0000, 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\nI'm thinking that in the future it would be better to move debug output\nof this type to tracepoints instead of logging, to avoid cluttering up\nthe log with such frequent debug messages.\n\nUntil we make that change though, I think this script is useful.\n\n> ---\n> utils/raspberrypi/delayedctrls_parse.py | 98 +++++++++++++++++++++++++\n> 1 file changed, 98 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..20c92fb620e6\n> --- /dev/null\n> +++ b/utils/raspberrypi/delayedctrls_parse.py\n> @@ -0,0 +1,98 @@\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 = {'Analogue Gain': 1, 'Exposure': 2, 'Vertical Blanking': 2}\n> +ctrl_action = {'Write': {}, 'Get': {}, 'Queue': {}, 'No-op': {}}\n> +ctrl_re = {'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\nI think these should be expanded, like:\n\ndelays = {\n 'Analogue Gain': 1,\n 'Exposure': 2,\n 'Vertical Blanking': 2\n}\n\n\nAcked-by: Paul Elder \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> -- \n> 2.25.1\n> \n> _______________________________________________\n> libcamera-devel mailing list\n> libcamera-devel@lists.libcamera.org\n> https://lists.libcamera.org/listinfo/libcamera-devel","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 89AB8BD1F1\n\tfor ;\n\tMon, 1 Mar 2021 08:42:22 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 19B90689DD;\n\tMon, 1 Mar 2021 09:42:22 +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 B386860521\n\tfor ;\n\tMon, 1 Mar 2021 09:42:20 +0100 (CET)","from pyrite.rasen.tech (unknown\n\t[IPv6:2400:4051:61:600:2c71:1b79:d06d:5032])\n\tby perceval.ideasonboard.com (Postfix) with ESMTPSA id 0FBDD332;\n\tMon, 1 Mar 2021 09:42:18 +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=\"RYT7V9hO\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=ideasonboard.com;\n\ts=mail; t=1614588140;\n\tbh=pPYs0VJ3fiUiqGGpXJUqLDdmgyXUuqM38MFj4hu2qN4=;\n\th=Date:From:To:Cc:Subject:References:In-Reply-To:From;\n\tb=RYT7V9hOgJFg+QypmHPQJNo67tV9J/UCSacvnFplMl2IJQC9QYhjX3l7NExkHw4qk\n\tiXb/hwd9RWuahQWajX430WgTddiJ4effO48rQC0YieVIipdUdYPIyjITr/hLkJp+UF\n\tzG05bHb7tJRWnaiOaxJqDs5s7iXmLGZRuGv+SQW0=","Date":"Mon, 1 Mar 2021 17:42:13 +0900","From":"paul.elder@ideasonboard.com","To":"Naushir Patuck ","Message-ID":"<20210301084213.GB3084@pyrite.rasen.tech>","References":"<20210216085342.1012717-1-naush@raspberrypi.com>\n\t<20210216085342.1012717-3-naush@raspberrypi.com>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210216085342.1012717-3-naush@raspberrypi.com>","Subject":"Re: [libcamera-devel] [PATCH v2 2/5] 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@lists.libcamera.org","Content-Type":"text/plain; charset=\"us-ascii\"","Content-Transfer-Encoding":"7bit","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}}]