Solaris mon amour

Petit sujet qui m'a tenu en haleine un petit moment... Pour situer un peu le contexte, nous obtenions des hangs sur plusieurs bases de données Oracle (hang pouvant dépasser l'heure) situés sur plusieurs serveurs et plusieurs baies SAN. La seule alerte obtenue était ce message d'erreur "WARNING: aiowait timed out" dans l'alert.log des bases. Pour le support Oracle bases de données, ce type de message provient d'un problème sur la couche IO du serveur.

Analysons déjà ce que veut dire cette alerte : Oracle effectue une écriture de type KAIO sur un fichier. Le temps de réalisation de cette écriture ne doit pas dépasser 10 minutes sinon Oracle l'indique via ce message d'erreur. Ce qui veut dire qu'entre la demande et la réalisation de cette écriture il y a eu un délai supérieur à 10 minutes... 10 minutes pour réaliser une IO ??? De quoi devenir fou...

Ne disposant d'aucune alerte système, l'investigation commençait difficilement. La première chose à faire dans ce type de cas s'est d'obtenir un maximum de traces pour pouvoir investiguer correctement le problème. Nous avons donc mis en place un script détectant l'anomalie dans l'alert.log des bases. Ce script exécute à la fois un Livecore et une prise de traces via l'outil Guds (je me suis inspiré de l'article suivant).

Je vous passe le fait que le script n'a pas fonctionné tout le temps... Les prises de traces exploitables n'ont absolument rien montré qui pouvaient expliquer notre problème (rien dans les traces iostat, la charge des systèmes était correcte, etc..). Je me suis concentré uniquement sur les IO. Pour ne pas m'éparpiller entre les différents serveurs, baies, bases, j'ai décidé d'analyser le problème sur une seule base (un serveur et une baie mutualisés).

J'ai écrit un petit script Dtrace me permettant de calculer le temps passé pour chaque appel KAIO. Ceci m'a permis de vérifier, cette latence de 10 minutes que la base de données Oracle indiquée.

# cat ./aiowait.d
#!/usr/sbin/dtrace -qs

 fbt:kaio:aiowait:entry
/execname == "oracle"/
{
        self->ts = timestamp;
}

fbt:kaio:aiowait:return
/self->ts && (timestamp - self->ts)/1000000 > 60/
{
        self->duration = (timestamp - self->ts)/1000000;
        printf("%Y %20s %8d %12d %12d\n", walltimestamp, execname, pid, tid, self->duration);
        self->duration = 0;
}

# ./aiowait.d
[...]
2011 Jul 19 23:45:40       oracle    14583       1        67
2011 Jul 19 23:45:39       oracle    14583       1        89
2011 Jul 19 23:45:40       oracle    14583       1        61
2011 Jul 19 23:45:40       oracle      714       1       127
[...]
2011 Jul 19 23:58:39       oracle    14583       1    600100
2011 Jul 19 23:58:39       oracle    14583       1      3014
2011 Jul 19 23:58:38       oracle    14583       1       908
2011 Jul 19 23:58:39       oracle    14583       1     36730 
[...] 

Si vous interprétez correctement cet output, on remarque des temps de latence entre l'entrée et la sortie de la fonction aiowait supérieurs à 60 millisecondes pour la plupart des KAIO mais surtout une latence supérieur à 10 minutes. Incroyable voilà ce que je me suis dis... Une latence de 10 minutes pour une écriture... Oracle dit vrai !!!

Ce qu'il faut bien comprendre c'est qu'une demande de lecture et / ou écriture se décompose en plusieurs couches dans le système. Une couche logique (opération vfs, opération vnode, file system, cache) et ensuite une couche physique. Suite à ma première constatation j'ai d'abord vérifié la couche physique (c'est la plus facile à analyser). Pour ce faire, j'ai utilisé le petit script Dtrace suivant.

# cat ./fsiolantency.d
#!/usr/sbin/dtrace -Cs

#pragma D option quiet
#pragma D option defaultargs

dtrace:::BEGIN
{
#if defined(ZONENAME)
        uzone = ZONENAME;
#else
        uzone = "";
#endif

#if defined(EXECNAME)
        uexec = EXECNAME;
#else
        uexec = "";
#endif

#define PROBE_SWITCH \
        ((uzone == "" || uzone == zonename) && \
                (uexec == "" || uexec == execname))
}

io:::start
/PROBE_SWITCH/
{
        start[arg0] = timestamp;
}

