CPU-Steal Time, hoher IO Wait - wo kann das Problem liegen?

[reox]

Ich hab auf einem Hetzner vServer seit einigen Tagen das Problem, dass IO Wait und Steal-Time recht hoch sind. Die Steal Time war vorher immer 0, jetzt ist sie im Durchschnitt 3 und IOWait war vorher ca 3%, jetzt sind es über 30... Das System erzeugt damit schon eine beträchtliche Load und einloggen auf der Maschine dauert ziemlich lang.

Top schaut so aus:

Code: Alles auswählen

top - 11:53:43 up 1 day, 15:38,  1 user,  load average: 1.59, 1.61, 1.14
Tasks:  86 total,   2 running,  84 sleeping,   0 stopped,   0 zombie
%Cpu(s):  2.3 us,  2.9 sy,  0.0 ni,  0.0 id, 78.6 wa,  0.0 hi,  6.9 si,  9.2 st
KiB Mem:    506324 total,   500760 used,     5564 free,    13272 buffers
KiB Swap:  2096124 total,   191344 used,  1904780 free.   162252 cached Mem

Hetzner sagt dazu folgendes:

wir haben das Hostsystem überprüft und konnten keine Probleme feststellen.
Bitte beachten Sie, dass wir leider keinen Software-Support für unsere dedizierten und virtuellen Server anbieten.

Ich habe seit dem Problem auftritt eigentlich nix geändert, nur ein paar Dienste gekillt weil ich dachte die sind vllt schuld... Liegt das jetzt wirklich an mir? Ich kann mir nicht vorstellen dass die Software am vServer eine so hohe IO Wait erzeugt und Steal Time kommt ja nun wirklich nicht von mir...?!

[gbotti]

Da kannst du nichts dafür. Steal bedeutet in diesem Fall, dass deine VM auf etwas warten muss. In der Regel hat ein anderer vServer gerade extremen Ressourcen-Hunger.

Bei IBM habe ich das hier gelesen:

Steal time is the percentage of time a virtual CPU waits for a real CPU while the hypervisor is servicing another virtual processor.

I/O-Wait bedeutet einfach, dass irgendetwas zwischen VM-Kernel und Festplatten (am wahrscheinlichsten die Festplatten) nicht mit den anstehenden Operationen zurecht kommen. Wenn jetzt jemand eine VM mit vielen kleinen Schreiboperationen betreibt, beispielsweise einen SQL-Server, dann führt das zu hohem I/O-Aufkommen, der vom Hostsystem erst mal bewältigt werden muss.

Leider kenne ich die Hosts von Hetzner nicht, ich weiß aber, dass bei einem anderen Hoster für vServer gut gespart werden kann und die Festplatten Beispielsweise in nem Software-RAID Hängen, was den Server noch langsamer macht. Da wäre ein RAID-Controller mit BBU und Cache-Speicher hilfreich... Aber darauf haben wir "Enduser" leider keinen Einfluss Wenn jetzt der Server noch Overcommited wird, dann muss der Server eventuell swappen, was den I/O-Wait auch in die Höhe treiben kann...

Zusammenfassend glaube ich nicht, dass du etwas dafür kannst. Dass Hetzner sich darauf "raus redet", dass am Hostsystem keine Probleme festgestellt werden konnten, dann haben sie vermutlich leider Recht. Ein anderer User Benutzt einfach viele Ressourcen und alle anderen auf diesem Server liegenden Kunden müssen leiden...

EDIT: Deine VM swappt zusätzlich noch. Das solltest du dringend optimieren, da in einer virtualisierten Umgebung swappen mit "schnellen" Lese- und Schreibzugriffen absolut schlecht ist.

[reox]

ja danke, genau den satz hab ich ihnen auch schon gesendet.
ich hab mal ins resuce system gebootet und da passiert das selbe wenn man ein bisserl was macht. Nach 3 Mails mit dem Support glaub ich nicht das sie mir da weiterhelfen, sie sagen Hosting System ist in Ordnung, keine Last dort, das ist ein Software Problem von mir. also interessiert es sie nicht...

Edit: Ich versuch der sache jetzt auf den Grund zu gehen. Zunächst einmal vmstat:

Code: Alles auswählen

