Auto-hébergement : IOwait m’a tuer 1/2 (vmstat, mpstat, atop, pidstat)

« Rien à péter, je suis passé au SSD… » (Bernard M., passionné par la fuite en avant)

IOwait : le mal aimé

« IOwait correspond au temps d’attente du système pour l’écriture ou la lecture de données. Un IOwait de 10 % signifie que 10 % de l’activité du CPU n’est pas destinée à faire des calculs mais à attendre l’exécution d’une opération de lecture/écriture. » (Wikipedia)

Pour afficher le pourcentage d’IOwait, c’est « vmstat » qui s’y colle :

# vmstat 1

procs  -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r  b   swpd   free   buff   cache   si   so    bi    bo   in   cs  us sy id wa
1  0   7680  32200 353264 3111032    0    0 17173 19114  752  536   0  3 72 25
0  1   7680  31124 353376 3114680    0    0 12722 12798  799  569   0  3 75 22
0  1   7680  32916 353396 3114088    0    0  4592  4689  940  552   0  2 76 22
0  1   7680  33208 353432 3117292    0    0 20621 20533  739  592   0  4 77 19
1  1   7680  32096 353448 3119244    0    0 18426 18563  771  592   0  4 77 20

La colonne qui nous intéresse est la dernière, celle qui se nomme « wa ». Plus cette valeur (en pourcentage) est élevée, plus le processeur se tourne les pouces parce que les disques durs sont littéralement à la bourre et n’arrivent pas à suivre la cadence.

Notez que, jusqu’ici tout va bien : « seulement » 20% d’IOwait (mais attendez un peu la suite).

IOwait le retour : petite tentative de démystification

La plupart du temps, quand on cherche rapidement des infos sur le sujet, on tombe surtout sur des personnes plus stressées les unes que les autres : « IOwait à 100%, suis-je maudis ? », « Trop d’IOwait, mon serveur rame à mort. » ou encore « J’ai un load average de fou à cause des IOwait, que faire ? ».

Ceci étant, pas de panique car pour réduire les IOwait, il suffit d’appliquer une des solutions suivantes :

  • diminuer le nombre d’accès disque (Super, t’en as d’autres comme ça ?)
  • augmenter la charge du processeur (Gné ? Keskidi ?)
  • opter pour un processeur poussif (Chérie, fais gaffe, ce type est complètement con…)

Et pourtant, je vous assure que ça marche : installez cpuburn sur un serveur saturé au niveau des IO, lancez autant de burns que le processeur a de coeurs et admirez le résultat.

Félicitations, les IOwait sont maintenant à 0%, n’hésitez pas à demander une augmentation à votre boss…
(Cependant, si le CPU crame à cause de vos conneries, ça va être une autre paire de manche)

J’en vois certains qui froncent les sourcils et c’est bien normal : le nombre d’accès disques n’a pas baissé d’un pouce (et le processeur est à bloc), alors c’est quoi l’embrouille ?

IOwait, la vengeance du come back : voyage au centre de la terre du kernel

Maintenant que l’on sait, au moins intuitivement, que l’indicateur d’IOwait est (plus ou moins) foireux, z’allions voir pourquoi.

L’aventure commence, comme d’hab, avec « /proc » :

# cat /proc/stat

cpu   14471379  41901343  7624436  1631039241  4181730  8954  254946  0  0
cpu0  2230907   8693273   1693928  409959262   1653894  1704  69221   0  0
cpu1  2183699   8699859   1554726  411272346   1392114  3277  69635   0  0
cpu2  4914950   12282210  2201785  405373432   646329   2223  62046   0  0
cpu3  5141820   12226000  2173996  404434200   489391   1749  54042   0  0
[...]

En fonction du noyau utilisé, le nombre de colonnes varie, « man 5 proc » est votre ami :

/proc/stat

kernel/system statistics. Varies with architecture. Common entries include:

cpu  3357 0 4313 1362393

The amount of time, measured in units of USER_HZ (1/100ths of a second on most architectures, use sysconf(_SC_CLK_TCK) to obtain the right value), that the system spent in user mode, user mode with low priority (nice), system mode, and the idle task, respectively. The last value should be USER_HZ times the second entry in the uptime pseudo-file.

