qemu-devel.nongnu.org archive mirror
 help / color / mirror / Atom feed
* Re: [Qemu-devel] vm performance degradation after kvm live migration or save-restore with EPT enabled
@ 2013-08-08 11:31 Zhanghaoyu (A)
  2013-08-08 12:29 ` Paolo Bonzini
  0 siblings, 1 reply; 15+ messages in thread
From: Zhanghaoyu (A) @ 2013-08-08 11:31 UTC (permalink / raw)
  To: Xiao Guangrong
  Cc: Xiejunyong, Huangweidong (C), KVM, Gleb Natapov,
	Michael S. Tsirkin, Luonengjun, Xiahai, Marcelo Tosatti,
	paolo.bonzini@gmail.com, qemu-devel, Bruce Rogers, Zanghongyong,
	Xin Rong Fu, Yi Li, xiaoguangrong@linux.vnet.ibm.com, Hanweidong,
	Andreas Färber

[-- Attachment #1: Type: text/plain, Size: 7359 bytes --]

>>>> >> >> hi all,
>>>> >> >>
>>>> >> >> I met similar problem to these, while performing live migration or
>>>> >> >> save-restore test on the kvm platform (qemu:1.4.0, host:suse11sp2,
>>>> >> >> guest:suse11sp2), running tele-communication software suite in
>>>> >> >> guest,
>>>> >> >> https://lists.gnu.org/archive/html/qemu-devel/2013-05/msg00098.html
>>>> >> >> http://comments.gmane.org/gmane.comp.emulators.kvm.devel/102506
>>>> >> >> http://thread.gmane.org/gmane.comp.emulators.kvm.devel/100592
>>>> >> >> https://bugzilla.kernel.org/show_bug.cgi?id=58771
>>>> >> >>
>>>> >> >> After live migration or virsh restore [savefile], one process's CPU
>>>> >> >> utilization went up by about 30%, resulted in throughput
>>>> >> >> degradation of this process.
>>>> >> >>
>>>> >> >> If EPT disabled, this problem gone.
>>>> >> >>
>>>> >> >> I suspect that kvm hypervisor has business with this problem.
>>>> >> >> Based on above suspect, I want to find the two adjacent versions of
>>>> >> >> kvm-kmod which triggers this problem or not (e.g. 2.6.39, 3.0-rc1),
>>>> >> >> and analyze the differences between this two versions, or apply the
>>>> >> >> patches between this two versions by bisection method, finally find the key patches.
>>>> >> >>
>>>> >> >> Any better ideas?
>>>> >> >>
>>>> >> >> Thanks,
>>>> >> >> Zhang Haoyu
>>>> >> >
>>>> >> >I've attempted to duplicate this on a number of machines that are as similar to yours as I am able to get my hands on, and so far have not been able to see any performance degradation. And from what I've read in the above links, huge pages do not seem to be part of the problem.
>>>> >> >
>>>> >> >So, if you are in a position to bisect the kernel changes, that would probably be the best avenue to pursue in my opinion.
>>>> >> >
>>>> >> >Bruce
>>>> >>
>>>> >> I found the first bad
>>>> >> commit([612819c3c6e67bac8fceaa7cc402f13b1b63f7e4] KVM: propagate fault r/w information to gup(), allow read-only memory) which triggers this problem by git bisecting the kvm kernel (download from https://git.kernel.org/pub/scm/virt/kvm/kvm.git) changes.
>>>> >>
>>>> >> And,
>>>> >> git log 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4 -n 1 -p >
>>>> >> 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4.log
>>>> >> git diff
>>>> >> 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4~1..612819c3c6e67bac8fceaa7cc4
>>>> >> 02f13b1b63f7e4 > 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4.diff
>>>> >>
>>>> >> Then, I diffed 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4.log and
>>>> >> 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4.diff,
>>>> >> came to a conclusion that all of the differences between
>>>> >> 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4~1 and
>>>> >> 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4
>>>> >> are contributed by no other than 612819c3c6e67bac8fceaa7cc402f13b1b63f7e4, so this commit is the peace-breaker which directly or indirectly causes the degradation.
>>>> >>
>>>> >> Does the map_writable flag passed to mmu_set_spte() function have effect on PTE's PAT flag or increase the VMEXITs induced by that guest tried to write read-only memory?
>>>> >>
>>>> >> Thanks,
>>>> >> Zhang Haoyu
>>>> >>
>>>> >
>>>> >There should be no read-only memory maps backing guest RAM.
>>>> >
>>>> >Can you confirm map_writable = false is being passed to __direct_map? (this should not happen, for guest RAM).
>>>> >And if it is false, please capture the associated GFN.
>>>> >
>>>> I added below check and printk at the start of __direct_map() at the fist bad commit version,
>>>> --- kvm-612819c3c6e67bac8fceaa7cc402f13b1b63f7e4/arch/x86/kvm/mmu.c     2013-07-26 18:44:05.000000000 +0800
>>>> +++ kvm-612819/arch/x86/kvm/mmu.c       2013-07-31 00:05:48.000000000 +0800
>>>> @@ -2223,6 +2223,9 @@ static int __direct_map(struct kvm_vcpu
>>>>         int pt_write = 0;
>>>>         gfn_t pseudo_gfn;
>>>>
>>>> +        if (!map_writable)
>>>> +                printk(KERN_ERR "%s: %s: gfn = %llu \n", __FILE__, __func__, gfn);
>>>> +
>>>>         for_each_shadow_entry(vcpu, (u64)gfn << PAGE_SHIFT, iterator) {
>>>>                 if (iterator.level == level) {
>>>>                         unsigned pte_access = ACC_ALL;
>>>>
>>>> I virsh-save the VM, and then virsh-restore it, so many GFNs were printed, you can absolutely describe it as flooding.
>>>>
>>>The flooding you see happens during migrate to file stage because of dirty
>>>page tracking. If you clear dmesg after virsh-save you should not see any
>>>flooding after virsh-restore. I just checked with latest tree, I do not.
>>
>>I made a verification again.
>>I virsh-save the VM, during the saving stage, I run 'dmesg', no GFN printed, maybe the switching from running stage to pause stage takes so short time,
>>no guest-write happens during this switching period.
>>After the completion of saving operation, I run 'demsg -c' to clear the buffer all the same, then I virsh-restore the VM, so many GFNs are printed by running 'dmesg',
>>and I also run 'tail -f /var/log/messages' during the restoring stage, so many GFNs are flooded dynamically too.
>>I'm sure that the flooding happens during the virsh-restore stage, not the migration stage.
>>
>>On VM's normal starting stage, only very few GFNs are printed, shown as below
>>gfn = 16
>>gfn = 604
>>gfn = 605
>>gfn = 606
>>gfn = 607
>>gfn = 608
>>gfn = 609
>>
>>but on the VM's restoring stage, so many GFNs are printed, taking some examples shown as below,
>>
>That's really strange. Could you please disable ept and add your trace code to FNAME(fetch)( ), then
>test again to see what will happen?
>
>If there is still have many !rmap_writable cases, please measure the performance to see if it still has
>regression.
>
I made a test on SLES11-SP2 environment (kernel version: 3.0.13-0.27), and  applied below patch to arch/x86/kvm/paging_tmpl.h
@@ -480,6 +480,9 @@ static u64 *FNAME(fetch)(struct kvm_vcpu
        if (!is_present_gpte(gw->ptes[gw->level - 1]))
                return NULL;

+        if (!map_writable)
+                printk(KERN_ERR "%s: %s: gfn = %llu \n", __FILE__, __func__, gw->gfn);
+
        direct_access = gw->pt_access & gw->pte_access;
        if (!dirty)
                direct_access &= ~ACC_WRITE_MASK;
And, rebuild the kvm-kmod, then  re-insmod kvm-intel.ko with ept=0,
I virsh-save the VM, and then virsh-restore the VM,  the performance degradation disappeared, and no GFN printed.

But, I also made a test on the first bad commit(612819c3c6e67bac8fceaa7cc402f13b1b63f7e4), and applied above patch too,
With EPT disabled,  as soon as the restoring completed, the GFNs’ flooding is starting, take some examples to show as below,
130419
130551
3030618
3030619
3030620
3030621
3030622
3030623
3030624
3030625
3030626
3030627
3030628
3030629
3030630
3030631
3030632
2062054
2850204
2850205
2850207
2850208
2850271
2850273
2850274
2850277
2850278
2850281
2850282
2850284
2850285
2850286
2850288
2850289
2850292
2850293
2850296
2850297
2850299
2850300
2850301
2850365
2850366
2850369
2850370
2850372
2850373
2850374
2850376
2850377
2850380
…

but,  after a period of time, only gfn = 240 printed constantly. And some processes restore failed, so the performance cannot be measured.

Thanks,
Zhang Haoyu

>Many thanks!

[-- Attachment #2: Type: text/html, Size: 35669 bytes --]

^ permalink raw reply	[flat|nested] 15+ messages in thread
* [Qemu-devel] vm performance degradation after kvm live migration or save-restore with ETP enabled
@ 2013-07-11  9:36 Zhanghaoyu (A)
  2013-07-11 18:20 ` Bruce Rogers
  0 siblings, 1 reply; 15+ messages in thread
