Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1naKyL-000707-9X for pgsql-hackers@arkaria.postgresql.org; Fri, 01 Apr 2022 17:22:05 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1naKyJ-0000R3-8v for pgsql-hackers@arkaria.postgresql.org; Fri, 01 Apr 2022 17:22:03 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1naKyI-0000Qs-4k for pgsql-hackers@lists.postgresql.org; Fri, 01 Apr 2022 17:22:03 +0000 Received: from out3-smtp.messagingengine.com ([66.111.4.27]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1naKyA-0002sR-Oc for pgsql-hackers@postgresql.org; Fri, 01 Apr 2022 17:22:01 +0000 Received: from compute2.internal (compute2.nyi.internal [10.202.2.46]) by mailout.nyi.internal (Postfix) with ESMTP id 7E8125C022B for ; Fri, 1 Apr 2022 13:21:52 -0400 (EDT) Received: from mailfrontend1 ([10.202.2.162]) by compute2.internal (MEProxy); Fri, 01 Apr 2022 13:21:52 -0400 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=anarazel.de; h= cc:content-type:date:date:from:from:in-reply-to:message-id :mime-version:reply-to:sender:subject:subject:to:to; s=fm1; bh=W dIzi4HuvaYWuE+s61DVVrawwD//2pDac4/hnrmRiQ0=; b=qzhn+fRETToG/zHqO kklarIY/7TQLLzhbZlK2okdaqYhupvBNCgM0KoXiXIKlmdA324F259k9KW3cZFJC dd1DCbm6zt3rXmM/psWCzTwfb8PBG4B2xkbE992GsMuP5pwaHLBbdFv3ldNdK1Zp FpsjnNm77l2kMTOeWT00i0K668+GUGttxVt/c9cabyhDUm25myqDxoe9Kxd9oRwg sfrjyXcC4oer2Tu4BLd50b8Sqh0z2jjUdNLgWSXU0HotpkDLqtClNj7okMwDa5sS woQP6Cjd0/1IlYpG661CyGU4TpFc5PqILBX7fKFJu4JtqkH6JJ3Ur4ziXdxGhNDy 0v2Bw== DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d= messagingengine.com; h=cc:content-type:date:date:from:from :in-reply-to:message-id:mime-version:reply-to:sender:subject :subject:to:to:x-me-proxy:x-me-proxy:x-me-sender:x-me-sender :x-sasl-enc; s=fm3; bh=WdIzi4HuvaYWuE+s61DVVrawwD//2pDac4/hnrmRi Q0=; b=VNLPSxzpvSuM9wrW6bwbW0LtrK8nt42BdIV5jv+/LmeOqFwAwhtFfWPow 9mtwMI4PCRaM9V+GTq4bCig+1wd6lQMESUFNp20zjw5mThPxtFKw1gjJH+LflFDe qN6kUuDmh2WdC/9LtmytX0kJAnWvjVyV4eRKQUO6uwuJVjcmlqzNjW07b9iENI5f s/QEk86iooaE+EExOmyzR0+C1ZVkOSOlnYbpAtX6y08NByg+nFRU8Q7L2/li280d c76a2ZamziA/uFs7yuBGdfcuSZDfNDA+bS2vwrUgDmetQnbI5Qxi2nPo5TO8W4YF 5eJiu27TaKCRbVSDh/w8u35r6HvSQ== X-ME-Sender: X-ME-Received: X-ME-Proxy-Cause: gggruggvucftvghtrhhoucdtuddrgedvvddrudeiiedgudduvdcutefuodetggdotefrod ftvfcurfhrohhfihhlvgemucfhrghsthforghilhdpqfgfvfdpuffrtefokffrpgfnqfgh necuuegrihhlohhuthemuceftddtnecunecujfgurhepfffhvffukfggtggusehttdertd dttddvnecuhfhrohhmpeetnhgurhgvshcuhfhrvghunhguuceorghnughrvghssegrnhgr rhgriigvlhdruggvqeenucggtffrrghtthgvrhhnpeeivdeileegueeutdefudfhfeethe fhvedvleejtefguefgtdeltddutedvheekffenucevlhhushhtvghrufhiiigvpedtnecu rfgrrhgrmhepmhgrihhlfhhrohhmpegrnhgurhgvshesrghnrghrrgiivghlrdguvg X-ME-Proxy: Received: by mail.messagingengine.com (Postfix) with ESMTPA for ; Fri, 1 Apr 2022 13:21:52 -0400 (EDT) Date: Fri, 1 Apr 2022 10:21:50 -0700 From: Andres Freund To: pgsql-hackers@postgresql.org Subject: Can we automatically add elapsed times to tap test log? Message-ID: <20220401172150.rsycz4lrn7ewruil@alap3.anarazel.de> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk Hi, right now I am looking at a test added in the shmstats patch that's slow on CI, on windows only. Unfortunately the regress_log_* output is useless as-is to figure out where things hang. I've hit this several times before. Of course it's not too hard to hack up something printing elapsed time. But ISTM that it'd be better if we were able to prefix the logging into regress_log_* with something like [timestamp + time since start of test] or [timestamp + time since start of test + time since last log message] This isn't just useful to figure out what parts of test are slow, but also helps correlate server logs with the regress_log_* output. Which right now is hard and inaccurate, requiring manually correlating statements between server log and the tap test (often there's no logging for statements in the regress_log_*). Greetings, Andres Freund