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".