reox@host / % vmstat -a 2 100
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free  inact active   si   so    bi    bo   in   cs us sy id wa st
 0  0 195604  18520 203620 213140   19   28  1728   893  366  544  2 13 35 46  4
 0  1 195604  18396 203632 213192    0    0     0   828  149  151  0  2 73 23  2
 0  1 195604  18304 203632 213200    0    0     0  1026  304  175  9 13  0 71  7
 0  1 195604  17900 203636 213212    2    0     8   938  296  273  3 14  0 78  5
 0  1 195604  17932 203628 213240    0    0     6  1168  298  283  2  7  0 85  6
 0  1 195604  17932 203628 213240    0    0     0   962  254  134  0  3  0 88  9
 0  1 195604  17900 203632 213248    0    0     2   966  254  181  0  5  0 88  7
 0  0 195604  18148 203632 213248    0    0     0   458  225  141  0  2 58 34  6
 0  0 195604  18148 203620 213260    0    0     0     0   84  226  1  1 99  0  0
 0  0 195604  18148 203620 213280    0    0     6    72   86  328  1  2 96  2  0
 0  0 195604  18024 203992 213300    0    0   202     0  157  145  1  1 98  1  0
 0  0 195604  17776 204132 213304    0    0    66     0  155  153  0  1 99  1  0
 0  0 195604  17504 204260 213312    0    0    64   466  240  154  0  3 90  5  3
 0  0 195604  17504 204264 213312    0    0     2     0   84  230  1  1 99  0  0
 0  0 195604  17504 204272 213324    0    0    10     0   93  577  0  2 97  1  0
 0  1 195604  17536 204272 213332    0    0     0  1406  269  198  1  8  7 78  7
 0  1 195604  17536 204268 213336    0    0     0  1024  279  299  1  4  0 89  7
 0  1 195604  17508 204268 213336    0    0     0  1142  246  129  0  1  0 92  8
 0  1 195604  17540 204268 213344    0    0     8   994  265  220  0  6  0 86  7
 0  1 195604  17504 204284 213368    0    0    12   954  265  347  1  6  0 85  8
 0  1 195604  17412 204284 213376    0    0     0  1172  275  158  1  5  0 89  6
 0  0 195604  17396 204292 213376    0    0     4   564  247  159  0  4 35 52  9
 0  0 195604  17428 204292 213376    0    0     0    24   59  122  0  1 99  0  0

Man sieht, wenn irgendwo IO ist geht iowait gleich mal hoch, Swap schaut gut aus, auch wenn da immer was drin ist.
Mit perf sieht man allerdings, dass scheinbar viel im Swap gemacht wird:

Code: Alles auswählen

$ perf record -g -a sleep 10
[ perf record: Woken up 7 times to write data ]
[ perf record: Captured and wrote 1.787 MB perf.data (~78074 samples) ]

Die ersten paar Zeilen:

Code: Alles auswählen

+   95.06%    95.06%          swapper  [kernel.kallsyms]    [k] native_safe_halt
+    2.69%     2.69%          swapper  [kernel.kallsyms]    [k] _raw_spin_unlock_irqrestore
+    0.63%     0.63%          swapper  [kernel.kallsyms]    [k] __do_softirq
+    0.28%     0.00%         collectd  [unknown]            [.] 0000000000000000
+    0.07%     0.00%         collectd  libc-2.19.so         [.] mmap64
+    0.07%     0.00%         collectd  libc-2.19.so         [.] munmap
+    0.07%     0.00%         collectd  [unknown]            [.] 0x00007f7541aac000
+    0.06%     0.00%         collectd  libc-2.19.so         [.] 0x00000000000908f0
+    0.06%     0.06%         collectd  [kernel.kallsyms]    [k] _raw_spin_unlock_irqrestore
+    0.05%     0.01%         collectd  libc-2.19.so         [.] 0x00000000000850b0
+    0.05%     0.00%         collectd  [unknown]            [.] 0x00007f7541a88000
+    0.05%     0.02%         collectd  libpthread-2.19.so   [.] __libc_close
+    0.04%     0.04%          swapper  [kernel.kallsyms]    [k] finish_task_switch
+    0.04%     0.00%         collectd  libc-2.19.so         [.] __xstat64
+    0.04%     0.00%         collectd  libc-2.19.so         [.] read
+    0.04%     0.00%           mysqld  mysqld               [.] __io_getevents_0_4
+    0.04%     0.00%         collectd  libpthread-2.19.so   [.] 0x000000000000f1ed
+    0.04%     0.04%          swapper  [kernel.kallsyms]    [k] cp_rx_poll
+    0.03%     0.03%          swapper  [kernel.kallsyms]    [k] tick_nohz_idle_enter

