Overblog
Suivre ce blog Administration + Créer mon blog
24 octobre 2011 1 24 /10 /octobre /2011 20:05

fork: Resource temporarily unavailable

 

Petite anlyse d'un problème survenu sur un serveur Solaris 10. Le contexte était le suivant : dysfonctionnement applicatif, impossible de se connecter au serveur bien que la couche IP semblait active.

 

Généralement je me pose pas de question dans ce genre de cas : je force une prise de dump (afin d'analyser le problème) et reboote le serveur (minimiser l'impact utilisateurs).

 

Avant de se lancer dans l'analyse du core, essayons de comprendre ce message. Le système tente de créer de nouveaux "processus" mais n'y parvient pas par manque de ressource.

 

Questions :

 

- Quelles sont les ressources nécessaires pour la création d'un nouveau processus ?

- Quelles sont les limites possibles ?

 

Un petit tour dans notre librairie : Solaris Internals et plus spécifiquement le chapitre 2 "The Solaris Process Model". La lecture est un peu longue mais très enrichissante... Bref, en vulgarisant beaucoup (désolé pour les puristes), il existe deux limites possibles : une est appliquée au Process, l'autre au Thread.

 

Le système Solaris est capable de créer un nombre déterminé de processus et de threads. Les deux limites Process et Thread sont utilisées à cet effet. La 1er ressource nécessaire à la création d'un processus (ou d'un thread) reste la mémoire (notons cela dans le coin de notre tête). 

 

Revenons un peu à notre crash... Qu'avons nous ?

 

> ::showrev
Hostname: myserver
Release: 5.10
Kernel architecture: sun4u
Application architecture: sparcv9
Kernel version: SunOS 5.10 sun4u Generic_142909-17
Platform: SUNW,SPARC-Enterprise

 

 

Vérifions le nombre de process et threads actif sur le serveur au moment du crash

 

> ::walk proc !wc -l
   14041

> ::walk thread !wc -l
   63017

 

Les limites ne sont pas atteintes, cependant le nombre de threads semble assez important. Une autre façon de savoir si le nombre de process a été atteinte est d'utiliser la variable suivante :

 

> fork_fail_pending/D
fork_fail_pending:
fork_fail_pending:       0  

 

 

Le problème semble provenir d'une allocation mémoire. Deux cas possible, le serveur ne disposait plus de mémoire virtuelle ou la table mémoire d'allocation des process (ou thread) est pleine. Le 1er cas ne semble pas possible (on aurait saturé la totalité de la mémoire virtuelle, ce qui provoque du swap... lire ce petit article). Intéressons nous au 2ème cas. L'allocation mémoire dans la table kernel concerne les threads.

 

> ::kmastat
cache                        buf    buf    buf    memory     alloc alloc
name                        size in use  total    in use   succeed  fail
------------------------- ------ ------ ------ --------- --------- -----
kmem_magazine_1               16  10662  27940    450560    244998     0
kmem_magazine_3               32   5701  32258   1040384    498170     0
kmem_magazine_7               64   5318  23495   1515520    436661     0
kmem_magazine_15             128   4544  24822   3227648    454626     0

[...]

segkp_16384                16384      0      0         0         0     0
segkp_24576                24576      0      0         0         0     0
segkp_32768                32768  63080  63080 2067005440  14589775 1429945523
segkp_40960                40960      0      0         0         0     0
[...]

------------------------- ------ ------ ------ --------- --------- -----
Total [static]                                 110821376 1078194013     0
Total [hat_memload]                            483278848 1120195850     0
[...]
Total [umem_np]                                 12320768    556204     0
Total [segkp]                                  2146041856 186166476 1429945523
Total [zfs_file_data_buf]                      3911852032   9675276     0

[...]

 

 

Nous avons plusieurs demandes d'allocation en erreur pour le cache segkp. La taille de ce cache semble trop petite par rapport au nombre important de threads que le système gére. Pour résoudre ce problème il est nécessaire d'augmenter la taille de ce cache (un peu de lecture).

 

Conseil, si vous utilisez un serveur fortement mutualisé (bcp de process et threads), n'oublie pas d'allouer un peu plus de mémoire au kernel (notamment la table segkp).

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
20 août 2011 6 20 /08 /août /2011 10:05

Analyse des alertes Oracle "WARNING: aiowait timed out"

 

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.

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
17 août 2011 3 17 /08 /août /2011 20:26

Exemple d'un "Hard Swapping"

 

Même si je ne pratique pas depuis longtemps dans le monde Unix (un peu plus de 10 ans) c'est l'une des 1er fois où je rencontre un cas de "Hard Swapping" sous Solaris. Situons un peu le contexte : depuis plusieurs jours un serveur sous Solaris 10 se retrouvait pratiquement tous les jours sur le prompt avec aucun message d'erreur (console et système). Malgrè la mise à jour corrective de l'OBP, rien n'y faisait, le serveur continuait à se retrouver continuellement sur le prompt. En intervenant par hasard sur un autre problème, j'ai intercepté une alerte provenant de ce fameux serveur "serveur non joignable".

 

