From patchwork Tue Feb 16 08:53:39 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Naushir Patuck X-Patchwork-Id: 11301 X-Patchwork-Delegate: niklas.soderlund@ragnatech.se Return-Path: X-Original-To: parsemail@patchwork.libcamera.org Delivered-To: parsemail@patchwork.libcamera.org Received: from lancelot.ideasonboard.com (lancelot.ideasonboard.com [92.243.16.209]) by patchwork.libcamera.org (Postfix) with ESMTPS id B9B72BD1EF for ; Tue, 16 Feb 2021 08:53:52 +0000 (UTC) Received: from lancelot.ideasonboard.com (localhost [IPv6:::1]) by lancelot.ideasonboard.com (Postfix) with ESMTP id BEC52637E4; Tue, 16 Feb 2021 09:53:51 +0100 (CET) Authentication-Results: lancelot.ideasonboard.com; dkim=fail reason="signature verification failed" (2048-bit key; unprotected) header.d=raspberrypi.com header.i=@raspberrypi.com header.b="imi5vIDH"; dkim-atps=neutral Received: from mail-wr1-x430.google.com (mail-wr1-x430.google.com [IPv6:2a00:1450:4864:20::430]) by lancelot.ideasonboard.com (Postfix) with ESMTPS id 952B0637CC for ; Tue, 16 Feb 2021 09:53:49 +0100 (CET) Received: by mail-wr1-x430.google.com with SMTP id t15so11940932wrx.13 for ; Tue, 16 Feb 2021 00:53:49 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=raspberrypi.com; s=google; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=+ImmBSuKB64yJiFyMrEt9UThLRyd9r3D1+xm3Snp0RU=; b=imi5vIDHQahPJzkjIAym22LGcN2fG5SZPBqMSJwZV0FGCK2sh2lVBrVGyKpd4J/pMz x1vC0xRGd+MP2nagfN+qtaC+rA20ZyJmODscLtAlGNvMaC+NHNKN1CTybEcYILKH72cq O+XpHOzJuj8XdAPyUED/OJ736aZLsviGXtE5IZ/rqINaJw0JB/nG8jlC3eQ5FHWvDC0s eeeRE1xzczYxdUMi6ZVLsTUk2J2ObEdjXHNvDoBnHEnFVqO5AVPX7wp2xNdXrwqH8C1k IDzC8Pr1amoOHBQCSwQBuTqbHITwtVgNsn1UPQg2N1PtfvIVqLHH9MrKQll0jkAmPHgb XQJQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=+ImmBSuKB64yJiFyMrEt9UThLRyd9r3D1+xm3Snp0RU=; b=ZOxDBvjaWSjvR7gkVxH2yXjzvOU3jnNsYI7SYudl+BYRhl3aFNX5rAjvwYJHEdh9TV T5+paczf6Z24QxV7w7wD/D0aGOaebl+VZjTOCMIGpdM5gmfc7wv70XE0sXnDn3aeWQmU KeAU+rC09oyZpSWiL/RTc8FLkVm6/Gv6xmhf+c321oNdZSv33yCxkARF1lBpc5fbFGT9 RnBIqCzdFPOQKOa0D2AX75SVzi4ZMMlAqvYehghYhT+d0qwcdr8bzroCD5BIOGHOGgy0 0OKufoDTNd32Vue/CPx+Ps94SiJ4vnbksbuGIJAsRDLO9wNZgolLfgOnpaRkV1bcE4SR E+AA== X-Gm-Message-State: AOAM531RuO/+a23em01+S4ho32Fs9k/7bVHBg02YGgs1o5yLEMDIG4pg M7ir27m5wh9CkHUyeU7fuLzqnKXqPZQEZ9bF X-Google-Smtp-Source: ABdhPJzY1mfybuTppVcnxFDLGczNKPMujgvVyprKVVjs4yiMpsi5r2b1BuW0EFha+cO1Zjrb9Uyz0Q== X-Received: by 2002:a05:6000:108f:: with SMTP id y15mr22895022wrw.195.1613465628622; Tue, 16 Feb 2021 00:53:48 -0800 (PST) Received: from naush-laptop.patuck.local ([88.97.76.4]) by smtp.gmail.com with ESMTPSA id e1sm9300369wrd.44.2021.02.16.00.53.47 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Tue, 16 Feb 2021 00:53:48 -0800 (PST) From: Naushir Patuck To: libcamera-devel@lists.libcamera.org Date: Tue, 16 Feb 2021 08:53:39 +0000 Message-Id: <20210216085342.1012717-3-naush@raspberrypi.com> X-Mailer: git-send-email 2.25.1 In-Reply-To: <20210216085342.1012717-1-naush@raspberrypi.com> References: <20210216085342.1012717-1-naush@raspberrypi.com> MIME-Version: 1.0 Subject: [libcamera-devel] [PATCH v2 2/5] utils: raspberrypi: Add a DelayedControls log parser X-BeenThere: libcamera-devel@lists.libcamera.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: libcamera-devel-bounces@lists.libcamera.org Sender: "libcamera-devel" This script will parse log output from the DelayedControls helper, when enabled with: LIBCAMERA_LOG_LEVELS=DelayedControls:0 It tabulates all control queuing/writing/getting per frame and warns about potential issues related to frame delays not being account for, or writes that are lagging behind or missed. Run with the following command: python3 ./delayedctrls_parse.py Signed-off-by: Naushir Patuck Acked-by: Paul Elder --- utils/raspberrypi/delayedctrls_parse.py | 98 +++++++++++++++++++++++++ 1 file changed, 98 insertions(+) create mode 100644 utils/raspberrypi/delayedctrls_parse.py diff --git a/utils/raspberrypi/delayedctrls_parse.py b/utils/raspberrypi/delayedctrls_parse.py new file mode 100644 index 000000000000..20c92fb620e6 --- /dev/null +++ b/utils/raspberrypi/delayedctrls_parse.py @@ -0,0 +1,98 @@ +import re +import sys +import os + +if len(sys.argv) != 2: + print("Usage: {} ".format(sys.argv[0])) + sys.exit() + +infile = sys.argv[1] +insplit = os.path.splitext(infile) +outfile = insplit[0] + '_parsed' + insplit[1] + +frame_re = re.compile('frame (\d+) started') + +delays = {'Analogue Gain': 1, 'Exposure': 2, 'Vertical Blanking': 2} +ctrl_action = {'Write': {}, 'Get': {}, 'Queue': {}, 'No-op': {}} +ctrl_re = {'Write': re.compile('Setting (.*?) to (\d+) at index (\d+)'), + 'No-op': re.compile('Queue is empty, (.*?) (.*?) (.*?)'), + 'Get': re.compile('Reading (.*?) to (\d+) at index (\d+)'), + 'Queue': re.compile('Queuing (.*?) to (\d+) at index (\d+)')} + +frame_num = -1 + +max_delay = 0 +for k, d in delays.items(): + if max_delay < d: + max_delay = d + +with open(infile) as f: + lines = f.readlines() + +for line in lines: + r = frame_re.search(line) + if r: + frame_num = int(r.group(1)) + + for (key, re) in ctrl_re.items(): + r = re.search(line) + if r: + ctrl_action[key][(frame_num, r.group(1))] = (r.group(2), r.group(3)) + +with open(outfile, 'wt') as f: + queueIndex = 1 + f.write('{:<10}{:<15}{:<12}{:<18}{}\n'.format('Frame', 'Action', 'Gain', 'Exposure', 'Vblank')) + for frame in range(0, frame_num + 1): + for (k, a) in ctrl_action.items(): + str = '{:<10}{:<10}'.format(frame, k) + + for c in delays.keys(): + # Tabulate all results + str += '{:>5} {:<10}'.format(a[(frame, c)][0] if (frame, c) in a.keys() else '---', + '[' + (a[(frame, c)][1] if (frame, c) in a.keys() else '-') + ']') + + f.write(str.strip() + '\n') + +# Test the write -> get matches the set delay. +for (frame, c) in ctrl_action['Write'].keys(): + set_value = ctrl_action['Write'][(frame, c)][0] + delay_frame = frame + delays[c] + if (delay_frame <= frame_num): + if (delay_frame, c) in ctrl_action['Get']: + get_value = ctrl_action['Get'][(delay_frame, c)][0] + if get_value != set_value: + print('Error: {} written at frame {} to value {} != {} at frame {}' + .format(c, frame, set_value, get_value, delay_frame)) + else: + print('Warning: {} written at frame {} to value {} did not get logged on frame {} - dropped frame?' + .format(c, frame, set_value, delay_frame)) + +# Test the queue -> write matches the set delay. +for (frame, c) in ctrl_action['Queue'].keys(): + set_value = ctrl_action['Queue'][(frame, c)][0] + delay_frame = frame + max_delay - delays[c] + 1 + if (delay_frame <= frame_num): + if (delay_frame, c) in ctrl_action['Write']: + write_value = ctrl_action['Write'][(delay_frame, c)][0] + if write_value != set_value: + print('Info: {} queued at frame {} to value {} != {} written at frame {}' + ' - lagging behind or double queue on a single frame!' + .format(c, frame, set_value, write_value, delay_frame)) + else: + print('Warning: {} queued at frame {} to value {} did not get logged on frame {} - dropped frame?' + .format(c, frame, set_value, delay_frame)) + +# Test the get -> write matches the set delay going backwards. +for (frame, c) in ctrl_action['Get'].keys(): + get_value = ctrl_action['Get'][(frame, c)][0] + delay_frame = frame - delays[c] + if (delay_frame >= 6): + if (delay_frame, c) in ctrl_action['Write']: + write_value = ctrl_action['Write'][(delay_frame, c)][0] + if get_value != write_value: + print('Info: {} got at frame {} to value {} != {} written at frame {}' + ' - lagging behind or double queue on a single frame!' + .format(c, frame, get_value, write_value, delay_frame)) + else: + print('Warning: {} got at frame {} to value {} did not get written on frame {}' + .format(c, frame, get_value, delay_frame))