In Linux 2.6 this line includes three additional columns: iowait – time waiting for I/O to complete (since 2.5.41); irq – time servicing interrupts (since 2.6.0-test4); softirq – time servicing softirqs (since 2.6.0-test4).

Since Linux 2.6.11, there is an eighth column, steal – stolen time, which is the time spent in other operating systems when running in a virtualized environment

Since Linux 2.6.24, there is a ninth column, guest, which is the time spent running a virtual CPU for guest operating systems under the control of the Linux kernel.

La nobox tournant avec une Debian Squeeze, la version du noyau est 2.6.32-41, le nombre de colonnes est donc égal à 9. Et si on veut savoir à quoi correspondent ces fameuses colonnes, suffit d’appeler Luke à la rescousse :

/*
 * 'kernel_stat.h' contains the definitions needed for doing
 * some kernel statistics (CPU usage, context switches ...),
 * used by rstatd/perfmeter
 */

struct cpu_usage_stat {
  cputime64_t user;
  cputime64_t nice;
  cputime64_t system;
  cputime64_t softirq;
  cputime64_t irq;
  cputime64_t idle;
  cputime64_t iowait;
  cputime64_t steal;
  cputime64_t guest;
};

Bon, ok, vu du noyau, z’avions les différents « états » de chaque processeur. Maintenant, ce qui nous intéresse, c’est de savoir comment iowait est incrémenté.

Et là, même punition, Luke s’y colle à nouveau :

/*
 * Account for idle time.
 * @cputime: the cpu time spent in idle wait
 */

void account_idle_time(cputime_t cputime)
{
  struct cpu_usage_stat *cpustat = &kstat_this_cpu.cpustat;
  cputime64_t cputime64 = cputime_to_cputime64(cputime);
  struct rq *rq = this_rq();

  if (atomic_read(&rq->nr_iowait) > 0)
    cpustat->iowait = cputime64_add(cpustat->iowait, cputime64);
  else
    cpustat->idle = cputime64_add(cpustat->idle, cputime64);
}

En français dans le texte, ça nous donne ceci : si un CPU est « idle » (il n’a rien à faire) et qu’il y a des entrées/sorties en attente, alors le compteur « iowait » est incrémenté, sinon c’est le compteur « idle » qui est incrémenté.

Je vous la refais en plus clair : le compteur « iowait » ne peut être incrémenté que si le CPU est « idle ».

Nan, toujours pas ? Bon, ok : si un CPU est utilisé à 100%, il ne peut pas être « idle » donc l’iowait est forcément nul.

Ce qui nous amène aux conclusions suivantes :

  1. Plus le processeur utilisé est puissant, plus les IOwait seront élevés (à charge égale)
  2. Un serveur « CPU bound » aura des IOwait très faibles même si les disques sont débordés
  3. En résumé, l’indicateur IOwait ne permet pas de savoir à coup sûr si les disques limitent les performances

Super, nous voilà bien avancé. Z’allions donc passer aux choses sérieuses.

IOwait, ze ultimate return même qu’il est pas content : mpstat

Sous Debian, mptstat fait partie du package sysstat : « apt-get install sysstat ».

Si vous vous souvenez du début de l’article, vous aurez constaté que la commande « vmstat » n’indiquait que 20% d’IOwait, pas de quoi fouetter un chat pourrait-on se dire.

Erreur… En fait, le système copiait un dossier vers un autre (« cp -a mon-gros-dossier copie-de-gros-dossier ») et, dans ce cas de figure, ce sont bien les disques qui ralentissent la copie. (On dit alors que le système est « IO bound » ).

Donc, même avec un tout petit processeur (Atom D525 1.8 Ghz : 2 coeurs + hyperthreading), il est nécessaire de surveiller à la loupe chaque coeur :

# mpstat -P ALL 5

Linux 2.6.32-5-amd64 (www.nobox.lan)       02/29/2012      _x86_64_        (4 CPU)

02:02:04 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
02:02:09 PM  all    0.10    0.00    2.62   21.19    0.10    0.30    0.00    0.00   75.70
02:02:09 PM    0    0.40    0.00    6.15   63.10    0.00    0.60    0.00    0.00   29.76
02:02:09 PM    1    0.00    0.00    0.20    0.98    0.20    0.00    0.00    0.00   98.63
02:02:09 PM    2    0.00    0.00    4.13   21.06    0.20    0.39    0.00    0.00   74.21
02:02:09 PM    3    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00