Ist das normal? Ich kann jetzt nicht ganz nachvollziehen was da soviel IO zieht?
output von pidstat -d 1 30: http://debianforum.de/forum/pastebin.ph ... ew&s=38570

kworker/u2:0 ist ja recht aktiv und hat viel delay, ist das vllt der swapper?

[rendegast]

Da scheinen die sekündlichen MB des collectd im swap zu landen.

Eventuell hast Du mit einer Maschine mit mehr RAM (~1GB) keine Probleme mehr.

[reox]

Da scheinen die sekündlichen MB des collectd im swap zu landen.

Eventuell hast Du mit einer Maschine mit mehr RAM (~1GB) keine Probleme mehr.

Nur wieso macht das seit ein paar Tagen ein Problem und vorher nicht?
Mehr RAM ist immer gut, nur in die Maschine bekomm ich keinen rein... Die Kiste sollte eh schon lang migriert worden sein aber bis jetzt war die Zeit dazu noch nicht da...

Ich hab jetzt auch mal ein swapoff -a gemacht und IOWait und Steal sind immer noch genau so hoch... im pidstat seh ich genau das selbe und perf zeigt mir immer noch den swapper ganz oben an?

Edit: Mir ist jetzt noch was aufgefallen: collectd zeigt ja auch die Disk Time per Operation an. Dort war es vorher immer <0.1s und jetzt ist es im avg 0.5s und 32s max! Siehe http://picpaste.com/disktime-hIL54I9l.png
Also kann ich davon ausgehen dass die Disks einfach ur lang brauchen? Hat jemand zufällig ein ähnliches Problem mit Hetzner gehabt? Die sagen ja es ist kein HW defekt...

[rendegast]

Weil sich das Nutzungsprofil einer oder mehrerer der auf dem Host angesiedelten VM geändert hat?

Welcher Prozeß benutzt auf Deiner VM denn den Speicher, sodaß (neuerdings?) ausgelagert wird?
Vielleicht hast Du eine weitere Domain angelegt, die nun zuschlägt?
Der collectd läuft schon immer? ~ 1MB Daten pro Sekunde ist für eine einzige Maschine IMO viel
( Ich denke dabei, daß der nur localhost überwachen soll? ).
Ist der (oder ein anderes Programm) neuerdings vielleicht im debug-Modus?

collectd recomm. default-jre-headless
und - - sugg. - > mysql-server.
beide können Ressourcenfresser sein.
Bei mysql könnte mal tuning-primer, mysqltuner o.ä. ausprobiert werden.
Beende mal collectd -> mysql, apache?

[gbotti]

Weil sich das Nutzungsprofil einer oder mehrerer der auf dem Host angesiedelten VM geändert hat?
...

Das glaube ich allerdings auch. Manche Kunden kündigen und neue kommen hinzu und schon hat man andere Auslastungen. Eventuell wurden auch die Limits für aktivierte VMs pro Server geändert.

Lass mal soetwas wie glances auf dem Server laufen. Da sieht man übersichtlich, was auf dem Server gerade passiert (incl. I/O). Ins Detail gehen kann man dann immernoch.

[reox]

Weil sich das Nutzungsprofil einer oder mehrerer der auf dem Host angesiedelten VM geändert hat?

Naja vermutlich, nur blöd das meine Kiste dadurch unbrauchbar wird...

Welcher Prozeß benutzt auf Deiner VM denn den Speicher, sodaß (neuerdings?) ausgelagert wird?

RAM und Swap verbrauch haben sich seit Jahren nicht geändert. Das System rennt einfach und hatte bisher nie resourcen probleme

Vielleicht hast Du eine weitere Domain angelegt, die nun zuschlägt?

Nein, da hat sich nix geändert. Zugriffe auf den Server schauen aus wie immer

