Solaris mon amour

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.