Re: Errors on MMIO read access on VM suspend / resume operations

[Stefan Berger <stefanb@linux.vnet.ibm.com>]

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