{"id":11488,"url":"https://patchwork.libcamera.org/api/patches/11488/?format=json","web_url":"https://patchwork.libcamera.org/patch/11488/","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":"<20210304081728.1058394-3-naush@raspberrypi.com>","date":"2021-03-04T08:17:23","name":"[libcamera-devel,v4,2/7] utils: raspberrypi: Add a DelayedControls log parser","commit_ref":null,"pull_url":null,"state":"accepted","archived":false,"hash":"996d2bb9ad1de998002fbc7d7bf738dadc2510de","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/11488/mbox/","series":[{"id":1757,"url":"https://patchwork.libcamera.org/api/series/1757/?format=json","web_url":"https://patchwork.libcamera.org/project/libcamera/list/?series=1757","date":"2021-03-04T08:17:21","name":"DelayedControls updates and fixes","version":4,"mbox":"https://patchwork.libcamera.org/series/1757/mbox/"}],"comments":"https://patchwork.libcamera.org/api/patches/11488/comments/","check":"pending","checks":"https://patchwork.libcamera.org/api/patches/11488/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 56A72BD1F1\n\tfor ;\n\tThu, 4 Mar 2021 08:17:40 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id D0D7368AA3;\n\tThu, 4 Mar 2021 09:17:39 +0100 (CET)","from mail-wm1-x330.google.com (mail-wm1-x330.google.com\n\t[IPv6:2a00:1450:4864:20::330])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 0D9A9602EC\n\tfor ;\n\tThu, 4 Mar 2021 09:17:38 +0100 (CET)","by mail-wm1-x330.google.com with SMTP id n4so8703873wmq.3\n\tfor ;\n\tThu, 04 Mar 2021 00:17:38 -0800 (PST)","from naush-laptop.patuck.local ([88.97.76.4])\n\tby smtp.gmail.com with ESMTPSA id\n\tb186sm6997926wmc.44.2021.03.04.00.17.36\n\t(version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);\n\tThu, 04 Mar 2021 00:17:37 -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=\"eFBvkeiW\"; 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=a67QPnmZ/7naEtWkLMtX0KKvq0VldgvuT1P9Ujvt2t0=;\n\tb=eFBvkeiWdVMHgzcJnngnWKqfeHLCXZAUYFmLaW3LODw/aKTO06lwyP51RfI7L4atNy\n\tAg62Uh42Hgr6kVdr7o22a8Rxf0t59FECJYDp4X7R2Vsv25K/jnn0u69E3QiX7AsEbmVl\n\thrbeU1oj+Vu39suI29pybszZ/v/7OuzikkAdMvD3hHdge3t/1leTMBbfnnbuXuucyA/w\n\ti0i5xQYWIkBYJSZTMt4Ng2MXkYnXLETwzxS/eldIeQF9/lGgyWrRfkWUHU7/4gNqlovZ\n\tdg+oOb5/D6+M4XlaARmOpn1FhjATYD7Uy9hQxamleLJwR0w2XfBwRO6HWEbZTR1tDzdB\n\tM9IQ==","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=a67QPnmZ/7naEtWkLMtX0KKvq0VldgvuT1P9Ujvt2t0=;\n\tb=SA0PfGmsLPe5Pov2Rehl+VnCS3tSVjY9qUezB/R4ulXyUUpYrY2+1ttMJWQIIMvO0f\n\t1X+clWl1ubr0BpHradiZMYhuXk+1v2RVV1udD7tRQXv59u7SXOgUL4djLhE4E+BPOool\n\tnbjmLXA8a1GFzG+kjUiaBv/kWXNLjC5c/QpaTwiw9Rl7q3A5M9f+O7ubZ/XWoUF39ACQ\n\tIkaDjdRZafbzHYbO9uXAIBg8C3zeMfeyJzz8h6IY8352cFMFCs2+8i47D9tWIHYZ//JN\n\tLt5YNi6+Sd9OwJYkoowJ9mvk4v+iaaedHS6Be+Rz+niRYM+4S1fzBt5NUFAqRbjwbojV\n\t21sA==","X-Gm-Message-State":"AOAM532uaA7PjTVgwOjZLff5VS0gXyUBHiDZFQ1ENMJwO9/zbrPv7F+K\n\t+S2lyWeRqgXTOCCz8Ti1IoxafHS+eZ3ZxtVk","X-Google-Smtp-Source":"ABdhPJzxkCSxIX7VUtI7dUcLCrhglVY7LS0d1eBniMGHxyLh6/Pq5oY8bBbYaN/zeGp2ANU/jBcEqA==","X-Received":"by 2002:a7b:cc90:: with SMTP id p16mr2727943wma.45.1614845857406;\n\tThu, 04 Mar 2021 00:17:37 -0800 (PST)","From":"Naushir Patuck ","To":"libcamera-devel@lists.libcamera.org","Date":"Thu, 4 Mar 2021 08:17:23 +0000","Message-Id":"<20210304081728.1058394-3-naush@raspberrypi.com>","X-Mailer":"git-send-email 2.25.1","In-Reply-To":"<20210304081728.1058394-1-naush@raspberrypi.com>","References":"<20210304081728.1058394-1-naush@raspberrypi.com>","MIME-Version":"1.0","Subject":"[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\" "},"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 \nTested-by: David Plowman \nAcked-by: Paul Elder \n---\n utils/raspberrypi/delayedctrls_parse.py | 111 ++++++++++++++++++++++++\n 1 file changed, 111 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..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","prefixes":["libcamera-devel","v4","2/7"]}