io:::done
/start[arg0]/
{
        @time["disk I/O latency (ns)", args[2]->fi_mount, args[0]->b_flags & B_READ ? "R" : "W"] = quantize(timestamp - start[arg0]);
        start[arg0] = 0;
}

# ./fsiolantency.d -D ZONENAME='"zone1'" -D EXECNAME='"oracle"'
^C 

disk I/O latency (ns)     /zones/zone01/root/ZONE01/oradata02         W                                              
           value  ------------- Distribution ------------- count
         1048576 |                                         0
         2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           1112
         4194304 |@@@@@@@@@@                               104
         8388608 |                                         0

 disk I/O latency (ns)    /zones/zone01/root/ZONE01/oradata03         R                                             
           value  ------------- Distribution ------------- count
          131072 |                                         0
          262144 |@@@@@@@@@@@@@@@@@@@                      2408
          524288 |@@                                       231
         1048576 |@@                                       230
         2097152 |                                         0
         4194304 |@@@@@                                    1023
         8388608 |@@@@@@@@@@@@                             1940
        16777216 |                                         0

 disk I/O latency (ns)    /zones/zone01/root/ZONE01/oraredo01         W                                             
           value  ------------- Distribution ------------- count
         1048576 |                                         0
         2097152 |@@@@@@@@@@@@@@@@@@@@@@@                  2013
         4194304 |@@@@@@@@@@@@@@@@@                        1870
         8388608 |                                         0

 disk I/O latency (ns)    /zones/zone01/root/ZONE01/oradata01         R                                              
           value  ------------- Distribution ------------- count
          131072 |                                         0
          262144 |@@@@@@@                                  498
          524288 |@@                                       156
         1048576 |                                         0
         2097152 |                                         0
         4194304 |@@@@@@@@@@@@                             750
         8388608 |@@@@@@@@@@@@@@@@@@                       1134
        16777216 |@@                                       134
        33554432 |                                         0

 disk I/O latency (ns)    <none>                                      R                                              
           value  ------------- Distribution ------------- count
          131072 |                                         0
          262144 |@@@@@@@@@@@@@@@                          158
          524288 |@@                                       27
         1048576 |                                         0
         2097152 |                                         0
         4194304 |@@@@@@@@@@@@@                            139
         8388608 |@@@@@@@@@@@                              114
        16777216 |                                         0

 disk I/O latency (ns)    /zones/zone01/root/ZONE01/oradata01         W                                              
          value  ------------- Distribution ------------- count
          524288 |                                         0
         1048576 |@@@@@@@                                  44
         2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           202
         4194304 |@@@                                      519
         8388608 |                                         153
        16777216 |                                         0

 disk I/O latency (ns)    /zones/zone01/root/ZONE01/oradata03         W                                             
           value  ------------- Distribution ------------- count
          524288 |                                         0
         1048576 |@@@@@@@                                  968
         2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           2309
         4194304 |@@@                                      528
         8388608 |                                         42
        16777216 |                                         0

 disk I/O latency (ns)    <none>                                      W                                             
           value  ------------- Distribution ------------- count
          524288 |                                         0
         1048576 |@@@@@@@@@@@                              913
         2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@             13482
         4194304 |@                                        418
         8388608 |                                         25
        16777216 |                                         0

Les résultats obtenus étaient correctes. Les IO physiques (lecture et écriture) se déroulaient dans des temps très convenables. Le problème ne se situait donc pas sur les baies. Donc dans le système... Mais où ? Je me suis donc plonger dans la lecture de "Solaris Internals" et "Configuring and Tuning Databases on the Solaris Platform" pour compendre ce qui se passait entre l'écriture demandée par Oracle (usermode) et l'écriture sur le device (IO physique). J'imaginais qu'il y avait un lock mais lequel ?

Une chose s'est révélée intéressante : les "Reader/Writer" locks (voir chapitre 17.6 dans "Solaris Internals"). Un seul thread à la fois peut accéder en écriture à un fichier. Voilà quelque chose de fort intéressant... J'ai donc écrit un petit script Dtrace en utilisant la probe lockstat (spécifiquement rw-block) pour obtenir les temps d'attente pour ce type de lock.

# cat rwlock.d
#!/usr/sbin/dtrace -Cs

#pragma D option quiet

lockstat::rw_enter:rw-block
/execname == "oracle" && arg1 > 1000000000 && zonename == "zone01"/
{
          printf("%Y %20s %8d %12d %12d %12d",walltimestamp,execname,pid,tid,arg1,arg2);
}