L'examen via le déport m'indiquait aucune anomalie : alimentation, aucun message à la console, aucune interruption hard. La console répondait bizarrement aux commandes mais aucune réponse du système... Hop un petit break et une génération d'un petit core au passage histoire d'analyser un peu tout ça. Mon expérience dans ce type de cas m'oriente généralement vers un problème de "Swapping".

 

Je commence par vérifier ce que contenait mes queues CPU lors du crash...


# mdb -k 0
>
> ::cpuinfo
ID ADDR        FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD      PROC
  0 30003990000  1d    7    0  98  yes    no t-134  2a100781ca0 pageout
  1 30003994000  1d    2    6  -1   no    no t-0    2a100629ca0 (idle)
  2 30003998000  1d    1    0  -1   no    no t-0    2a100679ca0 (idle)
  3 0000183a628  1b    7    0 165  yes    no t-11   2a100047ca0 sched

 

C'est vraiment intéressant cette fonction pageout()... Cela confirme mon soupçon sur un problème provoqué par du "swapping"


> 30003990000::cpuinfo -v

 ID ADDR        FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD      PROC
  0 30003990000  1d    7    0  98  yes    no t-134  2a100781ca0 pageout
                  |    |
       RUNNING <--+    +-->  PRI THREAD      PROC
      QUIESCED                60 30008786380 cron
        EXISTS                60 30004861c20 aws_orb
        ENABLE                60 3000e307840 nsrexecd
                              60 300052d41c0 java 
                              60 3000539d0c0 inetd
                              60 300052d8200 svc.configd
                              60 30007789ae0 dataserver

 

Regardons de plus près ce que la cpu "id 3" tentait de faire

 

> 0000183a628::cpuinfo -v
ID ADDR        FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD      PROC
  3 0000183a628  1b    7    0 165  yes    no t-11   2a100047ca0 sched
                  |    |    |
       RUNNING <--+    |    +--> PIL THREAD
         READY         |           6 2a100047ca0
        EXISTS         |           - 2a100751ca0 pageout
        ENABLE         |
                       +-->  PRI THREAD      PROC
                              60 30008784360 cron
                              60 30007164760 adclient
                              60 30007fa1c40 dataserver
                              60 30005128400 python
                              60 3000dcc8b00 java
                              60 3000d7b9280 aws_sadmin
                              60 30003b563e0 naviagent

> 2a100751ca0::threadlist -v
            ADDR             PROC              LWP CLS PRI            WCHAN000002a100751ca0      60027254468                0   0  97                0

  PC: ktl0+0x48    THREAD: pageout_scanner()
  stack pointer for thread 2a100751ca0: 2a100750f91
  [ 000002a100750f91 ktl0+0x48() ]
    checkpage+0x78()
    pageout_scanner+0x3f4()
    thread_start+4()

 

Le "Page scanner" est bien en cours de fonctionnement (voir sched.c). Vérifions un peu les valeurs liées aux "Swapping".


> avefree/E
avefree:
avefree:          2871
> minfree/E
minfree:
minfree:          8029
> freemem/E
freemem:
freemem:          2888
> needfree/E
needfree:
needfree:        18322
> freemem_wait/D
freemem_wait:
freemem_wait:      426

 

Pour le coup le rapport avefree < minfree est avéré... confirmation de mon hypothèse... On ne dispose plus beaucoup de pages libre (freemem) et le nombre de thread en attente est de 426 (freemem_wait). Voir dans le code vm_page.c pour les explications.

 

Nous sommes donc en présence d'un cas de "Hard Swapping". Ce mode est beaucoup plus agressif que le "Soft Swapping". Une fois activé l'algorithme peut décider de unloader un module kernel non utilisé pour libérer des pages mémoires. Ce qui explique que mon serveur ne répondait plus...

 

> ::modinfo !grep ip
 58         7b600000   144040   1 ip (IP STREAMS driver 1.47)
 82         7bb61cd8      590   1 ip6 (IP6 STREAMS driver 1.9)
146                0        0   0 ipsecesp (?)
147                0        0   0 ipsecah (?)
200                0        0   0 ippctl (?)
223         7afcc000     83a8   1 fcip (SunFC FCIP v20091105-1.50)
242         7aa42000    2dd90   1 ipf (IP Filter: v4.1.9)
253         7b7f8d38     1300   1 ipc (common ipc code)

 

Pour les habitués il manque le "module ip". Petite vérification sur le serveur en fonctionnement


# modinfo | grep ip
58 7b600000 144040   3   1  ip (IP STREAMS driver 1.47)
58 7b600000 144040   -   1  ip (IP STREAMS module 1.47)
[. . .] 

 

J'ai réussi à mettre en pratique un cas rare que j'avais étudié il y a déjà quelques temps. Faut dire des problèmes de "Swapping" sur les infras actuelles sont de plus en plus rare. Pour les mordus de lecture, je vous renvois au chapitre 10 de "Solaris Internals".

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
14 août 2011 7 14 /08 /août /2011 15:32

Comprendre et vérifier l'utilisation du cache filesystem

 

Je vais m'intéresser ici uniquement au cache filesystem, pour ceux qui souhaitent comprendre le fonctionnement globale de la mémoire je vous renvoie à la présentation de William Roche effectuée lors d'une des nombreuses soirée Guses. Il ne s'agit pas ici d'expliquer précisemment le fonctionnement de ce cache, pour les puristes je vous renvois aux excellents ouvrages "Solaris Internals" et "Solaris Performance and tools".

 