From: Zhanghaoyu (A) @ 2013-07-11  9:36 UTC (permalink / raw)
  To: KVM, qemu-devel, cloudfantom@gmail.com, mpetersen@peak6.com,
	Shouta.Uehara@jp.yokogawa.com, paolo.bonzini@gmail.com,
	Michael S. Tsirkin
  Cc: Huangweidong (C), Zanghongyong, Luonengjun, Hanweidong

hi all,

I met similar problem to these, while performing live migration or save-restore test on the kvm platform (qemu:1.4.0, host:suse11sp2, guest:suse11sp2), running tele-communication software suite in guest,
https://lists.gnu.org/archive/html/qemu-devel/2013-05/msg00098.html
http://comments.gmane.org/gmane.comp.emulators.kvm.devel/102506
http://thread.gmane.org/gmane.comp.emulators.kvm.devel/100592
https://bugzilla.kernel.org/show_bug.cgi?id=58771

After live migration or virsh restore [savefile], one process's CPU utilization went up by about 30%, resulted in throughput degradation of this process.
oprofile report on this process in guest,
pre live migration:
CPU: CPU with timer interrupt, speed 0 MHz (estimated)
Profiling through timer interrupt
samples  %        app name                 symbol name
248      12.3016  no-vmlinux               (no symbols)
78        3.8690  libc.so.6                memset
68        3.3730  libc.so.6                memcpy
30        1.4881  cscf.scu                 SipMmBufMemAlloc
29        1.4385  libpthread.so.0          pthread_mutex_lock
26        1.2897  cscf.scu                 SipApiGetNextIe
25        1.2401  cscf.scu                 DBFI_DATA_Search
20        0.9921  libpthread.so.0          __pthread_mutex_unlock_usercnt
16        0.7937  cscf.scu                 DLM_FreeSlice
16        0.7937  cscf.scu                 receivemessage
15        0.7440  cscf.scu                 SipSmCopyString
14        0.6944  cscf.scu                 DLM_AllocSlice