02:02:09 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
02:02:14 PM  all    2.23    0.00    2.67   23.32    0.20    0.35    0.00    0.00   71.24
02:02:14 PM    0    0.60    0.00    6.79   66.67    0.40    1.00    0.00    0.00   24.55
02:02:14 PM    1    8.12    0.00    0.59    0.00    0.20    0.00    0.00    0.00   91.09
02:02:14 PM    2    0.20    0.00    3.36   21.15    0.20    0.59    0.00    0.00   74.51
02:02:14 PM    3    0.00    0.00    0.00    5.88    0.00    0.00    0.00    0.00   94.12

02:02:14 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
02:02:19 PM  all    0.10    0.00    2.73   22.23    0.20    0.25    0.00    0.00   74.49
02:02:19 PM    0    0.20    0.00    7.36   63.02    0.20    0.99    0.00    0.00   28.23
02:02:19 PM    1    0.00    0.00    0.00    1.58    0.40    0.00    0.00    0.00   98.02
02:02:19 PM    2    0.20    0.00    3.74   24.21    0.20    0.20    0.00    0.00   71.46
02:02:19 PM    3    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00

La seconde ligne (CPU all) de chaque bloc nous indique la moyenne des CPU (tout comme vmstat) mais on s’en contrefiche : regardez plutôt les IOwait de chaque coeur et en particulier celui du CPU 0.

Tout de suite c’est moins folichon : il n’y a qu’un seul coeur qui bosse vraiment1 et pas de chance, il passe plus de 60% de son temps à attendre que les IO en cours se terminent. Mais dormez tranquilles braves gens, l’IOwait moyen n’est que de 20%…

Formidable, tout ça c’est très joli sauf que, trop souvent, on ne sait pas à quelle sauce les disques durs sont mangés ni qui est le coupable : il est temps de passer à la chasse à l’homme.

IOwait, randonnée pour un tueur : iotop, atop et pidstat à la rescousse

Se promener dans les bois c’est bien, trouver une proie pour se faire un casse-croute aux fines herbes (et, soyons fou, avec un peu de mayo), c’est quand même mieux : « apt-get install iotop ».

Histoire d’avoir quelque chose à se mettre sous la prémolaire, pour changer, on va lancer une compilation du noyau (« make-kpkg –initrd kernel_image »)

# iotop -ako

Total DISK READ: 0.00 K/s | Total DISK WRITE: 1272.82 K/s
TID   PRIO USER       DISK READ  DISK WRITE  SWAPIN     IO>   COMMAND
762   be/3 root          0.00 K    340.00 K  0.00 %  2.26 %   [jbd2/sda9-8]
777   be/3 root          0.00 K    160.00 K  0.00 %  0.97 %   [jbd2/sda7-8]
782   be/3 root          0.00 K    580.00 K  0.00 %  0.93 %   [jbd2/sda8-8]
772   be/3 root          0.00 K     44.00 K  0.00 %  0.30 %   [jbd2/sda6-8]
4918  be/4 postfix       4.00 K     24.00 K  0.00 %  0.04 %   cleanup -z -t unix -u -c
548   be/4 root          0.00 K    172.00 K  0.00 %  0.02 %   [flush-8:0]
7795  be/4 bdd-mysq      4.00 K     12.00 K  0.00 %  0.02 %   mysqld --basedir=/var/jail/ --datadir=[...]
4919  be/4 postfix       8.00 K     52.00 K  0.00 %  0.02 %   virtual -t unix
7686  be/4 bdd-mysq      0.00 K     92.00 K  0.00 %  0.00 %   mysqld --basedir=/var/jail/ --datadir=[...]
14190 be/4 mails         0.00 K     88.00 K  0.00 %  0.00 %   imap [xxxxxxxx@xxxxxxxxxx.fr xxx.xxx.xx.xxx]
12084 be/4 mails         0.00 K     40.00 K  0.00 %  0.00 %   imap [xxxxxxxx@xxxxxxxxxx.fr xxx.xxx.xx.xxx]
7679  be/4 bdd-mysq      0.00 K      4.00 K  0.00 %  0.00 %   mysqld --basedir=/var/jail/ --datadir=[...]
4377  be/4 root          0.00 K     76.00 K  0.00 %  0.00 %   rsyslogd -c4
31337 be/4 bdd-mysq      0.00 K      0.00 K  0.00 %  0.00 %   mysqld --basedir=/var/jail/ --datadir=[...]
25511 be/4 opendkim      0.00 K     28.00 K  0.00 %  0.00 %   opendkim -x /etc/opendkim.conf -u [...]
19797 be/4 root          0.00 K     12.00 K  0.00 %  0.00 %   vlogger (error log)
19799 be/4 root          0.00 K     32.00 K  0.00 %  0.00 %   vlogger (access log)
7681  be/4 bdd-mysq      0.00 K     80.00 K  0.00 %  0.00 %   mysqld --basedir=/var/jail/ --datadir=[...]
7685  be/4 bdd-mysq      0.00 K      8.00 K  0.00 %  0.00 %   mysqld --basedir=/var/jail/ --datadir=[...]
7933  be/4 root          0.00 K      8.00 K  0.00 %  0.00 %   dovecot -c /etc/dovecot/dovecot.conf
12080 be/4 mails         0.00 K      4.00 K  0.00 %  0.00 %   imap [xxxxxg@xxxxxxxxx.fr xxx.xxx.xx.xxx]
24558 be/4 www-blog      0.00 K     12.00 K  0.00 %  0.00 %   php5-cgi
25512 be/4 opendkim      0.00 K      0.00 K  0.00 %  0.00 %   opendkim -x /etc/opendkim.conf -u [...]

