From patchwork Fri Jun 1 12:32:21 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Max Reitz X-Patchwork-Id: 10443221 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id C3B31602BD for ; Fri, 1 Jun 2018 12:37:37 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id B395D28BF0 for ; Fri, 1 Jun 2018 12:37:37 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id A872828C7D; Fri, 1 Jun 2018 12:37:37 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-7.9 required=2.0 tests=BAYES_00, MAILING_LIST_MULTI, RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from lists.gnu.org (lists.gnu.org [208.118.235.17]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 16C6928BF0 for ; Fri, 1 Jun 2018 12:37:37 +0000 (UTC) Received: from localhost ([::1]:55513 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1fOjJI-0003VG-Cr for patchwork-qemu-devel@patchwork.kernel.org; Fri, 01 Jun 2018 08:37:36 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:37507) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1fOjEO-00009c-H1 for qemu-devel@nongnu.org; Fri, 01 Jun 2018 08:32:34 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1fOjEN-0008Ne-37 for qemu-devel@nongnu.org; Fri, 01 Jun 2018 08:32:32 -0400 Received: from mx3-rdu2.redhat.com ([66.187.233.73]:38630 helo=mx1.redhat.com) by eggs.gnu.org with esmtps (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:32) (Exim 4.71) (envelope-from ) id 1fOjEI-0008Jy-3S; Fri, 01 Jun 2018 08:32:26 -0400 Received: from smtp.corp.redhat.com (int-mx05.intmail.prod.int.rdu2.redhat.com [10.11.54.5]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 9E8A068817; Fri, 1 Jun 2018 12:32:25 +0000 (UTC) Received: from localhost (ovpn-204-42.brq.redhat.com [10.40.204.42]) by smtp.corp.redhat.com (Postfix) with ESMTPS id E0C6664660; Fri, 1 Jun 2018 12:32:23 +0000 (UTC) From: Max Reitz To: qemu-block@nongnu.org Date: Fri, 1 Jun 2018 14:32:21 +0200 Message-Id: <20180601123221.29437-1-mreitz@redhat.com> X-Scanned-By: MIMEDefang 2.79 on 10.11.54.5 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.11.55.1]); Fri, 01 Jun 2018 12:32:25 +0000 (UTC) X-Greylist: inspected by milter-greylist-4.5.16 (mx1.redhat.com [10.11.55.1]); Fri, 01 Jun 2018 12:32:25 +0000 (UTC) for IP:'10.11.54.5' DOMAIN:'int-mx05.intmail.prod.int.rdu2.redhat.com' HELO:'smtp.corp.redhat.com' FROM:'mreitz@redhat.com' RCPT:'' X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] [fuzzy] X-Received-From: 66.187.233.73 Subject: [Qemu-devel] [PATCH] iotests: Fix 219's timing X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Kevin Wolf , qemu-devel@nongnu.org, Max Reitz Errors-To: qemu-devel-bounces+patchwork-qemu-devel=patchwork.kernel.org@nongnu.org Sender: "Qemu-devel" X-Virus-Scanned: ClamAV using ClamSMTP 219 has two issues that may lead to sporadic failure, both of which are the result of issuing query-jobs too early after a job has been modified. This can then lead to different results based on whether the modification has taken effect already or not. First, query-jobs is issued right after the job has been created. Besides its current progress possibly being in any random state (which has already been taken care of), its total progress too is basically arbitrary, because the job may not yet have been able to determine it. This patch addresses this by just filtering the total progress, like what has been done for the current progress already. Secondly, query-jobs is issued right after a job has been resumed. The job may or may not yet have had the time to actually perform any I/O, and thus its current progress may or may not have advanced. To make sure it has indeed advanced (which is what the reference output already assumes), insert a sleep of 100 ms before query-jobs is invoked. With a slice time of 100 ms, a buffer size of 64 kB and a speed of 256 kB/s, this should be the right amount of time to let the job advance by exactly 64 kB. Signed-off-by: Max Reitz Reviewed-by: Eric Blake --- tests/qemu-iotests/219 | 10 +++++++--- tests/qemu-iotests/219.out | 10 +++++----- 2 files changed, 12 insertions(+), 8 deletions(-) diff --git a/tests/qemu-iotests/219 b/tests/qemu-iotests/219 index 898a26eef0..87ab07b94d 100755 --- a/tests/qemu-iotests/219 +++ b/tests/qemu-iotests/219 @@ -20,6 +20,7 @@ # Check using the job-* QMP commands with block jobs import iotests +import time iotests.verify_image_format(supported_fmts=['qcow2']) @@ -46,6 +47,8 @@ def test_pause_resume(vm): iotests.log(vm.qmp(resume_cmd, **{resume_arg: 'job0'})) iotests.log(iotests.filter_qmp_event(vm.event_wait('JOB_STATUS_CHANGE'))) + # Let the job proceed before querying its progress + time.sleep(0.1) iotests.log(vm.qmp('query-jobs')) def test_job_lifecycle(vm, job, job_args, has_ready=False): @@ -58,12 +61,13 @@ def test_job_lifecycle(vm, job, job_args, has_ready=False): iotests.log(vm.qmp(job, job_id='job0', **job_args)) # Depending on the storage, the first request may or may not have completed - # yet, so filter out the progress. Later query-job calls don't need the - # filtering because the progress is made deterministic by the block job - # speed + # yet (and the total progress may not have been fully determined yet), so + # filter out the progress. Later query-job calls don't need the filtering + # because the progress is made deterministic by the block job speed result = vm.qmp('query-jobs') for j in result['return']: del j['current-progress'] + del j['total-progress'] iotests.log(result) # undefined -> created -> running diff --git a/tests/qemu-iotests/219.out b/tests/qemu-iotests/219.out index 346801b655..740b3d06d7 100644 --- a/tests/qemu-iotests/219.out +++ b/tests/qemu-iotests/219.out @@ -3,7 +3,7 @@ Launching VM... Starting block job: drive-mirror (auto-finalize: True; auto-dismiss: True) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'job0', u'type': u'mirror'}]} +{u'return': [{u'status': u'running', u'id': u'job0', u'type': u'mirror'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} @@ -93,7 +93,7 @@ Waiting for PENDING state... Starting block job: drive-backup (auto-finalize: True; auto-dismiss: True) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'job0', u'type': u'backup'}]} +{u'return': [{u'status': u'running', u'id': u'job0', u'type': u'backup'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} @@ -144,7 +144,7 @@ Waiting for PENDING state... Starting block job: drive-backup (auto-finalize: True; auto-dismiss: False) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'job0', u'type': u'backup'}]} +{u'return': [{u'status': u'running', u'id': u'job0', u'type': u'backup'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} @@ -203,7 +203,7 @@ Waiting for PENDING state... Starting block job: drive-backup (auto-finalize: False; auto-dismiss: True) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'job0', u'type': u'backup'}]} +{u'return': [{u'status': u'running', u'id': u'job0', u'type': u'backup'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} @@ -262,7 +262,7 @@ Waiting for PENDING state... Starting block job: drive-backup (auto-finalize: False; auto-dismiss: False) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'job0', u'type': u'backup'}]} +{u'return': [{u'status': u'running', u'id': u'job0', u'type': u'backup'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'}