post live migration:
CPU: CPU with timer interrupt, speed 0 MHz (estimated)
Profiling through timer interrupt
samples  %        app name                 symbol name
1586     42.2370  libc.so.6                memcpy
271       7.2170  no-vmlinux               (no symbols)
83        2.2104  libc.so.6                memset
41        1.0919  libpthread.so.0          __pthread_mutex_unlock_usercnt
35        0.9321  cscf.scu                 SipMmBufMemAlloc
29        0.7723  cscf.scu                 DLM_AllocSlice
28        0.7457  libpthread.so.0          pthread_mutex_lock
23        0.6125  cscf.scu                 SipApiGetNextIe
17        0.4527  cscf.scu                 SipSmCopyString
16        0.4261  cscf.scu                 receivemessage
15        0.3995  cscf.scu                 SipcMsgStatHandle
14        0.3728  cscf.scu                 Urilex
12        0.3196  cscf.scu                 DBFI_DATA_Search
12        0.3196  cscf.scu                 SipDsmGetHdrBitValInner
12        0.3196  cscf.scu                 SipSmGetDataFromRefString

So, memcpy costs much more cpu cycles after live migration. Then, I restart the process, this problem disappeared. save-restore has the similar problem.

perf report on vcpu thread in host,
pre live migration:
Performance counter stats for thread id '21082':

                 0 page-faults
                 0 minor-faults
                 0 major-faults
             31616 cs
               506 migrations
                 0 alignment-faults
                 0 emulation-faults
        5075957539 L1-dcache-loads                                              [21.32%]
         324685106 L1-dcache-load-misses     #    6.40% of all L1-dcache hits   [21.85%]
        3681777120 L1-dcache-stores                                             [21.65%]
          65251823 L1-dcache-store-misses    # 1.77%                                   [22.78%]
                 0 L1-dcache-prefetches                                         [22.84%]
                 0 L1-dcache-prefetch-misses                                    [22.32%]
        9321652613 L1-icache-loads                                              [22.60%]
        1353418869 L1-icache-load-misses     #   14.52% of all L1-icache hits   [21.92%]
         169126969 LLC-loads                                                    [21.87%]
          12583605 LLC-load-misses           #    7.44% of all LL-cache hits    [ 5.84%]
         132853447 LLC-stores                                                   [ 6.61%]
          10601171 LLC-store-misses          #7.9%                                   [ 5.01%]
          25309497 LLC-prefetches             #30%                                  [ 4.96%]
           7723198 LLC-prefetch-misses                                          [ 6.04%]
        4954075817 dTLB-loads                                                   [11.56%]
          26753106 dTLB-load-misses          #    0.54% of all dTLB cache hits  [16.80%]
        3553702874 dTLB-stores                                                  [22.37%]
           4720313 dTLB-store-misses        #0.13%                                    [21.46%]
     <not counted> dTLB-prefetches
     <not counted> dTLB-prefetch-misses

      60.000920666 seconds time elapsed

