Repeated severe performance problems on guest
Hi All,
We are experiencing severe performance problems on a regular basis which require us to destroy and restart the guest OS. What happens is that the load average rises well above 50 and the guest OS becomes quite unresponsive,
though no serious workload is running on the system. Even issuing a clean reboot
command takes so long, that we have to abort that by simply cutting off the guest instead
of waiting for around 40mins for the clean reboot to happen.
These problems arise on a regular basis, though there is no apparent pattern behind
that. It may occur on larger workloads during daytime, but also during nighttime
when there is virtually no load on the system. There are no associated kernel messages
and the host does seem to work OK, though we think that also rebooting the host after
such an incident prolongs the time to the next occurence of the problem.
The system in general serves around 50 GB incoming traffic and 90 GB outgoing
traffic per day (it is a kind of fileserver). With 90% of the traffic occuring
during the daytime.
Logging the kvm_stat on the host, we obtained the following output during normal operation:
efer_reload 0 0
exits 5101302255 1974
fpu_reload 306359390 62 halt_exits 737202541 764 halt_wakeup 327442392 65 host_state_reload 2065997773 912 hypercalls 0 0 insn_emulation 1702740746 914 insn_emulation_fail 0 0 invlpg 0 0 io_exits 1352400686 148 irq_exits 736230648 38 irq_injections 881709782 767 irq_window 17402610 0 largepages 326880 0 mmio_exits 2951391 0 mmu_cache_miss 2986088 0 mmu_flooded 0 0 mmu_pde_zapped 0 0 mmu_pte_updated 0 0 mmu_pte_write 108123 0 mmu_recycled 0 0 mmu_shadow_zapped 3178728 0 mmu_unsync 0 0 nmi_injections 0 0 nmi_window 0 0 pf_fixed 84440791 0 pf_guest 0 0 remote_tlb_flush 37610010 8 request_irq 0 0 signal_exits 0 0 tlb_flush 0 0
and about 90 mins later, the output when the guest is in a state where it is rather unresponsive looks like this:
efer_reload 0 0
exits 5125445200 21349
fpu_reload 307627942 119 halt_exits 741717495 792 halt_wakeup 328747102 108 host_state_reload 2075042930 1330 hypercalls 0 0 insn_emulation 1711070317 1135 insn_emulation_fail 0 0 invlpg 0 0
io_exits 1356868798 424irq_exits 738940729 155irq_injections 886685967 1012irq_window 17463827 3
largepages 321488 18mmio_exits 3062654 90mmu_cache_miss 3552726 5581
mmu_flooded 0 0 mmu_pde_zapped 0 0 mmu_pte_updated 0 0 mmu_pte_write 108123 0 mmu_recycled 0 0 mmu_shadow_zapped 3781317 5396 mmu_unsync 0 0 nmi_injections 0 0 nmi_window 0 0 pf_fixed 86464743 18627 pf_guest 0 0 remote_tlb_flush 37881302 137 request_irq 0 0 signal_exits 0 0 tlb_flush 0 0
Our attempts to extract some valuable information from the logs inside the guest OS were not exactly successful. We could not find anything unusual as compared to normal operation, except for the huge load average.
We are running the following setup:
Host OS:
RHEL 6.3 (amd64) Kernel 2.6.32-279.22
qemu-kvm 0.12.1.2-2.295
Guest OS:
Ubuntu Server 10.04 (amd64) Kernel 2.6.32-45
Assigned CPU cores: 7 (we also tested single CPU pinning too, without success)
Assigned Memory: 32GB
All harddrives / network paravirtualized using virtio
The filesystem in use is mainly xfs.
Hardware:
IBM BladeServer HS22 with 44 GB memory and 2 Xeon QC CPUs (E5506)
Only a single guest is running on that machine.
We messed around with a lot of parameters (including clocksource, APICs etc.),
but none of them seems to have an effect on the problem other than just prolonging or shortening (and even this we cannot tell for sure due to some randomness involved) the interval to the next catastrophic failure.
Any hints on how to approach that problem are welcome, since we are out of ideas over here.
Best regards,
Martin
Quoted 1 line · Martin Wawro
Logging the
kvm_staton the host, we obtained the following output during
Besides the kvm_stat, general performance data from the host is useful when dealing with high load averages.
Do you have vmstat or sar data for periods of time when the machine was slow?
Stefan
On 04/16/2013 07:49 AM, Stefan Hajnoczi wrote:
Hi Stefan,
Quoted 7 lines
Besides the
kvm_stat, general performance data from the host is useful when dealing with high load averages.Do you have vmstat or sar data for periods of time when the machine was slow?
Stefan
We do have a rather exhaustive log on the guest. As for the host, we did not find
anything suspicious except for the kvm_stat output. So we did not log any more
than that.
Here is the output of "vmstat 5 5" on the guest:
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy
id wa
84 0 19596 104404 60 21932616 0 0 232 110 9 2 7
2 90 1
80 0 19596 98100 60 21933920 0 0 106 119 854 912 79 21 0 0 89 0 19596 94216 60 21932764 0 0 106 223 864 886 79 21 0 0 87 0 19596 95848 60 21927612 0 0 82 47 856 906 79 21 0 0
Load average at that time: 75 (1:20 AM)
The guest seems to have a hard time scheduling tasks. The log output, which is triggered by a simple cronjob that executes commands like "vmstat", "atop"
or simply appending some information from /proc and /sys to the log (in a sequential manner) is a bit scrambled (i.e. the expected order of the output is not kept, most likely because the cronjobs get piled up). This can also be seen on the rather large numbers in the first column (there is
no workload scheduled for that time and virtually no one is using the system,
the whole thing just seems to happen out of thin air).
The huge number of runnable tasks fits the high load average, but we could not
see the reason why the tasks are piling up. There is/was no apparent I/O issue on
disk or network and no messages from the kernel at that time. Also, there was no
swap activity on either guest or host (host has swap disabled).
For comparison, here is the output from 22:55 (10:55 PM), a couple of hours before the output from above:
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy
id wa
5 0 36 97848 60 24259656 0 0 227 111 7 1 7
2 91 1
6 0 36 121532 60 24220340 0 0 106 327 974 539 31
22 46 0
9 0 36 126108 60 24212756 0 0 6 0 1019 517 19
7 73 0
2 0 36 125264 60 24212780 0 0 0 26 1007 481 25
6 69 0
6 0 36 147564 60 24212808 0 0 4 120 1345 1161 25
10 65 0
If you need any more info, just let me know.
Best regards,
Martin
Quoted 7 lines · Martin Wawro
Quoted 6 lines · Stefan Hajnoczi
Besides the
kvm_stat, general performance data from the host is useful when dealing with high load averages.Do you have vmstat or sar data for periods of time when the machine was slow?
Quoted 7 lines
Quoted 1 line
Stefan
We do have a rather exhaustive log on the guest. As for the host, we did not find
anything suspicious except for thekvm_statoutput. So we did not log any more
than that.
The host is interesting too if you suspect KVM is involved in the performance issue (rather than it being purely an application issue inside the guest). For example, pidstat (from the sysstat package) on the host can tell you the guest mode CPU utilization percentage. That's useful for double-checking that the guest is indeed using up a lot of CPU time (the guest data you posted suggests it is).
Quoted 8 lines
Here is the output of "vmstat 5 5" on the guest:
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy
id wa
84 0 19596 104404 60 21932616 0 0 232 110 9 2 7
2 90 1
Quoted 8 lines
80 0 19596 98100 60 21933920 0 0 106 119 854 912 79 21 0 0 89 0 19596 94216 60 21932764 0 0 106 223 864 886 79 21 0 0 87 0 19596 95848 60 21927612 0 0 82 47 856 906 79 21 0 0Load average at that time: 75 (1:20 AM)
What does top or ps say about the 79% userspace CPU utilization? Perhaps this is unrelated to KVM and simply a buggy application going nuts.
Stefan
Hi Stefan,
Quoted 6 lines
The host is interesting too if you suspect KVM is involved in the performance issue (rather than it being purely an application issue inside the guest). For example, pidstat (from the sysstat package) on the host can tell you the guest mode CPU utilization percentage. That's useful for double-checking that the guest is indeed using up a lot of CPU time (the guest data you posted suggests it is).
I added it to the host logging to have more information next time something goes haywire.
Quoted 5 lines
What does top or ps say about the 79% userspace CPU utilization? Perhaps this is unrelated to KVM and simply a buggy application going nuts.
In this case, it was postgres (we have a couple of instances running on the guest). But it can also be another daemon process that usually behaves very well, so no real culprit to pinpoint it to.
We have the same setup (including OS versions and binary versions) in other locations (on "physical machines") running for years without any problems, so I doubt that this is an application issue. Another hint that it is not an application issue is the fact, that when we shutdown the processes that generate the load, the load average goes down for a couple of seconds and then again rises to sky-high values with another process consuming the load (until nothing is left running on the machine except for syslogd :-) ).
Best regards,
Martin
Quoted 18 lines · Martin Wawro
Hi Stefan,
Quoted 6 lines
The host is interesting too if you suspect KVM is involved in the performance issue (rather than it being purely an application issue inside the guest). For example, pidstat (from the sysstat package) on the host can tell you the guest mode CPU utilization percentage. That's useful for double-checking that the guest is indeed using up a lot of CPU time (the guest data you posted suggests it is).
I added it to the host logging to have more information next time something goes haywire.
Quoted 5 lines
What does top or ps say about the 79% userspace CPU utilization? Perhaps this is unrelated to KVM and simply a buggy application going nuts.
Quoted 10 lines
In this case, it was postgres (we have a couple of instances running on the guest). But it can also be another daemon process that usually behaves very well, so no real culprit to pinpoint it to.
We have the same setup (including OS versions and binary versions) in other locations (on "physical machines") running for years without any problems, so I doubt that this is an application issue. Another hint that it is not an application issue is the fact, that when we shutdown the processes that generate the load, the load average goes down for a couple of seconds and then again rises to sky-high values with another process consuming the load (until nothing is left running on the machine except for syslogd :-) ).
I see. That's a good reason to carefully monitor the host for things that could interfere with guest performance.
Stefan
On 04/18/2013 09:25 AM, Stefan Hajnoczi wrote:
Hi Stefan,
Quoted 4 lines
I see. That's a good reason to carefully monitor the host for things that could interfere with guest performance.
Stefan
Seems that today is a bad day for our server. We had to give him the boot (again).
Also the results of the pidstat output do not seem to yield much additional information
on what could be the problem.
In order to avoid spilling this mailing list, here is some data gathered on the host:
http://pastebin.com/8q7UgXkJ
...and this is the data from the guest:
http://pastebin.com/xLTYZjGp
Best regards,
Martin
Quoted 11 lines · Martin Wawro
Quoted 4 lines · Stefan Hajnoczi
I see. That's a good reason to carefully monitor the host for things that could interfere with guest performance.
Stefan
Seems that today is a bad day for our server. We had to give him the boot (again).
Also the results of the pidstat output do not seem to yield much additional information
on what could be the problem.
Quoted 6 lines
In order to avoid spilling this mailing list, here is some data gathered on the host:
http://pastebin.com/8q7UgXkJ...and this is the data from the guest:
http://pastebin.com/xLTYZjGp
No answer but some more questions.
Regarding the kvm_stat output, the exits are caused by 68,000 pagefaults/second (pf_fixed). Perhaps someone can explain what this means?
The host has 8 cores, the guest has 7. Host pidstat shows qemu-kvm consuming 263.9% CPU:
11:25:27 4017 11.13 34.65 218.12 263.90 7 qemu-kvm
Why is the guest not getting more than 3 CPUs since the host is otherwise idle?
You may want to disable ksmd on the host since you only have 1 guest, but I doubt that will fix the main problem:
11:25:27 100 0.00 7.89 0.00 7.89 7 ksmd
For details, see https://www.kernel.org/doc/Documentation/vm/ksm.txt.
What is the python process on the host doing? Is it poking libvirt?
11:25:27 4558 4.66 3.55 0.00 8.21 7 python 11:25:27 3659 3.99 4.55 0.00 8.54 7 libvirtd
Stefan
On 04/18/2013 03:14 PM, Stefan Hajnoczi wrote:
Dear Stefan,
Quoted 6 lines
No answer but some more questions.
Regarding the
kvm_statoutput, the exits are caused by 68,000 pagefaults/second (pf_fixed). Perhaps someone can explain what this means?
Quoted 6 lines
The host has 8 cores, the guest has 7. Host pidstat shows qemu-kvm consuming 263.9% CPU:
11:25:27 4017 11.13 34.65 218.12 263.90 7 qemu-kvm
Why is the guest not getting more than 3 CPUs since the host is otherwise idle?
If one waits a little longer, top shows all 7 cores under utilization (700%). Unfortunately
we have to be quick with the reboots during daytime, because the system is in
production use and we have not decided yet to completely replace it.
Quoted 5 lines
You may want to disable ksmd on the host since you only have 1 guest, but I doubt that will fix the main problem:
11:25:27 100 0.00 7.89 0.00 7.89 7 ksmd
We did that earlier today. No difference.
Quoted 7 lines
For details, see https://www.kernel.org/doc/Documentation/vm/ksm.txt.
What is the python process on the host doing? Is it poking libvirt?
11:25:27 4558 4.66 3.55 0.00 8.21 7 python 11:25:27 3659 3.99 4.55 0.00 8.54 7 libvirtd
That is virt-manager.py, exactly doing that.
Best regards,
Martin
Quoted 1 line
Stefan
Quoted 12 lines · Martin Wawro
Quoted 11 lines · Stefan Hajnoczi
No answer but some more questions.
Regarding the
kvm_statoutput, the exits are caused by 68,000 pagefaults/second (pf_fixed). Perhaps someone can explain what this means?The host has 8 cores, the guest has 7. Host pidstat shows qemu-kvm consuming 263.9% CPU:
11:25:27 4017 11.13 34.65 218.12 263.90 7 qemu-kvm
Quoted 7 lines
Quoted 1 line
Why is the guest not getting more than 3 CPUs since the host is otherwise idle?
If one waits a little longer, top shows all 7 cores under utilization (700%). Unfortunately
we have to be quick with the reboots during daytime, because the system is in
production use and we have not decided yet to completely replace it.
BTW does the host CPU support Intel Extended Page Tables or AMD Nested Page Tables? grep 'npt\|ept' /proc/cpuinfo
(I think the kvm_stat is saying EPT/NPT are not in use)
Quoted 9 lines
Quoted 7 lines
For details, see https://www.kernel.org/doc/Documentation/vm/ksm.txt.
What is the python process on the host doing? Is it poking libvirt?
11:25:27 4558 4.66 3.55 0.00 8.21 7 python 11:25:27 3659 3.99 4.55 0.00 8.54 7 libvirtdThat is
virt-manager.py, exactly doing that.
Okay, I was wondering if something is causing libvirt and maybe QEMU to act strangely. If its just virt-manager then it's probably not the issue.
Stefan
On 04/19/2013 07:59 AM, Stefan Hajnoczi wrote:
Hi Stefan,
Quoted 4 lines
BTW does the host CPU support Intel Extended Page Tables or AMD Nested Page Tables? grep 'npt\|ept'
/proc/cpuinfo(I think the
kvm_statis saying EPT/NPT are not in use)
Host CPU has EPT.
Quoted 4 lines
That is
virt-manager.py, exactly doing that.
Okay, I was wondering if something is causing libvirt and maybe QEMU to act strangely. If its just virt-manager then it's probably not the issue.
We upgraded to RHEL 6.4 yesterday. Now running kernel 2.6.32-358 and qemu-kvm 0.12.1.2-2.355 .
Maybe this does improve something...
Best regards,
Martin
Hi Stefan,
This morning we had to reboot the guest system again. pidstat logging was not
enabled on the host (planned to do that later, hate myself for that). Again it
looks like the schedulerinside the guest just does not want to schedule anymore
(or takes coffee breaksinbetween), because tasks are piling up in the queue.
Info from guest (load at that time 28.88):
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy
id wa
43 0 0 129684 56 25702740 0 0 399 58 9 167 16
11 72 1
52 0 0 115632 56 25706964 0 0 85 1118 1091 1225 74 26 0 0 59 0 0 150380 56 25692648 0 0 122 681 1135 1283 73 27 0 0 47 0 0 135424 56 25699504 0 0 79 415 1076 1064 74 26 0 0 49 0 0 132420 56 25705604 0 0 130 551 1113 1083 74 26 0 0
Again, there is no apparent reason why the load should be that high. It just spikes
up until we finally put the guest out of its misery (5 minutes before the load went
up to 28.88 it was at 2.68 (normal for that time of day). We did not wait until we
ended up at >70, because the system was actively used at that time. Shutdown occured when load was at 35). There was no unusual workload and during normal
operation the load on the system at that time of day is (reproducible) between 2 and 4.
Info from host (same time, load on host 6.32 w/ 7 cores assigned to the guest):
kvm_stat:
efer_reload 0 0
exits 2549659797 106703
fpu_reload 18554960 630 halt_exits 33754341 230 halt_wakeup 17080387 188 host_state_reload 91193250 2016 hypercalls 0 0 insn_emulation 99324537 2569 insn_emulation_fail 0 0 invlpg 0 0 io_exits 51338365 1097 irq_exits 82789640 6115 irq_injections 53016628 1494
irq_window 1240060 70
largepages 10937 701mmio_exits 4443644 72mmu_cache_miss 409801870 21168
mmu_flooded 0 0 mmu_pde_zapped 0 0 mmu_pte_updated 0 0 mmu_pte_write 108123 0 mmu_recycled 0 0 mmu_shadow_zapped 411841775 18928 mmu_unsync 0 0 nmi_injections 0 0 nmi_window 0 0 pf_fixed 2248004983 95456 pf_guest 0 0 remote_tlb_flush 35279973 4976 request_irq 0 0 signal_exits 0 0 tlb_flush 0 0
vmstat 5 5:
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy
id wa st
7 0 0 4442088 160968 2382804 0 0 251 115 3 1 9
6 85 0 0
7 0 0 4459008 160968 2382804 0 0 497 1021 11254 3502 6
84 10 0 0
7 0 0 4431464 160968 2382804 0 0 372 1054 10286 2753 6
83 11 0 0
7 0 0 4437076 160972 2382804 0 0 552 1710 12890 4518 7
82 10 0 0
8 0 0 4438508 160972 2382804 0 0 174 1736 10398 3092 5
84 10 0 0
Best regards,
Martin