# ./rwlock.d
2011 Jul 21 00:01:13     oracle    21289       223   4238043920        0
2011 Jul 21 00:01:13     oracle    21289        88   4628837600        0
2011 Jul 21 00:01:13     oracle    21289       212   4351952245        0
2011 Jul 21 00:01:13     oracle    21289       238   4929624480        0
[...]
2011 Jul 21 00:01:18     oracle    21289       208   8635095680        0
[...]
2011 Jul 21 00:01:20     oracle    21289       195  12103783200        0
2011 Jul 21 00:01:20     oracle    21289       235  11806798240        0
2011 Jul 21 00:01:20     oracle    21289        43  11860924640        0
^C
2011 Jul 21 00:01:21     oracle    21289       226  13598520640        0
2011 Jul 21 00:01:21     oracle    21289        26  13602492640        0
2011 Jul 21 00:01:21     oracle    21289        46  13493121680        0
2011 Jul 21 00:01:21     oracle    21289        56  13310176960        0
2011 Jul 21 00:01:21     oracle    21289        64  13236565680        0
2011 Jul 21 00:01:21     oracle    21289        73  13197836080        0
2011 Jul 21 00:01:21     oracle    21289        75  13198641840        0
2011 Jul 21 00:01:21     oracle    21289        76  13199566320        0
2011 Jul 21 00:01:21     oracle    21289        71  12498137520        0

J'obtenais des "Writer" Locks supérieurs à 12 secondes !!! J'ai donc décicidé de faire tourner ces deux petits scripts (rwlock.d et aiowait.d) en même temps afin de voir si mes soupçons étaient corrects. Et bingo... Lors d'un message "WARNING: aiowait timed out", la somme des temps pour les "Writer Locks" était supérieur à 10 minutes (certains "Writer Lock" dépassaient 1 minute).

Mon gros soucis avec cette analyse était la suivante. J'avais la conviction que le soucis se situer sur ce type de lock mais impossible de l'affirmer. En effet, l'analyse s'avère exact si et seulement si il s'agit du même fichier qui est accéder. J'ai donc demandé au support Oracle système de me fournir un script Dtrace pouvant m'indiquer à la fois le type de lock "Reader/Writer", le temps de lock mais surtout le nom du fichier sur lequel le lock attendait. Le script fournit par le support - un grand Merci à Alexandre et Alain - nous a permis de mettre en relation l'alerte Oracle "WARNING: aiowait timed out" avec le nom du fichier (le plus souvent les fichiers undo et les tempfiles). 

Résumons la situation : des temps IO vu d'Oracle dépassant les 10 minutes, des IO physiques inférieurs à 30 millisecondes, des "Writers Locks" dépensant la minutes... ???!!! Lors d'une demande d'écriture sur un fichier, le système vérifie si le fichier est déjà accédé, si celui-ci est accédé alors il place cette demande dans une queue de type turnstile. Une fois la ressource disponible (ici le fichier) l'écriture physique peut s'effectuer. Lors d'une forte activité d'écriture sur un fichier, toutes les demandes s'empilent dans la queue. La dernière requête de la queue prendra donc un certains à se réaliser (c'est une FIFO). Il s'agit du mode fonctionnement POSIX d'un système de fichiers (UFS, VxFS, TMPFS).

Comment contourner ce problème ? Plusieurs solutions possibles : l'une d'elles est d'augmenter le nombre de fichiers (pour nous il s'agissait des fichiers undo et tempfiles). En augmentant le nombre de fichiers on augmente le nombre de queues (donc moins de locks par queue). L'autre solution consite à passer les systèmes de fichiers en accès directio. En effet le mode directio supprime les "Reader/Writer" locks : la couche applicative se débrouille pour gérer les accès concurents aux fichiers. Les bases de données Oracle savent très bien le faire (quelques infos dans cette article). Mais voilà, le passage en directio supprime certes ces locks mais supprime aussi l'effect du "cache filesystem". Toutes les lectures s'effectueront directement sur les disques physiques (pour pallier à ce problème il faut augmenter impérativement les SGA de vos bases de données).

Un sacré problème réglé...

P.S. : c'est pas évident d'être clair, n'hésitez pas à me demander des informations supplémentaires sur ces aspects. Je tiens à le souligner encore mais sans un outil comme Dtrace (n'oublions pas mdb) ce type d'analyse est pratiquement impossible. Un grand merci au support Oracle (base de données et système) pour toute l'aide apporté à la résolution de ce problème.