post live migration:
Performance counter stats for thread id '1579':

                 0 page-faults                                                  [100.00%]
                 0 minor-faults                                                 [100.00%]
                 0 major-faults                                                 [100.00%]
             34979 cs                                                           [100.00%]
               441 migrations                                                   [100.00%]
                 0 alignment-faults                                             [100.00%]
                 0 emulation-faults
        6903585501 L1-dcache-loads                                              [22.06%]
         525939560 L1-dcache-load-misses     #    7.62% of all L1-dcache hits   [21.97%]
        5042552685 L1-dcache-stores                                             [22.20%]
          94493742 L1-dcache-store-misses    #1.8%                                   [22.06%]
                 0 L1-dcache-prefetches                                         [22.39%]
                 0 L1-dcache-prefetch-misses                                    [22.47%]
       13022953030 L1-icache-loads                                              [22.25%]
        1957161101 L1-icache-load-misses     #   15.03% of all L1-icache hits   [22.47%]
         348479792 LLC-loads                                                    [22.27%]
          80662778 LLC-load-misses           #   23.15% of all LL-cache hits    [ 5.64%]
         198745620 LLC-stores                                                   [ 5.63%]
          14236497 LLC-store-misses          #   7.1%                                    [ 5.41%]
          20757435 LLC-prefetches                                               [ 5.42%]
           5361819 LLC-prefetch-misses       #   25%                                [ 5.69%]
        7235715124 dTLB-loads                                                   [11.26%]
          49895163 dTLB-load-misses          #    0.69% of all dTLB cache hits  [16.96%]
        5168276218 dTLB-stores                                                  [22.44%]
           6765983 dTLB-store-misses        #0.13%                                    [22.24%]
     <not counted> dTLB-prefetches
     <not counted> dTLB-prefetch-misses

