[User Question] Repeated severe performance problems on guest

[User Question] Repeated severe performance problems on guest

[Martin Wawro]

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       424
irq_exits              738940729       155
irq_injections         886685967      1012
irq_window              17463827         3
largepages                321488        18
mmio_exits               3062654        90
mmu_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

Re: [User Question] Repeated severe performance problems on guest

[Stefan Hajnoczi]

On Fri, Apr 12, 2013 at 05:04:27PM +0200, Martin Wawro wrote:
> Logging the kvm_stat on 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

Re: [User Question] Repeated severe performance problems on guest

[Martin Wawro]

On 04/16/2013 07:49 AM, Stefan Hajnoczi wrote:

Hi Stefan,

> 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

Re: [User Question] Repeated severe performance problems on guest

[Stefan Hajnoczi]

On Tue, Apr 16, 2013 at 09:49:20AM +0200, Martin Wawro wrote:
> On 04/16/2013 07:49 AM, Stefan Hajnoczi wrote:
> > 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.

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).

> 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)

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

Re: [User Question] Repeated severe performance problems on guest

[Martin Wawro]

Hi Stefan,

> 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.

> 
> 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

Re: [User Question] Repeated severe performance problems on guest

[Stefan Hajnoczi]

On Wed, Apr 17, 2013 at 09:52:39PM +0200, Martin Wawro wrote:
> Hi Stefan,
> 
> > 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.
> 
> > 
> > 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 :-) ).

I see.  That's a good reason to carefully monitor the host for things
that could interfere with guest performance.

Stefan

Re: [User Question] Repeated severe performance problems on guest

[Martin Wawro]

On 04/18/2013 09:25 AM, Stefan Hajnoczi wrote:

Hi Stefan,

> 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

Re: [User Question] Repeated severe performance problems on guest

[Stefan Hajnoczi]

On Thu, Apr 18, 2013 at 12:00 PM, Martin Wawro <martin.wawro@gmail.com> wrote:
> On 04/18/2013 09:25 AM, Stefan Hajnoczi wrote:
>> 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

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

Re: [User Question] Repeated severe performance problems on guest

[Martin Wawro]

On 04/18/2013 03:14 PM, Stefan Hajnoczi wrote:

Dear Stefan,

> 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?

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.


>
> 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.



>
> 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

> Stefan

Re: [User Question] Repeated severe performance problems on guest

[Stefan Hajnoczi]

On Thu, Apr 18, 2013 at 03:27:45PM +0200, Martin Wawro wrote:
> On 04/18/2013 03:14 PM, Stefan Hajnoczi wrote:
> > 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?
> 
> 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)

> >
> > 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.

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

Re: [User Question] Repeated severe performance problems on guest

[Martin Wawro]

On 04/19/2013 07:59 AM, Stefan Hajnoczi wrote:

Hi Stefan,

> 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)
Host CPU has EPT.


> 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

Re: [User Question] Repeated severe performance problems on guest

[Martin Wawro]

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       701
mmio_exits               4443644        72
mmu_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