{"id":11414,"url":"https://patchwork.libcamera.org/api/1.1/patches/11414/?format=json","web_url":"https://patchwork.libcamera.org/patch/11414/","project":{"id":1,"url":"https://patchwork.libcamera.org/api/1.1/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":"<20210301133159.4179129-3-naush@raspberrypi.com>","date":"2021-03-01T13:31:56","name":"[libcamera-devel,v3,2/5] utils: raspberrypi: Add a DelayedControls log parser","commit_ref":null,"pull_url":null,"state":"superseded","archived":false,"hash":"996d2bb9ad1de998002fbc7d7bf738dadc2510de","submitter":{"id":34,"url":"https://patchwork.libcamera.org/api/1.1/people/34/?format=json","name":"Naushir Patuck","email":"naush@raspberrypi.com"},"delegate":null,"mbox":"https://patchwork.libcamera.org/patch/11414/mbox/","series":[{"id":1734,"url":"https://patchwork.libcamera.org/api/1.1/series/1734/?format=json","web_url":"https://patchwork.libcamera.org/project/libcamera/list/?series=1734","date":"2021-03-01T13:31:54","name":"DelayedControls updates and fixes","version":3,"mbox":"https://patchwork.libcamera.org/series/1734/mbox/"}],"comments":"https://patchwork.libcamera.org/api/patches/11414/comments/","check":"pending","checks":"https://patchwork.libcamera.org/api/patches/11414/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 3BC7DBD1F1\n\tfor ;\n\tMon, 1 Mar 2021 13:32:10 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 0A5F168A96;\n\tMon, 1 Mar 2021 14:32:10 +0100 (CET)","from mail-wr1-x430.google.com (mail-wr1-x430.google.com\n\t[IPv6:2a00:1450:4864:20::430])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 4594F68A7F\n\tfor ;\n\tMon, 1 Mar 2021 14:32:07 +0100 (CET)","by mail-wr1-x430.google.com with SMTP id f12so12359473wrx.8\n\tfor ;\n\tMon, 01 Mar 2021 05:32:07 -0800 (PST)","from naush-laptop.patuck.local ([88.97.76.4])\n\tby smtp.gmail.com with ESMTPSA id\n\ta75sm11263630wme.10.2021.03.01.05.32.05\n\t(version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);\n\tMon, 01 Mar 2021 05:32:06 -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=\"t13eMd1B\"; 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=t13eMd1B+9jr8JL6hnpZPpV56DEfUV47YANyp0XbeozyeWbCsgPWUnQC3Vftmb78dW\n\t4CKvc3XXoCvP8pSAEciw3THHbrHtCD3P7yQOfP1r9yu9FA2b9aWt+WRtUyslHMucV39F\n\t8o8CCVpTU1Q8Wl/hAah3AQPCPX7n0ljvsDz0JKjw33vbci0gloNh/FbG2onCM4mj4Ysw\n\tWTjo9Tb2izCZvIaPL9TjC26Tbemhbrcss1HjZe5OivXQVXh7Af2SfcsAc3ait/K3D2cr\n\tVfdgliMjitXRiTUby88Mbg096HMHyq4A0o+RTBHRvOXcP8Z7wip1fmaUvpigB4TPcIYS\n\tEQmg==","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=jo4glPd1z47JO9QIGJHgPs7xF2a6QkDR7h8RyeP95Xe4IlpMmjzWPIODWkML9PL9A2\n\tm5xqGYckWa6GnBkmufJ2QNTeL2jCI6Wp4GcNnvHIRygOJlfLvaOSuZ5NucbM0aLyfuPx\n\tr4GWImNLoA3WpxGW8N5wolbQ9ixqa/5QRpIHifLxcYGpc1NHtP9ckJr1llg8c1+s1FbU\n\t0TRa7yPsZ+0SHmOqMLXZgPBwOz/r4hiaGa15U7ZY+Vw9o2y2I6BgqrLvhsoaiJ+PC9wM\n\t8q6a+/NAoCaroA7lBnUOYJl/eM66qFYAYFwucyybBu6CxoX6m7EbXsxJbgz+4EhySFqn\n\tP+AA==","X-Gm-Message-State":"AOAM5335iIKjPLuoIonLYtA/ueRkgiFCkDXZy3k1ylcryBAX2Crw1k+R\n\thZIOC9rWm5h1ALsPDzW46GSke5cGAUTvxYoC","X-Google-Smtp-Source":"ABdhPJxGMcMmTNyxy7Rbdyw2Uy0Xptx9qEa4cJjB7xm8ZH/4DOl/1qyhrkNU4oM3f77Vh+axZ6IHGA==","X-Received":"by 2002:a05:6000:114b:: with SMTP id\n\td11mr16477710wrx.318.1614605526480; \n\tMon, 01 Mar 2021 05:32:06 -0800 (PST)","From":"Naushir Patuck ","To":"libcamera-devel@lists.libcamera.org","Date":"Mon, 1 Mar 2021 13:31:56 +0000","Message-Id":"<20210301133159.4179129-3-naush@raspberrypi.com>","X-Mailer":"git-send-email 2.25.1","In-Reply-To":"<20210301133159.4179129-1-naush@raspberrypi.com>","References":"<20210301133159.4179129-1-naush@raspberrypi.com>","MIME-Version":"1.0","Subject":"[libcamera-devel] [PATCH v3 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 \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","v3","2/5"]}