From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-5.4 required=3.0 tests=BAYES_00,DKIMWL_WL_HIGH, DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS, MAILING_LIST_MULTI,NICE_REPLY_A,SPF_HELO_NONE,SPF_PASS,USER_AGENT_SANE_1 autolearn=no autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 3E67CC433DF for ; Mon, 12 Oct 2020 15:08:39 +0000 (UTC) Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id BC09120679 for ; Mon, 12 Oct 2020 15:08:38 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (1024-bit key) header.d=redhat.com header.i=@redhat.com header.b="CtzZecE+" DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org BC09120679 Authentication-Results: mail.kernel.org; dmarc=fail (p=none dis=none) header.from=redhat.com Authentication-Results: mail.kernel.org; spf=pass smtp.mailfrom=qemu-devel-bounces+qemu-devel=archiver.kernel.org@nongnu.org Received: from localhost ([::1]:45820 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1kRzRF-0005ZU-Qe for qemu-devel@archiver.kernel.org; Mon, 12 Oct 2020 11:08:37 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:49572) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1kRzQB-0004wp-MF for qemu-devel@nongnu.org; Mon, 12 Oct 2020 11:07:31 -0400 Received: from us-smtp-delivery-124.mimecast.com ([216.205.24.124]:47453) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.90_1) (envelope-from ) id 1kRzQ7-0003pV-Vx for qemu-devel@nongnu.org; Mon, 12 Oct 2020 11:07:31 -0400 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1602515245; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=b6LaOfSdQ+0nmNScex2tz4+whjcvPoZEyuND4GIYkgA=; b=CtzZecE+UzEvY34Lzkhaw2NDpzCqTvSrhWjjHVtz40lcgvdOim28K+gEA9u1qMHw4ngHSz 9ziDKQR6UigaFNVQCml/55vYjC5po1p96nWdefWar4y8WoGptXARJZjnqjVhjq0F+BwqJ2 jCLYwc+zRK0X1Zon8EqGsbqxY4T9qv0= Received: from mimecast-mx01.redhat.com (mimecast-mx01.redhat.com [209.132.183.4]) (Using TLS) by relay.mimecast.com with ESMTP id us-mta-175-XjDjNKMROBW5j8BKGsPHkw-1; Mon, 12 Oct 2020 11:07:21 -0400 X-MC-Unique: XjDjNKMROBW5j8BKGsPHkw-1 Received: from smtp.corp.redhat.com (int-mx08.intmail.prod.int.phx2.redhat.com [10.5.11.23]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 0834710E218C for ; Mon, 12 Oct 2020 15:07:20 +0000 (UTC) Received: from thuth.remote.csb (ovpn-114-60.ams2.redhat.com [10.36.114.60]) by smtp.corp.redhat.com (Postfix) with ESMTP id 4682019C71; Mon, 12 Oct 2020 15:07:19 +0000 (UTC) Subject: Re: [PATCH] scripts: display how long each test takes to execute To: =?UTF-8?Q?Daniel_P=2e_Berrang=c3=a9?= , qemu-devel@nongnu.org References: <20200914110948.1425082-1-berrange@redhat.com> From: Thomas Huth Message-ID: Date: Mon, 12 Oct 2020 17:07:18 +0200 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Thunderbird/68.6.0 MIME-Version: 1.0 In-Reply-To: <20200914110948.1425082-1-berrange@redhat.com> X-Scanned-By: MIMEDefang 2.84 on 10.5.11.23 Authentication-Results: relay.mimecast.com; auth=pass smtp.auth=CUSA124A263 smtp.mailfrom=thuth@redhat.com X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset=utf-8 Content-Language: en-US Content-Transfer-Encoding: 8bit Received-SPF: pass client-ip=216.205.24.124; envelope-from=thuth@redhat.com; helo=us-smtp-delivery-124.mimecast.com X-detected-operating-system: by eggs.gnu.org: First seen = 2020/10/11 23:52:29 X-ACL-Warn: Detected OS = Linux 2.2.x-3.x [generic] [fuzzy] X-Spam_score_int: -20 X-Spam_score: -2.1 X-Spam_bar: -- X-Spam_report: (-2.1 / 5.0 requ) BAYES_00=-1.9, DKIMWL_WL_HIGH=-0.001, DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, NICE_REPLY_A=-0.001, RCVD_IN_DNSWL_NONE=-0.0001, RCVD_IN_MSPIKE_H4=0.001, RCVD_IN_MSPIKE_WL=0.001, 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.23 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Paolo Bonzini Errors-To: qemu-devel-bounces+qemu-devel=archiver.kernel.org@nongnu.org Sender: "Qemu-devel" On 14/09/2020 13.09, Daniel P. Berrangé wrote: > Sometimes under CI tests non-deterministically take longer to execute > than expected which can trigger timeouts. It is almost impossible to > diagnose this though without seeing execution time for each test case. > > With this change, when passing "V=1" to make, we get a duration printed > at test completion: > > $ make check V=1 > ...snip... > MALLOC_PERTURB_=${MALLOC_PERTURB_:-$(( ${RANDOM:-0} % 255 + 1))} QTEST_QEMU_IMG=./qemu-img G_TEST_DBUS_DAEMON=/home/berrange/src/virt/qemu/tests/dbus-vmstate-daemon.sh QTEST_QEMU_BINARY=./qemu-system-x86_64 tests/qtest/migration-test --tap -k > PASS 1 qtest-x86_64: migration-test /x86_64/migration/deprecated > PASS 2 qtest-x86_64: migration-test /x86_64/migration/bad_dest > PASS 3 qtest-x86_64: migration-test /x86_64/migration/fd_proto > PASS 4 qtest-x86_64: migration-test /x86_64/migration/validate_uuid > PASS 5 qtest-x86_64: migration-test /x86_64/migration/validate_uuid_error > PASS 6 qtest-x86_64: migration-test /x86_64/migration/validate_uuid_src_not_set > PASS 7 qtest-x86_64: migration-test /x86_64/migration/validate_uuid_dst_not_set > PASS 8 qtest-x86_64: migration-test /x86_64/migration/auto_converge > PASS 9 qtest-x86_64: migration-test /x86_64/migration/postcopy/unix > PASS 10 qtest-x86_64: migration-test /x86_64/migration/postcopy/recovery > PASS 11 qtest-x86_64: migration-test /x86_64/migration/precopy/unix > PASS 12 qtest-x86_64: migration-test /x86_64/migration/precopy/tcp > PASS 13 qtest-x86_64: migration-test /x86_64/migration/xbzrle/unix > PASS 14 qtest-x86_64: migration-test /x86_64/migration/multifd/tcp/none > PASS 15 qtest-x86_64: migration-test /x86_64/migration/multifd/tcp/cancel > PASS 16 qtest-x86_64: migration-test /x86_64/migration/multifd/tcp/zlib > TIME 28 seconds If I run "make check -j8" in parallel, it's quite hard to match the "TIME xx seconds" lines with the corresponding tests... so could you please in include the test name in the output there? Thanks, Thomas