From mboxrd@z Thu Jan 1 00:00:00 1970 From: Stefan Berger Subject: Re: Errors on MMIO read access on VM suspend / resume operations Date: Fri, 14 Jan 2011 14:27:11 -0500 Message-ID: <4D30A38F.3030002@linux.vnet.ibm.com> References: <4D2C8305.2090609@linux.vnet.ibm.com> <4D2ED260.4010801@redhat.com> Mime-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Cc: kvm@vger.kernel.org To: Avi Kivity Return-path: Received: from e36.co.us.ibm.com ([32.97.110.154]:55011 "EHLO e36.co.us.ibm.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S933167Ab1ANT1k (ORCPT ); Fri, 14 Jan 2011 14:27:40 -0500 Received: from d03relay01.boulder.ibm.com (d03relay01.boulder.ibm.com [9.17.195.226]) by e36.co.us.ibm.com (8.14.4/8.13.1) with ESMTP id p0EJMfgr028697 for ; Fri, 14 Jan 2011 12:22:41 -0700 Received: from d03av06.boulder.ibm.com (d03av06.boulder.ibm.com [9.17.195.245]) by d03relay01.boulder.ibm.com (8.13.8/8.13.8/NCO v10.0) with ESMTP id p0EJRX5l171368 for ; Fri, 14 Jan 2011 12:27:33 -0700 Received: from d03av06.boulder.ibm.com (loopback [127.0.0.1]) by d03av06.boulder.ibm.com (8.14.4/8.13.1/NCO v10.0 AVout) with ESMTP id p0EJW1YQ025520 for ; Fri, 14 Jan 2011 12:32:01 -0700 In-Reply-To: <4D2ED260.4010801@redhat.com> Sender: kvm-owner@vger.kernel.org List-ID: On 01/13/2011 05:22 AM, Avi Kivity wrote: > On 01/11/2011 06:19 PM, Stefan Berger wrote: >> >> What puzzles me is that the read operation may be run twice but >> others don't. >> > > Reads have split execution: kvm emulates the mmio instruction, notices > that it cannot satisfy the read request, exits to qemu, then restarts > the instruction. If the last step is omitted due to savevm, then kvm > will exit back to qemu again and your device will see the read > duplicated. That would then explain it on the read-side. MMIO writes seem to be ok. > >> If you have insights as why the above may be occurring, please let me >> know. A simple solution to work around this may be to introduce a >> register holding the index into the result packet where to read the >> next byte from (rather than advancing an internal pointer to the next >> byte), though this would deviate the driver from the standard >> interface the model currently implements. > > Most undesirable, I'd like to fix the bug. In the meantime I modified the tpm_tis driver making use of the fact that the packet can be re-read. I reread the packet when I recognize that the TIS is running out of bytes early (due to double-read). That makes it work. Debugging output of the driver shows the retrying, implying that the double-reads do occur. This work-around is just 'masking' the problem. > > Can you sprinkle some printfs() arount kvm_run (in qemu-kvm.c) to > verify this? > Here's what I did: diff --git a/kvm-all.c b/kvm-all.c index cae24bb..7ba222a 100644 --- a/kvm-all.c +++ b/kvm-all.c @@ -31,7 +31,7 @@ /* KVM uses PAGE_SIZE in it's definition of COALESCED_MMIO_MAX */ #define PAGE_SIZE TARGET_PAGE_SIZE -//#define DEBUG_KVM +#define DEBUG_KVM #ifdef DEBUG_KVM #define DPRINTF(fmt, ...) \ @@ -874,6 +874,9 @@ int kvm_cpu_exec(CPUState *env) kvm_arch_pre_run(env, run); cpu_single_env = NULL; qemu_mutex_unlock_iothread(); +#ifdef DEBUG_KVM + fprintf(stderr,"ioctl(KVM_RUN)\n"); +#endif ret = kvm_vcpu_ioctl(env, KVM_RUN, 0); qemu_mutex_lock_iothread(); cpu_single_env = env; > Good pattern: > > ioctl(KVM_RUN) > -> KVM_EXIT_MMIO > ioctl(KVM_RUN) > -> ENTR > no further KVM_RUNs > > or > > ioctl(KVM_RUN) > -> something other than KVM_EXIT_MMIO > no further KVM_RUNs > > Bad pattern: > > ioctl(KVM_RUN) > -> KVM_EXIT_MMIO > no further KVM_RUNs > Here's what I see in the failure case: ioctl(KVM_RUN) handle_mmio ioctl(KVM_RUN) handle_mmio ioctl(KVM_RUN) handle_mmio ioctl(KVM_RUN) handle_mmio interrupt exit requested 0+0 records in 0+0 records out 0 bytes (0 B) copied, 9.18e-06 s, 0.0 kB/s tpm_tis: suspend: locty 0 : r_offset = 61, w_offset = 0 tpm_tis: active locality : 0 tpm_tis: state of locality 0 : 0x2 tpm_tis: register dump: tpm_tis: 0x0000 : 000000a0 tpm_tis: 0x0008 : 0x8000008d tpm_tis: 0x000c : 0x00000003 tpm_tis: 0x0010 : 0x00000000 tpm_tis: 0x0014 : 0x00000095 tpm_tis: 0x0018 : 0x00011290 tpm_tis: 0x0f00 : 0x00010001 tpm_tis: 0x0f04 : 0x00000001 tpm_tis: read offset : 61 tpm_tis: result buffer : 00 c5 00 00 01 4f 00 00 00 00 00 00 00 01 00 03 tpm_tis: 00 01 00 00 00 0c 00 00 08 00 00 00 00 02 00 00 tpm_tis: 00 00 00 00 01 00 ca 47 12 16 3b e9 14 25 f7 f4 tpm_tis: b1 5e 69 c7 da 2d 5e f8 a3 82 04 bc e6>17 9e c5 tpm_tis: fd 2a f0 c0 01 13 c9 f2 c7 fb 5d e6 63 a7 db 48 tpm_tis: f2 85 bb 93 f1 b3 40 00 5b 27 70 5d 8c 28 79 89 tpm_tis: 36 49 7d 2f 56 b8 28 d5 61 74 4d ff 1c cf 4b a9 tpm_tis: a1 a8 b1 9e 6f 89 02 a3 21 02 86 8b ab 73 14 9b tpm_tis: 79 6e 86 27 da a8 2d 2c 0f 9c 28 ae 8d b7 b8 66 tpm_tis: 6a 20 92 3d 48 d0 c9 42 84 f6 2a ad e2 bd d3 11 tpm_tis: 2b e9 90 8e 1f 64 e4 de 9d 12 75 4a db 3f de d7 tpm_tis: 70 06 b0 95 47 56 9f a7 32 b6 20 1a 12 ea 8a ed tpm_tis: 24 b1 17 6b ad 4a 64 4b 64 b7 2c 1f 44 02 fe 2c tpm_tis: d8 72 1b bb 9c 42 8c 64 46 f4 29 ad 9c ff ea 37 tpm_tis: 48 77 26 4c 75 53 52 5a cb 6a 58 d5 d6 81 17 17 tpm_tis: 27 97 44 bf d7 0d 46 3c 9f b3 70 3f 5c 5c b1 ba tpm_tis: 86 5e 9c 78 bc 4c 40 41 90 ed 79 b2 06 64 73 6e tpm_tis: 64 18 e7 d0 9f 4d 7d d6 bb 2d 39 18 e1 41 3f 34 tpm_tis: 2b 9e a4 8e 70 a1 fa 35 1d f3 cf be 5a 73 4d dd tpm_tis: 49 dd 57 79 5b be 48 c6 44 3c 00 01 68 07 b3 2d tpm_tis: 42 08 2e 51 93 1a cf db 34 de 10 1d 94 fe 9a tpm_tis: write offset : 0 tpm_tis: request buffer:>00 c2 00 00 00 3b 00 00 00 81 40 00 00 06 78 e8 tpm_tis: a5 47 c3 e9 67 27 ac 27 5a a7 9c 53 19 f9 f0 cd tpm_tis: 8b 93 4a 82 85 af 00 e9 b8 c6 80 92 42 fb c6 55 tpm_tis: 06 00 f2 62 52 7b 8b cd 64 65 95 48+11535 records in 48+11535 records out 500881189 bytes (501 MB) copied, 14.282 s, 35.1 MB/s 2011-01-14 13:55:57.871: shutting down Immediately following is the restore part: 2011-01-14 13:55:59.575: starting up LC_ALL=C PATH=/usr/lib64/qt-3.3/bin:/usr/lib64/ccache:/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin HOME=/root USER=root LOGNAME=root QEMU_AUDIO_DRV=none [...] kvm_init_vcpu tpm_tis: resume : locty 0 : r_offset = 61, w_offset = 0 kvm_cpu_exec() interrupt exit requested kvm_cpu_exec() ioctl(KVM_RUN) irq_window_open kvm_cpu_exec() ioctl(KVM_RUN) handle_mmio ioctl(KVM_RUN) handle_mmio Cheers! Stefan