M’ouais… Je sais pas pour vous mais de mon côté, je ne vois rien d’excitant et encore moins les processus nécessaires à la compilation du noyau. Je n’ai pas creusé mais il semblerait qu’iotop n’affiche pas tous les processus effectuant des entrées/sorties. (Si quelqu’un a plus d’infos, je suis preneur !)

Pas grave, essayons autre chose : « apt-get install atop » :

# atop -c -d 5

ATOP - www                2012/02/29  07:53:17                5 seconds elapsed
PRC | sys   0.33s | user   5.15s | #proc    210 | #zombie    0 | #exit     48 |
CPU | sys     10% | user    104% | irq       1% | idle    284% | wait      1% |
cpu | sys      6% | user     87% | irq       0% | idle      7% | cpu002 w  0% |
cpu | sys      2% | user      8% | irq       0% | idle     88% | cpu001 w  1% |
cpu | sys      1% | user      8% | irq       0% | idle     91% | cpu000 w  0% |
cpu | sys      1% | user      1% | irq       0% | idle     97% | cpu003 w  0% |
CPL | avg1   1.09 | avg5    1.38 | avg15   1.19 | csw     1216 | intr    3907 |
MEM | tot    3.9G | free  664.6M | cache   1.9G | buff  652.5M | slab  252.4M |
SWP | tot    4.0G | free    4.0G |              | vmcom   2.2G | vmlim   5.9G |
DSK |         sda | busy      2% | read       9 | write     19 | avio    3 ms |
NET | transport   | tcpi     102 | tcpo     192 | udpi       0 | udpo       0 |
NET | network     | ipi      260 | ipo      350 | ipfrw    158 | deliv    102 |
NET | eth0     0% | pcki     264 | pcko     355 | si  244 Kbps | so  652 Kbps |
NET | ifb0   ---- | pcki     233 | pcko     233 | si  419 Kbps | so  419 Kbps |
NET | ifb2   ---- | pcki     121 | pcko     121 | si  230 Kbps | so  230 Kbps |