The "LLC-load-misses" went up by about 16%. Then, I restarted the process in guest, the perf data back to normal,
Performance counter stats for thread id '1579':

                 0 page-faults                                                  [100.00%]
                 0 minor-faults                                                 [100.00%]
                 0 major-faults                                                 [100.00%]
             30594 cs                                                           [100.00%]
               327 migrations                                                   [100.00%]
                 0 alignment-faults                                             [100.00%]
                 0 emulation-faults
        7707091948 L1-dcache-loads                                              [22.10%]
         559829176 L1-dcache-load-misses     #    7.26% of all L1-dcache hits   [22.28%]
        5976654983 L1-dcache-stores                                             [23.22%]
         160436114 L1-dcache-store-misses                                       [22.80%]
                 0 L1-dcache-prefetches                                         [22.51%]
                 0 L1-dcache-prefetch-misses                                    [22.53%]
       13798415672 L1-icache-loads                                              [22.28%]
        2017724676 L1-icache-load-misses     #   14.62% of all L1-icache hits   [22.49%]
         254598008 LLC-loads                                                    [22.86%]
          16035378 LLC-load-misses           #    6.30% of all LL-cache hits    [ 5.36%]
         307019606 LLC-stores                                                   [ 5.60%]
          13665033 LLC-store-misses                                             [ 5.43%]
          17715554 LLC-prefetches                                               [ 5.57%]
           4187006 LLC-prefetch-misses                                          [ 5.44%]
        7811502895 dTLB-loads                                                   [10.72%]
          40547330 dTLB-load-misses          #    0.52% of all dTLB cache hits  [16.31%]
        6144202516 dTLB-stores                                                  [21.58%]
           6313363 dTLB-store-misses                                            [21.91%]
     <not counted> dTLB-prefetches
     <not counted> dTLB-prefetch-misses

      60.000812523 seconds time elapsed

If EPT disabled, this problem gone.

I suspect that kvm hypervisor has business with this problem.
Based on above suspect, I want to find the two adjacent versions of kvm-kmod which triggers this problem or not (e.g. 2.6.39, 3.0-rc1),
and analyze the differences between this two versions, or apply the patches between this two versions by bisection method, finally find the key patches.

Any better ideas?

Thanks,
Zhang Haoyu

^ permalink raw reply	[flat|nested] 15+ messages in thread

end of thread, other threads:[~2013-08-31  7:45 UTC | newest]

Thread overview: 15+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-08-08 11:31 [Qemu-devel] vm performance degradation after kvm live migration or save-restore with EPT enabled Zhanghaoyu (A)
2013-08-08 12:29 ` Paolo Bonzini
  -- strict thread matches above, loose matches on Subject: below --
2013-07-11  9:36 [Qemu-devel] vm performance degradation after kvm live migration or save-restore with ETP enabled Zhanghaoyu (A)
2013-07-11 18:20 ` Bruce Rogers
2013-07-27  7:47   ` Zhanghaoyu (A)
2013-07-29 23:47     ` Marcelo Tosatti
2013-07-30  9:04       ` Zhanghaoyu (A)
2013-08-01  6:16         ` Gleb Natapov
2013-08-05  8:35           ` [Qemu-devel] vm performance degradation after kvm live migration or save-restore with EPT enabled Zhanghaoyu (A)
2013-08-05  8:43             ` Gleb Natapov
2013-08-05  9:09               ` Zhanghaoyu (A)
2013-08-05  9:15                 ` Andreas Färber
2013-08-05  9:22                   ` Zhanghaoyu (A)
2013-08-05  9:37                 ` Gleb Natapov
2013-08-06 10:47                   ` Zhanghaoyu (A)
2013-08-07  1:34                     ` Zhanghaoyu (A)
2013-08-07  5:52                       ` Gleb Natapov
2013-08-14  9:05                         ` Zhanghaoyu (A)
2013-08-20 13:33                         ` Zhanghaoyu (A)
2013-08-31  7:45                         ` Zhanghaoyu (A)
2013-08-05 18:27             ` Xiao Guangrong

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).