Le cache filesystem a été implémenté comme une partie intégrante de la mémoire virtuelle depuis la version de SunOS 4.0. Il permet d'utiliser dynamiquement l'ensemble de la mémoire disponible pour cacher les fichiers en mémoire RAM (découper en page). L'intérêt est important : éliminer les IO physiques. Le cache filesystem s'intégre automatiquement quelque soit le système de fichiers utilisé (fonctionne avec UFS, NFS, VxFS, a noter qu'avec ZFS son fonctionnement apporte son petit lot de différences).

 

Pour visulaliser l'utilisation de la mémoire j'utilise souvent la macro memstat. Cette macro permet de cerner rapidement comment la mémoire RAM du système Solaris est découpée.

 

# mdb -k
Loading modules: [ unix genunix specfs dtrace zfs sd pcisch ssd fcp fctl mpt emlxs ip hook neti mpt_sas sctp arp usba s1394 wrsm nca lofs md cpc random crypto wrsmd fcip logindmux ptm ufs sppp nfs ipc ]

> ::memstat

Page Summary                Pages                MB  %Tot
------------     ----------------  ----------------  ----
Kernel                     832396              6503    8%
ZFS File Data             2106285             16455   20%
Anon                      4334797             33865   42%
Exec and libs               24420               190    0%
Page cache                 342936              2679    3%
Free (cachelist)          2563444             20026   25%
Free (freelist)             88904               694    1% 

Total                    10293182             80415
Physical                 10269991             80234


Le cache filesystem est composé des deux éléments suivants "Page cache" et "Free (cachelist)". Pour simplifier, la catégorie "Page cache" inclue la portion "segmap" (inclus aussi les fichiers mappés). Quand un fichier est accédé (lecture ou écriture) celui-ci est placé dans la portion "segmap". Le fichier peut être par la suite placé dans la portion "Free (cachelist)" (pour plus de détails techniques sur le fonctionnement de segmap et du cache filesystem je vous renvois au chapitre 14.7 et 14.8 dans "Solaris Internals").

 

De nombreux outils inclus dans le système nous permettent de vérifier l'activité du cache filesystem. La commande vmstat fait partie de ces outils. La colonne "re" indique le nombre de page transféré entre la portion "Free (cachelist)" et la portion "segmap". La colonne "fpi" indique le nombre de lecture (en kb) de "fichiers réguliers" entre le disque et le cache filesystem (pour plus d'explication n'oublier pas de lire le manuel de la commande).     

 

# vmstat -p 3 5
     memory           page          executable      anonymous      filesystem
   swap  free  re  mf  fr  de  sr  epi  epo  epf  api  apo  apf  fpi  fpo  fpf
76804104 18206496 5744 5392 218 0 0 105  0    0    0    0    0 45998 218  218
83421912 26518528 868 223 0 0  0    0    0    0    0    0    0 6315    0    0
83421728 26526200 1624 503 8 0 0    0    0    0    0    0    0 6647    8    8
83423152 26536064 1159 458 0 0 0    0    0    0    0    0    0 5539    0    0
83421648 26538952 1002 1333 0 0 0   0    0    0    0    0    0 6738    0    0

 

Avec Dtrace il est possible d'en savoir un peu plus. Par exemple je peux savoir qui provoque cette activité de paging disque vers mémoire, qui provoque une activité "Free (cachelist)" vers "Page cache", etc... Les deux commandes suivantes nous le montre rapidement.

 

# dtrace -n 'vminfo:::fspgin { @[execname] = count(); }'
dtrace: description 'vminfo:::fspgin ' matched 1 probe
^C 

  rsync            20

# dtrace -n 'vminfo:genunix::pgrec { @[execname] = count(); }'
dtrace: description 'vminfo:genunix::pgrec ' matched 1 probe
^C 

  oracle          108 

 

Ce qui est surtout intéressant c'est de calculer le bénéfice qu'offre le cache filesystem. Je calcule ici le nombre d'opérations de lecture dans le cache et sur le disque. Pour ce faire j'utilise comme toujours Dtrace. Deux probes sont nécessaires : la probe "fsinfo" (activités du filesystem) et la probe "io" (activités des io physiques). Petite spécificité du script, je recherche uniquement des opérations des bases de données Oracles (chaque base étant dans une zone Solaris).

 

# cat cacheread.d

#!/usr/sbin/dtrace -s
#pragma D option quiet

dtrace:::BEGIN
{
        trace("Tracing for 60 minutes... Ctrl-C to quit.\n\n");
}

fsinfo:::read
/execname == "oracle"/
{
        @io["logical", zonename] = count();
}

io:::start
/args[0]->b_flags & B_READ && execname == "oracle"/
{
        @io["physical", zonename] = count();
}

profile:::tick-60m
{
        printa(" %-10s %-10s %10@d\n", @io);
        trunc(@io);
        exit(0);
}


# ./cacheread.d
Tracing for 60 minutes... Ctrl-C to quit.
^C
  physical      zone10             2022
  logical       zone10            45419 

 

Le résultat parle de lui même. 95% des lectures se sont effectuées en mémoire et non sur disque. L'accès à la mémoire étant nettement plus rapide que l'accès à un disque, le bénéficie est estimable (cela dépend en grande partie du type de workload de nos applications, je l'accorde). Cependant tout n'est pas si simple que cela... Dans un prochain article nous verrons un cas où son activation pose de réel problème.

 

P.S : Il existe une multitude de scripts Dtrace permettant de mesurer l'efficacité du cache filesystem : par exemple readtype.d, writetype.d, etc...

 

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
8 août 2011 1 08 /08 /août /2011 21:37

Vérifier le mode d'accès directio de vos fichiers

 

Comment vérifier le mode d'accès directio sur nos fichiers ? Confronté récemment à cette question, je vous livre ici une des manières d'y répondre. A noter l'utilisation d'UFS dans mon cas.

 

Il existe deux implémentations du directio pour UFS :

  • Option de montage du système de fichiers
  • Modification du flag de l'inode pour un fichier ouvert

La 1er méthode est assez simple à vérifier alors que la 2ème si vous n'êtes pas en train de vérifier l'appel ioctl() au moment ou celui-ci se produit il est plus difficile de le vérifier (je vous renvois à l'article suivant pour plus de précision). Reste la possibilité d'utiliser dtrace mais encore faut'il que le fichier soit accéder pour le savoir.

 

Bon passons un peu aux manipulations... Avec dtrace on peut utiliser la ligne suivante et attendre (longtemps... très longtemps)


# dtrace -qn fbt:ufs:directio_start:entry { printf("%d %s", pid, stringof(args[1]-›i_vnode-›v_path)); }
21350 /zones/zone01/root/ZONE01/oradata13/XXXG02/xxxg02_crontrol_02.ctl
21350 /zones/zone01/root/ZONE01/oradata13/XXXG02/xxxg02_crontrol_01.ctl
^C


Ici le process 21350 accède aux fichiers control* avec le mode d'accès directio. Vérifions maintenant dans le kernel ce qui s'y passe vraiment.

 

# sudo mdb -k
Loading modules: [ unix genunix specfs dtrace zfs sd pcisch ssd fcp fctl mpt emlxs ip mpt_sas hook neti sctp arp usba s1394 wrsm nca lofs md cpc wrsmd fcip random crypto logindmux ptm ufs sppp nfs ipc ]
> 0t21350::pid2proc
3021bbcd3e0
 3021bbcd3e0::pfiles !grep control
 256  REG 000003009dacc2c0 /zones/zone01/root/ZONE01/oradata13/XXXG02/xxxg02_control_01.ctl
 257  REG 000003006520e300 /zones/zone01/root/ZONE01/oradata13/XXXG02/xxxg02_control_02.ctl

> 000003009dacc2c0::print vnode_t

{
    v_lock = {
        _opaque = [ 0 ]
    }
    v_flag = 0x10000
    v_count = 0x5
    v_data = 0x30127d14d10
    v_vfsp = 0x60063e12040
    v_stream = 0
    v_type = 1 (VREG)
    v_rdev = 0xffffffffffffffff
    v_vfsmountedhere = 0
    v_op = 0x6006883ed80
    v_pages = 0
    v_npages = 0
    v_msnpages = 0
    v_scanfront = 0
    v_scanback = 0
    v_filocks = 0x3002740bd40
    v_shrlocks = 0
    v_nbllock = {
        _opaque = [ 0 ]
    }
    v_cv = {
        _opaque = 0
    }
    v_locality = 0
    v_femhead = 0
    v_path = 0x300adca6020 "/zones/zone01/root/ZONE01/oradata13/XXXG02/xxxg02_control_01.ctl"
    v_rdcnt = 0x4
    v_wrcnt = 0x4
    v_mmap_read = 0
    v_mmap_write = 0
    v_mpssdata = 0
    v_scantime = 0
    v_mset = 0
    v_msflags = 0
    v_msnext = 0                     
    v_msprev = 0
    v_mslock = {
        _opaque = [ 0 ]
    }
}

 

Comme évoqué plus haut, il y a deux implémentations possibles pour le directio. Soit le montage du système de fichiers posséde l'option directio (man mount_ufs), soit le flag de l'inode (voir ufs_inode.h).

 

Vérifions l'une et l'autre dans le kernel :

 

> 0x60063e12040::fsinfo -v
            VFSP FS              MOUNT
0000060063e12040 ufs             /zones/zone01/root/ZONE01/oradata13
              R: /dev/vx/dsk/zone01/oradata13
              O: rw,intr,largefiles,logging,noquota,xattr,nodfratime,onerror=panic

 

Nous voyons dans les options de montage qu'il ne sagit pas de la 1er méthode d'implémentation. Voyons la suivante :

 

> 0x30127d14d10::print inode_t !grep i_flag
    i_flag = 0x4260

 

Le flag pour cette inode possède bien le masque directio (0x4000). Suite à l'ouverture du fichier open(), l'application (ici une base de données Oracle) a modifié le mode d'accès directio par l'appel ioctl().

 

A vous de jouer pour vérifier directement dans le kernel, le mode d'accès directio à tous vos fichiers. Dans un prochain article je reviendrai sur ce mode (son fonctionnement, pourquoi l'utiliser, exemple d'un problème de performance).

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
16 octobre 2010 6 16 /10 /octobre /2010 17:54

Forte consommation du process fmd

 

C'est un problème que j'ai rencontré sous Solaris 10x86 sur du matériel Oracle Galaxy (x4100, x4150, ...). Les serveurs hébergent différentes applications type RMDS (Application pour les transactions boursières). Mais voilà que de temps en temps, le démon système fmd occupait tout les ressources CPU. Cela provoquait bien évidemment des latences applicatives. La solution semblait évidante : un bug avec le démon fmd. Et pourtant...

 

fmd est le démon pour le gestionnaire d'erreur de Solaris 10 nommé Solaris Fault Manager. Pour simplifier (désolé pour les puristes), il permet la détection de pannes hardware ou software. Il introduit aussi des composants d'autorétablissements. Désactiver le démon résolvait le problème mais la suppression de cette fonctionnalité n'était pas la meilleur solution (à mon sens).

 

Bizarrement le support SUN n'a pas été d'un très grand secours. Et la seule solution proposée était de désactiver le démon... La persévérance associée à un excellant outil comme Dtrace m'a permis de comprendre l'origine du problème et de le résoudre définitivement.

 

On commence par le début...

 

# vmstat 3
  kthr      memory            page            disk          faults      cpu
 r b w   swap   free  re  mf pi po fr de sr f0 s0 s1 s2   in   sy   cs us sy id
 0 0 0 8797840 4599880 10  20  0  0  0  0 26 -0  1  2  5  306  185  226  0  2 98
 0 0 0 8787000 4557880  6  17  0  0  0  0  0  0  0  0  0  309  114  152  0  1 99
 0 0 0 8786200 4557360  2   2  0  0  0  0  0  0  0  0  0  308  104  152  0  1 99
 0 0 0 8786200 4557360  2   2  0  0  0  0  0  0  0  0  0  305  102  148  0  1 99
 0 0 0 8786200 4557360  2   2  0  0  0  0  0  0  0  0  0  308  104  150  0  1 99
 0 0 0 8786200 4557360  2   2  0  0  0  0  0  0  0  0  0  305  102  146  0  1 99
[...]

 

Bizarrement la charge CPU m'indiquait absolument rien. L'application réceptionne des flux réseaux, effectue une opération atomique avec les données reçues et renvoie le tout. Les opérations sont rapides (de l'ordre de la ms). L'outil vmstat m'était pas d'une très grande utilité.

 

# prstat
[...]
PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP
934 root      13M  9400K cpu3    59    0   3:34:00 3.0% fmd/8
637 root     3712K 2960K cpu0    59    0   0:00:00 0.0% prstat/1
120 root     5432K 2828K sleep   59    0   0:00:00 0.0% nscd/29
604 root     6368K 3608K sleep   59    0   0:00:00 0.0% sshd/1
305 daemon   2816K 1200K sleep   59    0   0:00:00 0.0% rpcbind/1
310 daemon   2780K 1616K sleep   59    0   0:00:00 0.0% statd/1
[...] 

 

Première indication intéressante, le process fmd consommait effectivement beaucoup de temps CPU (temps cumulé) et utilisait environ 3% de CPU. Cela peut paraître très peu mais pour ce type d'application c'est déjà beaucoup trop. Mais que consommait exactement le process fmd ?

 

# prstat -mL -p 934
   PID USERNAME USR SYS  TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
   934 root     0.0 0.0  0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 fmd/8
   934 root     0.0 0.0  0.0 0.0 0.0 0.0 100 0.0   0   0   0   0 fmd/7
   934 root     0.0 23.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 fmd/6
   934 root     0.0 0.0  0.0 0.0 0.0 0.0 100 0.0   0   0   0   0 fmd/5
   934 root     0.0 0.0  0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 fmd/4
   934 root     0.0 0.0  0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 fmd/3
   934 root     0.0 0.0  0.0 0.0 0.0 0.0 100 0.0   0   0   0   0 fmd/2
   934 root     0.0 0.0  0.0 0.0 0.0 0.0 100 0.0   0   0   0   0 fmd/1

 

Un lwpid avait une utilisation très anormal de temps système. L'outil Solaris Fault Manager est orienté modules. Il est facile de connaître les différents modules utilisés mais surtout leurs statistiques.

 

# fmstat
module             ev_recv ev_acpt wait  svc_t  %w  %b  open solve  memsz  bufsz
cpumem-retire            0       0  0.0    0.0   0   0     0     0      0      0
disk-transport           0       0  0.0  286.3   0   0     0     0    32b      0
eft                      0       0  0.0    0.0   0   0     0     0   1.2M      0
ext-event-transport      0       0  0.0    0.0   0   0     0     0      0      0
fabric-xlate             0       0  0.0    0.0   0   0     0     0      0      0
fmd-self-diagnosis       2       0  0.0  320.9   0   0     0     0      0      0
io-retire                0       0  0.0    0.0   0   0     0     0      0      0
snmp-trapgen             0       0  0.0  963.1   0   0     0     0      0      0
sp-monitor               0       0  100  120.1   80  0     0     0      0      0
[...]

 

Le module sp-monitor semblait avoir un comportement vraiment bizarre. Le module sp-monitor se connecte au service processor via le pseudo device /dev/bmc et récupère différentes informations de télémétrie (et autres choses...).

 

Une piste sérieuse se dégageait. J'ai utilisé le script hotkernel pour voir rapidement la consommation de ma CPU par rapport aux fonctions et modules (voir la boite à outils de Gregg Brendan).

 

FUNCTION                     COUNT      PCNT                             
[...]
genunix`sigdiffset           100        0.0%
bmc`kcs_read                 120        0.0%
genunix`sigorset             127        0.0%
genunix`issig_justlooking    687        0.2%
bmc`kcs_status              3894        0.9%
unix`i86_mwait            407904        98.6%                                     

 

MODULE                     COUNT       PCNT                 
[...]
ip                           11        0.0%
ipsecah                      18        0.0%
genunix                     240        0.1%
bmc                        4957        1.2%
unix                     421921        98.8%

 

La CPU consommée l'était par les fonctions kcs_read et kcs_status du module bmc. J'ai utilisé par la suite le script errinfo (légèrement modifié) pour obtenir le code d'erreur du module bmc. En fait la connexion au service processor via le pseudo device bmc ne fonctionnait plus. L'installation du package ipmitool a par ailleurs confirmé ce problème.

 

Le fait d'unloader le module sp-monitor de la configuration fmd résolvait le problème de consommation CPU. Le problème de communication entre Oracle Solaris 10 et le service processor a été corrigé en appliquant le dernier firmware pour les serveurs Galaxy. Rien de très compliqué en fait... L'utilisation d'un outil comme Dtrace m'a permis rapidement de remonter à l'origine du problème. Il y a certainement d'autres méthodes d'investigations plus efficace que celle-ci mais le résultat restera le même : il n'y a plus de problème. Par contre je suis preneur de toutes informations.

 

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
16 août 2010 1 16 /08 /août /2010 21:04

Crash dump on Solaris x86 (with interrupt NMI)

 

 

I'm really surprised when I still see Solaris servers configured without the possibility of taking a dump. These next few lines explain how to do that especially for Solaris x86 (use interrupt NMI).

 

 

To achieve this, it's necessary to configure several elements in the Solaris system:

  • Activation system in debug mode
  • Correct setting for taking dump
  • System configuration for NMI interrupts

 

How to start in debug mode Solaris 10x86 ? It's really simple, just add parameter "kadb" at the end of line "multiboot" in the file "menu.lst" then reboot.

 

As you can see below:

 

# pwd
/rpool/boot/grub

# cat menu.lst
[...]
title s10x_u9wos_14a
bootfs rpool/ROOT/s10x_u9wos_14a
findroot (pool_rpool,0,a)
kernel$ /platform/i86pc/multiboot -B console=ttyb,$ZFS-BOOTFS kadb
module /platform/i86pc/boot_archive
[...] 

 

How to configure correct setting for taking dump ? Just use the command "dumpadm". Two things to check: the dump device and the savecore directory exist with the correct size (the size depends on RAM - two different policies on this subjetc: the size of dump device is the same as the RAM or not).

 

For exemple:

 

# dumpadm
      Dump content: kernel pages
       Dump device: /dev/zvol/dsk/rpool/dump (dedicated)
Savecore directory: /var/crash/zlap
  Savecore enabled: no
   Save compressed: on

# prtconf | grep -i memory
Memory size: 16384 Megabytes

# zfs get volsize rpool/dump
NAME           PROPERTY  VALUE    SOURCE
rpool/dump  volsize       512M     -

# df -h /var/crash/zlap
Filesystem            Size  Used Avail Use% Mounted on
rpool/ROOT/solaris     54G  9.9G   16G  39% / 

 

How to configure system for NMI interrupt ? Just add the following lines in the file /etc/system then reboot.

 

For exemple: 

 

# egrep apic /etc/system
set pcplusmp:apic_kmdb_on_nmi=1
set pcplusmp:apic_panic_on_nmi=1

 

Now, if the system hang, you can send an interrupt NMI and thus take a dump. Either you use the "ipmi" command (if ipmi command are available on ILOM's server) or you use the website of the ILOM's server to generate an interrupt NMI.

 

For exemple (ipmi command):

 

# ipmitool -I lanplus -H server-rsc -U root chassis power diag

 

 

A simple demonstration...

 

On server :

 

$ ssh zlap

 

# uname -a

SunOS zlap 5.10 Generic_142910-17 i86pc i386 i86pc

# prtdiag

System Configuration: HP ProLiant DL360 G5

BIOS Configuration: HP P58 05/18/2009

BMC Configuration: IPMI 2.0 (KCS: Keyboard Controller Style)

[...]

 

 

On Rilo server  :

 

$ ssh admin@zlap-rsc

root@zlap-rsc's password:
User:root logged-in to ILOLD75MU6996.(XXX.XXX.XXX.XX)
iLO 2 Advanced 2.05 at 15:38:15 Dec 17 2009
Server Name: DL360G5P-34-13
Server Power: On

</>hpiLO->
</>hpiLO-> nmi server

</>hpiLO-> vsp

 

Starting virtual serial port.
Press 'ESC (' to return to the CLI Session.

</>hpiLO-> Virtual Serial Port active: IO=0x02F8 INT=3

[1]> 
[1]> ::showrev
Hostname: zlap
Release: 5.10
Kernel architecture: i86pc
Application architecture: amd64
Kernel version: SunOS 5.10 i86pc Generic_142910-17
Platform: i86pc

[1]> $<systemdump
nopanicdebug:   0               =       0x1

panic[cpu1]/thread=fffffe80005e0c60: BAD TRAP: type=e (#pf Page fault) rp=fffffe80005e0980 addr=0 occurred in module "<unknown>" due to a NULL pointer dereference

sched: #pf Page fault
Bad kernel fault at addr=0x0
pid=0, pc=0x0, sp=0xfffffe80005e0a78, eflags=0x10002
cr0: 8005003b<pg,wp,ne,et,ts,mp,pe> cr4: 6f0<xmme,fxsr,pge,mce,pae,pse>
cr2: 0 cr3: 14717000 cr8: c
        rdi: fffffffffbc7eab0 rsi:              2f8 rdx:              2f8
        rcx:                a  r8:                0  r9: ffffffffa4f71c90
        rax: fffffffffbcecbe0 rbx: ffffffffef8f1250 rbp: fffffe80005e0a80
        r10: fffffe80005e09c0 r11:                0 r12: fffffe80005e0af0
        r13:                1 r14: fffffffffbc561c0 r15:                1
        fsb:                0 gsb: ffffffffa44fb800  ds:               43
         es:               43  fs:                0  gs:              1c3
        trp:                e err:                0 rip:                0
         cs:               28 rfl:            10002 rsp: fffffe80005e0a78
         ss:               30

fffffe80005e0890 unix:die+da ()
fffffe80005e0970 unix:trap+5e6 ()
fffffe80005e0980 unix:cmntrap+140 ()
fffffe80005e0a80 0 ()
fffffe80005e0a90 genunix:kdi_dvec_enter+d ()
fffffe80005e0ab0 unix:debug_enter+66 ()
fffffe80005e0ac0 pcplusmp:apic_nmi_intr+94 ()
fffffe80005e0ae0 unix:av_dispatch_nmivect+1f ()
fffffe80005e0af0 unix:nmiint+17e ()
fffffe80005e0be0 unix:i86_mwait+d ()
fffffe80005e0c20 unix:cpu_idle_mwait+125 ()
fffffe80005e0c40 unix:idle+89 ()
fffffe80005e0c50 unix:thread_start+8 ()

syncing file systems... done
dumping to /dev/zvol/dsk/rpool/dump, offset 65536, content: kernel
 0:01 100% done
100% done: 320938 pages dumped, dump succeeded
rebooting...

 

 

It's very simply... no ?

 

 

For you computer culture, here are some links on the topic:

 

 

 

 

 

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
29 juin 2010 2 29 /06 /juin /2010 15:05

Scheduling & Gestion des ressources CPU

 

Afin de mieux appréhender la gestion des ressources CPU, il est nécessaire de mieux cerner le système et notamment l'ordonnancement des processus. A ce titre j'ai eu l'occasion de faire une petite présentation pour l'association Guses sur l'ordonnencement dans Solaris/Opensolaris  en m'appuyant sur des cas pratiques où l'optimisation des ressources CPU est nécessaire. La présentation est disponible ici.

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
20 décembre 2009 7 20 /12 /décembre /2009 11:35

Process impossible a tuer

 

Suite à une mauvaise manipulation (synchronistation baie d'un système de fichiers encore monté), les process associés à ce système de fichiers ne peuvent plus être stopper (killer). A part l'arrêt/relance du serveur rien n'y fait. S'il s'agit d'un container Solaris 10, seul l'arrêt relance de la globale permet de rétablir la situation.

 

Situons nous un peu :

  • Serveur sous Solaris 10u7 avec des containers
  • Systèmes de fichiers montés sur la globale zone puis en lofs dans les containers

 

Soit un container avec une base Oracle où le système de fichiers a été synchronisé (synchro baie) alors qu'il n'était pas démonté au préalable ni dans le container ni dans la globale (normal la base n'a pas été totalement arrêté).

 

# ps -ef | egrep -i [o]rad3
  oracle 18780     1   1   Nov 25 ?  26455:53 oracleORAD3 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

 # kill -9 18780
 

# ps -ef | egrep -i [o]rad3
  oracle 18780     1   1   Nov 25 ?  26457:39 oracleORAD3 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

 

Ca commence mal, non ?

 

# pfiles 18780 
pfiles: no such process: 18780 

# pargs 18780 
pargs: cannot examine 18780: no such process 

# truss -p 18780 
truss: no such process: 18780

 

C'est encore pire. Voyons ce que dtrace peut nous dire (lancer la commande dtrace dans un 1er shell, et le kill dans un 2ème shell)

 

# dtrace -n 'fbt::sigtoproc:entry /pid == 18780/ { trace(arg2); trace(execname); }' 
dtrace: description 'fbt::sigtoproc:entry ' matched 1 probe

# kill -9 18780

 

 

Aucun signal reçu pour le pid 18780 et pourtant, le kill est bien initialisé

 

# signal.d 
... 
2009 Dec  2 08:12:25 ksh(pid:19084 uid:0) is sending signal 9 to oracle(pid:18780 ppid:1 uid:100) 
...

 

Regardons côté kernel

 

# ls /proc/18780 
as   contracts ctl   fd      lstatus lwp object   path psinfo  root    status     watch 
auxv cred      cwd   lpsinfo lusage  map pagedata priv rmap    sigact  usage      xmap 

 

# mdb -kw 
> 0t18780::pid2proc 
30155422488 
> 30155422488::kill 
mdb: command is not supported by current target

 > 30155422488::pfiles 
FD   TYPE            VNODE INFO
   0  CHR 0000030023723ec0 /zones/zone01/root/dev/pts/3
   1  CHR 0000030023723ec0 /zones/zone01/root/dev/pts/3
   2  CHR 0000030023723ec0 /zones/zone01/root/dev/pts/3 
   3  CHR 000006010b548b00 /zones/zone01/root/dev/null
   4  CHR 000006010b548b00 /zones/zone01/root/dev/null
[...] 
  11  REG 00000300a2ec6940 /zones/zone01/root/oracle/product/10.2.0/rdbms/mesg/oraus.msb
[...]
 256  REG 0000030095c4f900 /zones/zone01/root/ORAD3/data/ORAD3_01.ctl
 257  REG 00000300a4ba0740 /zones/zone01/root/ORAD3/data/system.256. 662477099
[...]
 279  REG 000003009469edc0 /zones/zone01/root/ORAD3/data/o1_mf_risk_dat_4w6ktdfx_.dbf

 > ::quit

# cd /proc/18780/fd
ksh: /proc/18780/fd:  not found

 # gcore 18780
gcore: cannot grab 18780: no such process

 

Comme on peut le voir, il y a toujours des fd en mémoire. Reste un à faire un arrêt/relance forcé du système. Si quelqu'un à une solution je suis preneur. Et aller pas me dire de ne pas synchroniser les données quand un système de fichiers est monté...

Partager cet article
Published by gloumps - dans kernel
commenter cet article …
5 décembre 2009 6 05 /12 /décembre /2009 22:33

Panic d'une node Oracle RAC

 

Voilà qu'un beau matin, une node d'un cluster Oracle RAC décide de se tuer. Voiçi l'analyse postmortem qui a permis de détecter un problème de désynchronisation d'horloge (TOD & tick). On commence par ici ...

 

# cd /var/core/`hostname`
# file *.0
unix.0:         ELF 64-bit MSB executable SPARCV9 Version 1, UltraSPARC1 Extensions Required, statically linked, not stripped, no debugging information available 
vmcore.0:       SunOS 5.10 Generic_127127-11 64-bit SPARC crash dump from 'xxxxxx'

# mdb unix.0 vmcore.0
Loading modules: [ unix krtld genunix specfs dtrace ufs sd mpt px ssd fcp fctl md ip hook neti sctp arp usba zfs random ipc nfs sppp crypto cpc fcip logindmux ptm ] 
> 
> ::panicinfo 
             cpu               17 
          thread      30009bf86c0 
         message forced crash dump initiated at user request 
          tstate       4400001600 
              g1                b 
              g2                0 
              g3          11ca714 
              g4              6e0 
              g5         88000000 
              g6                0 
              g7      30009bf86c0 
              o0          1211a68 
              o1      2a100a9b9e8 
              o2                1 
              o3                0 
              o4 fffffffffffffff5 
              o5             1000 
              o6      2a100a9b0b1 
              o7          1068368 
              pc          104980c 
             npc          1049810 
               y                0 

 > 30009bf86c0::thread -p 
            ADDR             PROC              LWP             CRED 
0000030009bf86c0      600b7cb50b8      600bab9af30      6009a003d98 

 > 600b7cb50b8::ps -ft 
S    PID   PPID   PGID    SID    UID      FLAGS             ADDR NAME 
R  29139  28993   1772   1772      0 0x4a004000 00000600b7cb50b8 /crs/10.2.0/bin/oprocd.bin run -t 1000 -m 500 -f 
        T     0x30009bf86c0 <TS_ONPROC> 

> 600b7cb50b8::walk thread |::findstack 
stack pointer for thread 30009bf86c0: 2a100a9b0b1 
  000002a100a9b161 kadmin+0x4a4() 
  000002a100a9b221 uadmin+0x11c() 
  000002a100a9b2e1 syscall_trap+0xac()

 

Le démon opcrod est à l'origine du suicide de la node (commande uadmin). Pour rappel le démon oprocd surveille le cluster RAC et réalise le fencing du cluster RAC (isolement primitif d'un noeud lors d'une défaillance de celui-ci). Lors de ce fencing, oprocd effectue des vérifications de fonctionnement, puis se fige. Si le réveil de l’oprocd n’a pas lieu avant une durée configurée, celui-ci procède au redémarrage du noeud du cluster.

 

Après une petite recherche, il s'agit d'un problème de TOD : bug suivant 6595936. L'ajout des deux paramètres suivants dans le fichier system a permis de corriger le problème définitivement.

 

# cat /etc/system
...
* Bug ID 6595936
set tod_broken = 1
set dosynctodr = 0
..


Partager cet article
Published by gloumps - dans kernel
commenter cet article …