Der collectd läuft schon immer? ~ 1MB Daten pro Sekunde ist für eine einzige Maschine IMO viel
( Ich denke dabei, daß der nur localhost überwachen soll? ).

Ja der rennt seit > 1 Jahr. Der collectd sammelt die Daten von 7 Hosts ein.

Ist der (oder ein anderes Programm) neuerdings vielleicht im debug-Modus?

Nein eigentlich nicht. /var/log/ schaut ruhig aus wie immer...

collectd recomm. default-jre-headless
und - - sugg. - > mysql-server.
beide können Ressourcenfresser sein.

jre ist da keins drauf. Ist auch nix da was java braucht.
Mysql ist benötigt, den hab ich schon versucht so wenig RAM wie möglich einzutrichtern.

Bei mysql könnte mal tuning-primer o.ä. ausprobiert werden.
Beende mal collectd -> mysql, apache?

tuning-primer werd ich mal ausprobierne.
Wenn ich collectd, mysql und nginx stoppe ist auch nix mehr da was auf der kiste rennt (außer vllt der postfix der nur mails an einen anderen smtp server relayed). dH keine IO Zugriffe, keine Load.

[gbotti]

War die VM vor kurzem mal aus / in einer Wartung von Hetzner? Eventuell haben die den Host ausgetauscht, auf dem das ganze lief.

[reox]

War die VM vor kurzem mal aus / in einer Wartung von Hetzner? Eventuell haben die den Host ausgetauscht, auf dem das ganze lief.

Ja am 15.05. gabs eine Wartung, seit 28.05 treten die Probleme auf. Ob sie da den Host getauscht haben weiß ich nicht. Aber laut status dings wurde nur eine Wartung durchgeführt.

Edit: Na bitte, langsam kommts raus (nach langen langen mails...):

am 28.05 ist die Load des IO Subsystem auf dem zugrunde liegenden Hostsystem extrem angestiegen. Daraufhin haben wir das Problem untersucht und mussten mehrere Kunden auf diesem Hostsystem Limitieren.

Scheinbar aber nicht bei mir... blöd nur dass ich trotzdem irgendwo betroffen bin :/

edit2: so sie waren jetzt so freundlich mich mal auf einen anderen Host zu verschieben. Steal-Time gibts jetzt keine mehr, IOWait ist aber immer noch recht hoch aber die Kiste spricht deutlich besser an... Naja vermutlich den mariadb server noch ein bisserl optimieren und irgendwann dann ganz migrieren.

edit3: mhhh jetzt bin ich verwirrt... nachdem sie mich jetzt übersiedelt haben und ich den host mal neu gestartet habe (das hab ich in den letzten tagen sicher sehr oft gemacht...) ist auch die load wieder normal. Unterschied diesmal: Ich hab nicht shutdown -r gemacht sondern -h und danach den host manuell hochgefahren. Kann es sein dass sich deren Hostingumgebung (die verwenden irgendwas mit qemu) aufgehangen hat und mal einen kompletten shutdown brauchte? Obwohl ich hab zwischendurch auch mal den Server heruntergefahren und neu gestartet (aber da war ich noch am alten Host)... Wenn jemand ne gescheite Erklärung hat, bitte. Freu mich aber auch so, dass ich den Server noch ein bisserl verwenden kann

[reox]

Interessant: Ich hab scheinbar einen Bug in derem Hosting System gefunden. Zufällig hab ich das Verhalten reproduziert! Am Freitag hab ich ein Kernelupdate eingespielt und dann neu gestartet. Dabei hat sich die VM scheinbar beim Herunterfahren aufgehängt und ich hab im Hetzner Robot den Reset Knopf gedrückt. Jetzt zeigt mir collectd wieder eine höhere Load und Steal time an! Beim letzten mal konnte ich das Verhalten lösen, indem ich die VM wirklich "aus" geschalten habe und dann neu gestartet. Keine Ahnung was die verwenden, jedenfalls irgendwas mit qemu. Kennt jemand so einen Bug?

edit: komisch. diesmal hat das mit dem ein und ausschalten nix geholfen...

edit2: Hetzner hat heute Wartungsarbeiten an dem System durchgeführt und nach dem Neustart durch ihr system geht auf einmal alles wieder normal... Also ich hab den schweren Verdacht, dass deren Hostingsystem was hat :/