From nobody Mon Nov 25 12:32:55 2024 Delivered-To: importer@patchew.org Authentication-Results: mx.zohomail.com; dkim=pass header.i=@intel.com; spf=pass (zohomail.com: domain of gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=qemu-devel-bounces+importer=patchew.org@nongnu.org; dmarc=pass(p=none dis=none) header.from=intel.com ARC-Seal: i=1; a=rsa-sha256; t=1715141966; cv=none; d=zohomail.com; s=zohoarc; b=bTTQGkAFiM/i0krQCBWvxnHuiNDEjPqQW3h+Z12zuj1WV1VA5f3492aNDj1g7Vql7CAsl5hebhLC2OIvxHC/hIes3wsAgQktohktfTWs+gOXCCK8FUEYMJuHngJXjXgWCe21we6qrkhhCNeF53nhXnGt1rXa8fiFrYjt4alkwTg= ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=zohomail.com; s=zohoarc; t=1715141966; h=Content-Transfer-Encoding:Cc:Cc:Date:Date:From:From:List-Subscribe:List-Post:List-Id:List-Archive:List-Help:List-Unsubscribe:MIME-Version:Message-ID:Sender:Subject:Subject:To:To:Message-Id:Reply-To; bh=bzcApznlexu+JZ8tukFKh+oo5bQKiC8MimcbRnHpMuY=; b=RLc/XCLV6RefHCHqhHnTIPVBVEKLa/pFio3r0k9zi5kyJ0BvwJfdkjHGxyGhRvj0z6E/+/Aq0P9xn82nqL0Z5l83XswawWAJ/pOHJU4ZKiaSoiLtEvuKDPBnzaIZEQtXEtFzwkyUogVIxlS7gayYa6ys5tXaMT1a/KQZqQtvspo= ARC-Authentication-Results: i=1; mx.zohomail.com; dkim=pass header.i=@intel.com; spf=pass (zohomail.com: domain of gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=qemu-devel-bounces+importer=patchew.org@nongnu.org; dmarc=pass header.from= (p=none dis=none) Return-Path: Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) by mx.zohomail.com with SMTPS id 1715141966779299.2597790649015; Tue, 7 May 2024 21:19:26 -0700 (PDT) Received: from localhost ([::1] helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1s4YlC-0000I6-7w; Wed, 08 May 2024 00:18:30 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1s4Yl9-0000G3-Ie for qemu-devel@nongnu.org; Wed, 08 May 2024 00:18:27 -0400 Received: from mgamail.intel.com ([192.198.163.10]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1s4Yl6-0008JM-R0 for qemu-devel@nongnu.org; Wed, 08 May 2024 00:18:27 -0400 Received: from orviesa010.jf.intel.com ([10.64.159.150]) by fmvoesa104.fm.intel.com with ESMTP/TLS/ECDHE-RSA-AES256-GCM-SHA384; 07 May 2024 21:18:21 -0700 Received: from liuzhao-optiplex-7080.sh.intel.com ([10.239.160.36]) by orviesa010.jf.intel.com with ESMTP; 07 May 2024 21:18:19 -0700 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=intel.com; i=@intel.com; q=dns/txt; s=Intel; t=1715141905; x=1746677905; h=from:to:cc:subject:date:message-id:mime-version: content-transfer-encoding; bh=Et9LDUjAoJfJWqbCQk5T4r9yxQDevWwlglwqSn5X2VI=; b=Wz92KGH6CG9iDJNmO4UzdRE+1L8kMkcm3ACekCDgrH3HRzEw8cYxAhuz SNmbGZADiHtGaCxlZpL6Fhe6vgmCy4stmOFmt/NMAh2iLrwLTSeiJOn+j NKlBm7+mfqxpMQb2oOp5gxnA/T5AEfsNAfeIikZsKcKH5pNCVHX+08Cfi RQRSRWtUEVF95yyhSSp+AUE3hJDlu0bbS7y/IskvkthwIFBn4dmzXl2ds QfPUv5f4yIgACu4Kt1+0+rFW6Y+YMIXMY5XStIdUDR79P/IFK4yEGI9/c uYaXTdPt4QoRPczp7Eu7OPKVSJ/4Zh5KlyLv3KQCvLY2xJxG7wS4Xv++s Q==; X-CSE-ConnectionGUID: /4mOvDCJS9K9ziU4Ze56mA== X-CSE-MsgGUID: VNEZ9YOiRYWzF4TdHOWRZw== X-IronPort-AV: E=McAfee;i="6600,9927,11066"; a="22372044" X-IronPort-AV: E=Sophos;i="6.08,144,1712646000"; d="scan'208";a="22372044" X-CSE-ConnectionGUID: s6jswCxJTp2Rzc3sGypSlw== X-CSE-MsgGUID: X13gBac9T7Wvo7QSA9uo1g== X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="6.08,144,1712646000"; d="scan'208";a="28616464" From: Zhao Liu To: Mads Ynddal , John Snow , Cleber Rosa , Stefan Hajnoczi , Paolo Bonzini Cc: qemu-devel@nongnu.org, Zhao Liu Subject: [PATCH] scripts/simpletrace: Mark output with unstable timestamp as WARN Date: Wed, 8 May 2024 12:32:29 +0800 Message-Id: <20240508043229.3433128-1-zhao1.liu@intel.com> X-Mailer: git-send-email 2.34.1 MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable Received-SPF: pass (zohomail.com: domain of gnu.org designates 209.51.188.17 as permitted sender) client-ip=209.51.188.17; envelope-from=qemu-devel-bounces+importer=patchew.org@nongnu.org; helo=lists.gnu.org; Received-SPF: pass client-ip=192.198.163.10; envelope-from=zhao1.liu@intel.com; helo=mgamail.intel.com X-Spam_score_int: -49 X-Spam_score: -5.0 X-Spam_bar: ----- X-Spam_report: (-5.0 / 5.0 requ) BAYES_00=-1.9, DKIMWL_WL_HIGH=-0.581, DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, RCVD_IN_DNSWL_MED=-2.3, SPF_HELO_NONE=0.001, SPF_PASS=-0.001 autolearn=ham autolearn_force=no X-Spam_action: no action X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: qemu-devel-bounces+importer=patchew.org@nongnu.org Sender: qemu-devel-bounces+importer=patchew.org@nongnu.org X-ZohoMail-DKIM: pass (identity @intel.com) X-ZM-MESSAGEID: 1715141968747100003 Content-Type: text/plain; charset="utf-8" In some trace log, there're unstable timestamp breaking temporal ordering of trace records. For example: kvm_run_exit -0.015 pid=3D3289596 cpu_index=3D0x0 reason=3D0x6 kvm_vm_ioctl -0.020 pid=3D3289596 type=3D0xffffffffc008ae67 arg=3D0x7ffeefb= 5aa60 kvm_vm_ioctl -0.021 pid=3D3289596 type=3D0xffffffffc008ae67 arg=3D0x7ffeefb= 5aa60 Negative delta intervals tend to get drowned in the massive trace logs, and an unstable timestamp can corrupt the calculation of intervals between two events adjacent to it. Therefore, mark the outputs with unstable timestamps as WARN like: WARN: skip unstable timestamp: kvm_run_exit cur(8497404907761146)-pre(84974= 04907761161) pid=3D3289596 cpu_index=3D0x0 reason=3D0x6 WARN: skip unstable timestamp: kvm_vm_ioctl cur(8497404908603653)-pre(84974= 04908603673) pid=3D3289596 type=3D0xffffffffc008ae67 arg=3D0x7ffeefb5aa60 WARN: skip unstable timestamp: kvm_vm_ioctl cur(8497404908625787)-pre(84974= 04908625808) pid=3D3289596 type=3D0xffffffffc008ae67 arg=3D0x7ffeefb5aa60 This would help to identify unusual events. And skip them without updating Formatter2.last_timestamp_ns to avoid time back. Signed-off-by: Zhao Liu --- scripts/simpletrace.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py index cef81b0707f0..23911dddb8a6 100755 --- a/scripts/simpletrace.py +++ b/scripts/simpletrace.py @@ -343,6 +343,17 @@ def __init__(self): def catchall(self, *rec_args, event, timestamp_ns, pid, event_id): if self.last_timestamp_ns is None: self.last_timestamp_ns =3D timestamp_ns + + if timestamp_ns < self.last_timestamp_ns: + fields =3D [ + f'{name}=3D{r}' if is_string(type) else f'{name}=3D0x{= r:x}' + for r, (type, name) in zip(rec_args, event.args) + ] + print(f'WARN: skip unstable timestamp: {event.name} ' + f'cur({timestamp_ns})-pre({self.last_timestamp_ns}) = {pid=3D} ' + + f' '.join(fields)) + return + delta_ns =3D timestamp_ns - self.last_timestamp_ns self.last_timestamp_ns =3D timestamp_ns =20 --=20 2.34.1