{"id":11255,"url":"https://patchwork.libcamera.org/api/patches/11255/?format=json","web_url":"https://patchwork.libcamera.org/patch/11255/","project":{"id":1,"url":"https://patchwork.libcamera.org/api/projects/1/?format=json","name":"libcamera","link_name":"libcamera","list_id":"libcamera_core","list_email":"libcamera-devel@lists.libcamera.org","web_url":"","scm_url":"","webscm_url":""},"msgid":"<20210212113312.239076-3-naush@raspberrypi.com>","date":"2021-02-12T11:33:09","name":"[libcamera-devel,2/5] utils: raspberrypi: Add a DelayedControls log parser","commit_ref":null,"pull_url":null,"state":"superseded","archived":false,"hash":"dc462a77ca1909e0c71d6749e3db4a8a6945f15a","submitter":{"id":34,"url":"https://patchwork.libcamera.org/api/people/34/?format=json","name":"Naushir Patuck","email":"naush@raspberrypi.com"},"delegate":null,"mbox":"https://patchwork.libcamera.org/patch/11255/mbox/","series":[{"id":1683,"url":"https://patchwork.libcamera.org/api/series/1683/?format=json","web_url":"https://patchwork.libcamera.org/project/libcamera/list/?series=1683","date":"2021-02-12T11:33:07","name":"DelayedControls updates and fixes","version":1,"mbox":"https://patchwork.libcamera.org/series/1683/mbox/"}],"comments":"https://patchwork.libcamera.org/api/patches/11255/comments/","check":"pending","checks":"https://patchwork.libcamera.org/api/patches/11255/checks/","tags":{},"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 D47AEBD160\n\tfor ;\n\tFri, 12 Feb 2021 11:37:37 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id A619563786;\n\tFri, 12 Feb 2021 12:37:37 +0100 (CET)","from mail-wr1-x435.google.com (mail-wr1-x435.google.com\n\t[IPv6:2a00:1450:4864:20::435])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 76DF863778\n\tfor ;\n\tFri, 12 Feb 2021 12:37:33 +0100 (CET)","by mail-wr1-x435.google.com with SMTP id g10so7513500wrx.1\n\tfor ;\n\tFri, 12 Feb 2021 03:37:33 -0800 (PST)","from naush-laptop.patuck.local ([88.97.76.4])\n\tby smtp.gmail.com with ESMTPSA id\n\tv5sm10005020wro.71.2021.02.12.03.37.32\n\t(version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);\n\tFri, 12 Feb 2021 03:37:32 -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=\"gnoGi5a1\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=raspberrypi.com; s=google;\n\th=from:to:cc:subject:date:message-id:in-reply-to:references\n\t:mime-version:content-transfer-encoding;\n\tbh=8Js2N/PMpza7AgEjn/VI402ahkH5WnlAn0p4sgmqgn8=;\n\tb=gnoGi5a1qxMi3Pwdfs+cgmlUdQHKlZzw3Bb6knyUJr1cQW+dOQ1QrgcZ0slAjhoL4I\n\t3dv+gA9LNDq24H91GRvRbOjYzUPYQgx3LVZDLd2GtUpCeNq6jhEDcn2I0g3Xxf8MQk5V\n\tyQR/Dx/GiiF2/2kvIKrVjPeq6WIEKoMUv23pILIUYni1DgSR7gqH1zHlm7N2c1NarGgU\n\thuJZjIpzlWbODKxmkghCfVDyQwv2lzoQkR6hl5TtKRedsQl/iVmjghkRNmf52BSEFRT7\n\tVq398KeuUe4BOECniiHGC5MUc39DB4gwp/YrgZB2KY1rbt1rOg5NqYQy54f0EJUrNU0r\n\tBTCg==","X-Google-DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=1e100.net; s=20161025;\n\th=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to\n\t:references:mime-version:content-transfer-encoding;\n\tbh=8Js2N/PMpza7AgEjn/VI402ahkH5WnlAn0p4sgmqgn8=;\n\tb=qjNsAVkvn4i/lw+XrobXbiQKiqtIsoa+Q8Mn92YGXNFavxYrUErPLK+VJzRxlmYy1Q\n\tVwciDnq0NKGmV67GcNDvi0vf4Xt4/E1p6J8bQkP+4d4ymDdE4KeoHIpXfGEFYZrsS9Em\n\tx3N9fafaP+aY9TngL2/QTlc9SkT4N6/Xz+NU4r8+EwPR5KTibVaT5OrNIv0yhXrbT1id\n\t9pdXVNy7NQC6bNt1tbGJdxcs57jbuTcKNl3/iUkXNhrR5CkmNkC96/hT67UeRDqyeO7P\n\tJc07SzjUksB7xiZo9fCJc0z42VS0+tGE4XymiS4NxO3HbQBMLT7Ct93U0Ag8TM6gLuZ5\n\tM9ig==","X-Gm-Message-State":"AOAM530jMfz4WQnD9Z8qD64i/2npAH1wLuAD93SgaffHaH0zFejX1TsM\n\t0dpqmyjpA8Y9G0SKOqOlV6lCoHFwq7bYmOvI","X-Google-Smtp-Source":"ABdhPJyOY5l2R72/GVmpwzxIepGg1hNVLG8ajdQRRE5zW4ODK8dtYDBZ1Wpdhh3Oja5mIG2fWekUFg==","X-Received":"by 2002:adf:82b3:: with SMTP id 48mr2856968wrc.22.1613129852672; \n\tFri, 12 Feb 2021 03:37:32 -0800 (PST)","From":"Naushir Patuck ","To":"libcamera-devel@lists.libcamera.org","Date":"Fri, 12 Feb 2021 11:33:09 +0000","Message-Id":"<20210212113312.239076-3-naush@raspberrypi.com>","X-Mailer":"git-send-email 2.25.1","In-Reply-To":"<20210212113312.239076-1-naush@raspberrypi.com>","References":"<20210212113312.239076-1-naush@raspberrypi.com>","MIME-Version":"1.0","Subject":"[libcamera-devel] [PATCH 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","Content-Type":"text/plain; charset=\"us-ascii\"","Content-Transfer-Encoding":"7bit","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "},"content":"This script will parse log output from the DelayedControls helper, when\nenabled with:\n\nLIBCAMERA_LOG_LEVELS=DelayedControls:0\n\nIt tabulates all control queuing/writing/getting per frame and warns\nabout potential issues related to frame delays not being account for, or\nwrites that are lagging behind or missed.\n\nRun with the following command:\n\npython3 ./delayedctrls_parse.py \n\nSigned-off-by: Naushir Patuck \n---\n utils/raspberrypi/delayedctrls_parse.py | 82 +++++++++++++++++++++++++\n 1 file changed, 82 insertions(+)\n create mode 100644 utils/raspberrypi/delayedctrls_parse.py","diff":"diff --git a/utils/raspberrypi/delayedctrls_parse.py b/utils/raspberrypi/delayedctrls_parse.py\nnew file mode 100644\nindex 000000000000..2e1c40d8b896\n--- /dev/null\n+++ b/utils/raspberrypi/delayedctrls_parse.py\n@@ -0,0 +1,82 @@\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': {}}\n+ctrl_re = {'Write': re.compile('Setting (.*?) to (\\d+) at index (\\d+)'),\n+ 'Get': re.compile('Reading (.*?) to (\\d+) at index (\\d+)'),\n+ 'Queue': re.compile('Queuing (.*?) to (\\d+) at index (\\d+)')}\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+ 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+for frame in range(0, frame_num + 1):\n+ # Test the write -> get matches the set delay.\n+ if (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('Error: {} 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+ if (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('Error: {} queued at frame {} to value {} did not get logged on frame {} - dropped frame?'\n+ .format(c, frame, set_value, delay_frame))\n","prefixes":["libcamera-devel","2/5"]}