PID  DSK COMMAND-LINE                                                  1/3
26991  96% /usr/bin/make -f scripts/Makefile.build obj=arch/x86/kernel
12719   2% rsync --server --sender -vlogDtpre.iLsf --bwlimit=48 . /home/backup/
777     2% jbd2/sda7-8
762     0% jbd2/sda9-8
27030   0% <cc1>
27044   0% <cc1>
27058   0% <cc1>
27072   0% /usr/lib/gcc/x86_64-linux-gnu/4.4.5/cc1 -quiet -nostdinc -Iinclude -
27036   0% <cc1>
27050   0% <cc1>
27035   0% <genksyms>
27064   0% <cc1>
27049   0% <genksyms>
27063   0% <genksyms>
27031   0% <as>
20630   0% atop -d -c 5
27045   0% <as>
27059   0% <as>
12703   0% sshd: root@notty
27024   0% <as --gdwarf2 -Qy --64 -o arch/x86/kernel/entry_64.o /tmp/cc697jEh.>
27039   0% <fixdep>
27053   0% <fixdep>
27067   0% <fixdep>
21223   0% /usr/sbin/munin-node
27073   0% as -Qy --64 -o arch/x86/kernel/.tmp_dumpstack_64.o -
3721    0% imap-login

Ha, enfin ! Notre grand gagnant de la semaine est le processus 26991. Zoomons un peu sur ce mécréant :

# pidstat -d -p 26991 5

Linux 2.6.32-5-amd64 (www.nobox.lan)       02/29/2012      _x86_64_        (4 CPU)

07:54:42 AM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
07:54:47 AM     26991      0.00    315.20    132.80  /usr/bin/make -f scripts/Makefile.build [...]
07:54:52 AM     26991      0.00    197.60     44.80  /usr/bin/make -f scripts/Makefile.build [...]
07:54:57 AM     26991      0.00    185.60     50.40  /usr/bin/make -f scripts/Makefile.build [...]
07:55:02 AM     26991      0.00    251.20     85.60  /usr/bin/make -f scripts/Makefile.build [...]
07:55:07 AM     26991      0.00    204.80     68.00  /usr/bin/make -f scripts/Makefile.build [...]
07:55:12 AM     26991      0.00    109.60      8.80  /usr/bin/make -f scripts/Makefile.build [...]
07:55:17 AM     26991      0.00    132.80      8.00  /usr/bin/make -f scripts/Makefile.build [...]

Voilà, fin de l’histoire : on apprend que « make » se promène tranquillement (dans les bois) tout en écrivant environ 200 Ko/s.

Ceci étant, au lieu de surveiller un seul processus, on peut aussi demander à voir l’activité globale avec « pidstat -d -l 5 » :

# pidstat -d -l 5

08:13:26 AM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
08:13:31 AM       762      0.00     24.51      0.00  jbd2/sda9-8
08:13:31 AM       782      0.00      0.79      0.00  jbd2/sda8-8
08:13:31 AM     19222  13796.84  14118.58      0.00  cp -a gros-backup copie-de-gros-backup

08:13:31 AM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
08:13:36 AM       762      0.00     15.20      0.00  jbd2/sda9-8
08:13:36 AM      1038      0.00      1.60      0.00  /usr/sbin/rsyslogd -c4
08:13:36 AM      5780      0.00      0.80      0.00  /usr/sbin/nmbd -D
08:13:36 AM     16095     32.80     20.80      0.80  /usr/lib/postfix/master
08:13:36 AM     19222  19984.00  19984.00      0.00  cp -a gros-backup copie-de-gros-backup

08:13:36 AM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
08:13:41 AM       762      0.00     13.60      0.00  jbd2/sda9-8
08:13:41 AM       782      0.00      3.20      0.00  jbd2/sda8-8
08:13:41 AM     16095      2.40      0.00      0.00  /usr/lib/postfix/master
08:13:41 AM     19222   8874.40   8993.60      0.00  cp -a gros-backup copie-de-gros-backup

Pour ceux qui viennent juste de comprendre, oui, depuis le début du billet et mis à part la compilation du kernel, tous les exemples sont basés sur « cp -a gros-backup copie-de-gros-backup » (mais, dans la seconde partie, on va varier les plaisirs car sinon c’est pas drôle).

The end ?

Non, suite au prochain numéro : il sera question d’IOPS, d’iostat et de plus si affinités…

A+

  1. ainsi que le CPU 2 mais, sauf erreur, il s’agit du même coeur (Hyperthreading)

Il y a 12 commentaires de gens bizarres, ce sont sûrement des drogués

Oui Jean-Pierre, je souhaite publier un commentaire assassin sur ce blog minable

(Votre adresse email ne sera jamais publiée, divulguée, revendue, broyée, atomisée, etc.)