Jeudi 7 février 2013 4 07 /02 /Fév /2013 20:41

 

Les apparences sont quelques fois trompeuses… Petite démonstration confirmant cet adage.

 

Situons le contexte : plusieurs DBA Oracle nous remontent un incident sur un de leur serveur. Le symptôme étant le suivant : connexion impossible. Après une rapide vérification le diagnostic initiale semble être le bon. Petite connexion au déport console du serveur et me voilà devant un message des plus explicite « Unable to fork ». Hop, je provoque un petit panic et en avant pour une petite analyse.

 

Avant de me lancer tête baissée dans l’analyse de ce core, je m’intéresse aux logs du serveur en recherchant le pattern fork.

 

Jan 22 13:05:43 myserver sshd[7716]: [ID 800047 auth.error] error: fork: Error 0
Jan 22 13:08:06 myserver inetd[7805]: [ID 702911 daemon.error] Unable to fork inetd_start method of instance svc:/network/nrpe/tcp:default: Resource temporarily unavailable
Jan 22 13:08:36 eqds2dstdby002 last message repeated 1 time
Jan 22 13:09:59 myserver inetd[7805]: [ID 702911 daemon.error] Unable to fork inetd_start method of instance svc:/network/nrpe/tcp:default: Resource temporarily unavailable

 

A partir de 13:05, il semble que le serveur ne pouvait plus « forker » de nouveau process. Je vais faire parler le core !?

 

# cd /var/crash/myserver
# savecore –f vmdump.0
savecore -f vmdump.0
savecore: System dump time: Tue Jan 22 14:54:46 2013

 

savecore: saving system crash dump in /var/crash/myserver/{unix,vmcore}.0
Constructing namelist /var/crash/myserver/unix.0
Constructing corefile /var/crash/myserver/vmcore.0
8:36  92% done
9:22 100% done: 3571069 of 3571069 pages saved

 

# mdb –k 0
Loading modules: [ unix genunix specfs dtrace zfs sd mpt px ssd fcp fctl sockfs ip hook neti qlc dls sctp arp usba md cpc fcip random crypto logindmux ptm ufs sppp ipc nfs lofs ]
> fork_fail_pending/D
fork_fail_pending:
fork_fail_pending:        1

 

Il s’agit bien d’un problème de fork. Combien de processus générés ?

 

> ::ps !grep -v FLAGS | wc -l
   29952

 

29952 processus en machine !! Sachant que la limite haute se situe vers 30000, je comprends mieux le problème. Essayons dans savoir plus. Quel est le contributeur ? S’agit-il d’une « mauvaise bouche » dans un script (merci la fork bomb)  ?

 
> ::ps
S    PID   PPID   PGID    SID    UID      FLAGS             ADDR NAME
R      0      0      0      0      0 0x00000001 00000000018b09c0 sched
R   4510      0      0      0      0 0x00020001 00000600e4766018 zpool-oradg00
R     92      0      0      0      0 0x00020001 00000600b4821960 zpool-spool
R     88      0      0      0      0 0x00020001 00000600b4823290 zpool-dump
R     86      0      0      0      0 0x00020001 00000600b21b6ca8 zpool-asmdg00
R      7      0      0      0      0 0x00020001 00000600b21b9270 vmtasks
R      3      0      0      0      0 0x00020001 000006009bdb4008 fsflush
R      2      0      0      0      0 0x00020001 000006009bdb4ca0 pageout
Z      1      0      0      0      0 0x4a004000 000006009bdb5938 init
Z   4712      1     11     11      0 0x5a006002 0000060146e6c0d0 p_ctscd
Z   4713      1     11     11      0 0x5a006002 0000060153fa8670 p_ctscs
R   7637      1   7637   7637      0 0x4a014000 00000600c9be4cf0 sac
R   7695   7637   7637   7637      0 0x4a014000 00000600c98b8cd8 ttymon
R  11035      1     11     11      0 0x4a004000 00000600cdd519b8 uce_agent.sh
R  15869  11035     11     11      0 0x4a004000 00000600b2b805e0 uce_agent.bin
Z  24884      1  24884  24884    100 0x4a004002 0000030597a799a0 oracle
Z   1449      1   1449   1449    100 0x4a004002 0000030597a28050 oracle
Z  18483      1  18483  18483    100 0x4a004002 0000030597a7a638 oracle
Z   5461      1   5461   5461    100 0x4a004002 0000030597a7d998 oracle
Z  28198      1  28198  28198    100 0x4a004002 0000030597a7c068 oracle
Z  21932      1  21932  21932    100 0x4a004002 0000030597a7cd00 oracle
Z  14770      1  14770  14770    100 0x4a004002 0000030597a37368 oracle
Z   8999      1   8999   8999    100 0x4a004002 0000030597aad938 oracle
[…]
Z  13641      1  13641  13641    100 0x4a004002 0000030597aa3280 oracle
Z  12707      1  12707  12707    100 0x4a004002 0000030597aa4018 oracle
>> More [<space>, <cr>, q, n, c, a] ?

 

A première vue Il semble y avoir beaucoup de processus « oracle ».  Piste intéressante, j’investigue.

 

> ::ps !grep -c oracle
29684

 

Confirmation qu’il s’agit bien du contributeur « oracle ». J’essaye dans savoir un peu plus.

 

> ::ptree
00000000018b09c0  sched
     00000600e4766018  zpool-oradg00
     00000600b4821960  zpool-spool
     00000600b4823290  zpool-dump
     00000600b21b6ca8  zpool-asmdg00
     00000600b21b9270  vmtasks
     000006009bdb4008  fsflush
     000006009bdb4ca0  pageout
     000006009bdb5938  init
          0000060146e6c0d0  p_ctscd
          0000060153fa8670  p_ctscs
          00000600c9be4cf0  sac
               00000600c98b8cd8  ttymon
          00000600cdd519b8  uce_agent.sh
               00000600b2b805e0  uce_agent.bin
          0000030597a799a0  oracle
          0000030597a28050  oracle
          0000030597a7a638  oracle
          0000030597a7d998  oracle
          0000030597a7c068  oracle
          0000030597a7cd00  oracle
          0000030597a37368  oracle
          0000030597aad938  oracle     
[…]

 

Tous les processus « oracle » ont comme père le processus init. Il s’agit vraisemblablement d’un nombre important de « sessions oracle » (et non pas une fork bomb). Je vérifie.

 

> ::ps -ft !grep oracle
Z  24884  1  24884  24884  100 0x4a004002 0000030597a799a0 oracleBASE (LOCAL=NO)
Z   1449  1   1449   1449  100 0x4a004002 0000030597a28050 oracleBASE (LOCAL=NO)
Z  18483  1  18483  18483  100 0x4a004002 0000030597a7a638 oracleBASE (LOCAL=NO)
Z   5461  1   5461   5461  100 0x4a004002 0000030597a7d998 oracleBASE (LOCAL=NO)
Z  28198  1  28198  28198  100 0x4a004002 0000030597a7c068 oracleBASE (LOCAL=NO)
Z  21932  1  21932  21932  100 0x4a004002 0000030597a7cd00 oracleBASE (LOCAL=NO)
Z  14770  1  14770  14770  100 0x4a004002 0000030597a37368 oracleBASE (LOCAL=NO)
Z   8999  1   8999   8999  100 0x4a004002 0000030597aad938 oracleBASE (LOCAL=NO)
Z   2874  1   2874   2874  100 0x4a004002 0000030597a7e630 oracleBASE (LOCAL=NO)
Z  29899  1  29899  29899  100 0x4a004002 0000030597a88050 oracleBASE (LOCAL=NO)
Z  26317  1  26317  26317  100 0x4a004002 0000030597a7f2c8 oracleBASE (LOCAL=NO)
Z  23244  1  23244  23244  100 0x4a004002 0000030597a80cf8 oracleBASE (LOCAL=NO)
Z  20412  1  20412  20412  100 0x4a004002 0000030597a81990 oracleBASE (LOCAL=NO)
Z  16689  1  16689  16689  100 0x4a004002 0000030597a82628 oracleBASE (LOCAL=NO)
[…]

 

 

Bingo ! J’ai un coupable… Un petit paasage chez les DBA Oracle pour leur expliquer que l’incident survenu sur le serveur (indisponibilité) provient de chez eux.

 

<troll><mode Adrien> Encore les DBA, les nuls !! Un bon DBA est un DBA … </mode Adrien></troll>

 

J’ai dit quoi déjà : les apparences sont quelques fois trompeuses…

 

<troll> Adrien, calme me toi et lis la suite </troll>

 

En regardant d’un peu plus près le retour des commandes « ps », un premier élément me choque.

 

> ::ps -ft
[…]
Z  24884  1  24884  24884  100 0x4a004002 0000030597a799a0 oracleBASE (LOCAL=NO)
Z   1449  1   1449   1449  100 0x4a004002 0000030597a28050 oracleBASE (LOCAL=NO)
Z  18483  1  18483  18483  100 0x4a004002 0000030597a7a638 oracleBASE (LOCAL=NO)
Z   5461  1   5461   5461  100 0x4a004002 0000030597a7d998 oracleBASE (LOCAL=NO)
[…]

 

A première vue il s’agit de processus « zombie ».  Strange… Combien de processus zombie pour cette base ? Existe-t-il d’autres processus zombie ?

 

> ::ps -ft !grep oracleBASE | grep -c ^Z
28773

> ::ps -ft !grep ^Z | grep -cv oracleBASE
469

 

Attention un processus zombie consomme une entrée dans la table des processus.

 

On a related note, the signal flow explains why zombie processes cannot be killed (any horror movie fan knows you can’t kill a zombie). A process must be executing in order to take delivery of a signal. A zombie process is, by definition, a process that has terminated. It exists only as a process table entry, with all of its execution state having been freed by the kernel (see preap(1) for cleaning up zombie processes).

 

En détaillant un peu les autres processus zombie un autre indice me choque rapidement.

 

> ::ps –ft !grep ^Z | grep –v BASE
Z      1   0      0      0    0 0x4a004000 000006009bdb5938 /sbin/init
Z  29265   1  29265  29265  100 0x4a004002 000003059798f2f8 oracle+ASM (LOCAL=NO)
Z  17389   1  17389  17389  100 0x4a004002 000003059791c088 oracleXXX (LOCAL=NO)
Z  10068   1  10068  10068  100 0x4a004002 00000305979172f8 oracleXXZ (LOCAL=NO)
Z   8308   1   8308   8308  100 0x4a004002 0000030597924d10 oracleXYZ (LOCAL=NO)
Z   6559   1   6559   6559  100 0x4a004002 0000030597930060 oracleZWX (LOCAL=NO)
Z   1229   1   1229   1229  100 0x4a004002 00000305978e8100 oracleZSD (LOCAL=NO)
Z  16366   1  16366  16366  100 0x4a004002 00000305977c0060 oracleWWW (LOCAL=NO)
Z   2621   1   2621   2621  100 0x4a004002 0000030597713340 oracleQQQ (LOCAL=NO)
Z  25811   1  25519  25519  100 0x4a004002 0000030597640d28 who am i
[…]

 

Le process « init » est dans l’état « zombie »… C’est assez surprenant !? Normalement un processus zombie est un processus terminé en attente d’un signal wait(2).

 

Regardless of which event causes the process to terminate, the kernel exit function is ultimately executed, freeing whatever resources have been allocated to the process, such as the address space mappings, open files, etc., and setting the process state to SZOMB, or the zombie state. A zombie process is one that has exited and that requires the parent process to issue a wait(2) system call to gather the exit status. The only kernel resource that a process in the zombie state is holding is the process table slot. Successful execution of a wait(2) call frees the process table slot. Orphaned processes are inherited by the init process solely for this purpose.

 

Mais s’agissant du processus init qui va lui envoyer le signal wait(2) ?

 

L’état du processus « init » semble inquiétant mais pour le moment, il n’existe pas encore de relation entre l’incident de fork et l’état du processus « init ». Y’a-t-il une information dans le buffer de messages concernant le process init ?

 

> ::msgbuf !grep init
NOTICE: core_log: init[1] core dumped: /var/core/core_myserver_init_0_0_1358854223_1
WARNING: init(1M) core dumped on signal 11: restarting automatically
WARNING: exec(/sbin/init) failed with errno 48.
WARNING: failed to restart init(1M) (err=48): system reboot required

 

Le processus init a eu un petit problème (signal SIGSEGV - Segmentation Fault) et n’a pas été réactivé correctement (exec failed – errno 48). Le problème du buffer de message c’est qu’il n’y a pas de timestamp. Du coup difficile de dire si il y a un rapport ou non avec mon incident « fork ».

 

Un petit passage par la log système est nécessaire.

 

Jan 22 12:30:24 myserver genunix: [ID 603404 kern.notice] NOTICE: core_log: init[1] core dumped: /var/core/core_myserver_init_0_0_1358854223_1
Jan 22 12:30:24 myserver genunix: [ID 894729 kern.warning] WARNING: init(1M) core dumped on signal 11: restarting automatically
Jan 22 12:30:24 myserver genunix: [ID 923222 kern.warning] WARNING: exec(/sbin/init) failed with errno 48.
Jan 22 12:30:24 myserver genunix: [ID 404865 kern.warning] WARNING: failed to restart init(1M) (err=48): system reboot required

 

L’incident du « fork » se situe environ 35 minutes après l’incident du processus init… Quelle est la date de création de ces processus zombie ? Proviennent -ils d’avant l’incident du processus init ou pas ?

 

J’ai écrit un petit script pour obtenir le timestamp de création des processus (c’est pas très élégant mais ça fonctionne).

 

# cat /tmp/time_process_zombie
echo "::ps !grep ^Z" | mdb -k 0 | awk '{print $8}' > ps$$

while read proc
do
        echo $proc | awk '{print $1}'
        echo $proc | awk '{print $1,"::print proc_t p_user.u_start.tv_sec"}' | mdb unix.0 vmcore.0
done < ps$$

 

# cd /var/crash/myserver
# sh /tmp/bruno > liste_zombie

 

 

# cat /tmp/time_process_run
echo "::ps !grep ^R" | mdb -k 0 | awk '{print $8}' > ps$$ 

while read proc
do
        echo $proc | awk '{print $1}'
        echo $proc | awk '{print $1,"::print proc_t p_user.u_start.tv_sec"}' | mdb unix.0 vmcore.0
done < ps$$

 

# cd /var/crash/myserver
# sh /tmp/time_process_run > liste_run

 

 

Quelques observations après l’analyse des résultats :

 

  • Seulement 3 processus créés après l’incident du processus « init » (bien entendu ces processus n’ont pas « init » comme père et celui-ci (leur père) n’est pas dans l’état zombie).
  • Plus de 29300 processus zombie ont été créés à partir du 22 janvier 12:30:00.
  • En date du 22 janvier, le premier processus zombie a démarré vers  « 2013 Jan 22 12:05:33 ».

 

> 00000600dd4b99c8::ps -ft
S   PID PPID  PGID   SID UID      FLAGS             ADDR NAME
Z 11891    1 11891 11891   0 0x42000002 00000600dd4b99c8 /usr/lib/rcm/rcm_daemon

 

Il s’agit du deamon rcm_deamon. C’est quoi ce truc ? RCM « Reconfiguration Coordination Manager » est un framework qui manage la suppression automatique de composants du système.

 

The Reconfiguration Coordination Manager (RCM) is the framework that manages the dynamic removal of system components. By using RCM, you can register and release system resources in an orderly manner. You can use the new RCM script feature to write your own scripts to shut down your applications, or to cleanly release the devices from your applications during dynamic reconfiguration. The RCM framework launches a script automatically in response to a reconfiguration request, if the request impacts the resources that are registered by the script.

 

Une modification récente sur le système ? Mais oui… évidement maintenant qu’on en parle : il y a eu effectivement un changement de disque SCSI sur le châssis vers 12h00. Je vérifie rapidement l’heure de l’opération.

 

Jan 22 12:02:08 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:02:08 myserver  Disconnected command timeout for Target 1
Jan 22 12:02:08 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:02:08 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:03:18 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:03:18 myserver Disconnected command timeout for Target 1
Jan 22 12:03:19 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:03:19 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:04:29 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:04:29 myserver Disconnected command timeout for Target 1
Jan 22 12:04:29 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:04:29 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:05:39 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:05:39 myserver Disconnected command timeout for Target 1
Jan 22 12:05:40 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:05:40 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:06:42 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:42 myserver wwn for target has changed
Jan 22 12:06:50 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver  Disconnected command timeout for Target 1
Jan 22 12:06:50 myserver scsi: [ID 107833 kern.notice] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver  mpt_flush_target discovered non-NULL cmd in slot 484, tasktype 0x3
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver Cmd (0x3005fa08e00) dump for Target 1 Lun 0:
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver cdb=[ 0x25 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 ]
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver pkt_flags=0x1c000 pkt_statistics=0x0 pkt_state=0x0
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver pkt_scbp=0x0 cmd_flags=0x860
Jan 22 12:06:53 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1/sd@1,0 (sd0):
Jan 22 12:06:53 myserver Corrupt label; wrong magic number
[…]
Jan 22 12:09:57 myserver genunix: [ID 408114 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0) quiesced
[…]

 

Que dire de plus… Le changement physique du disque semble avoir « perturber » le système au point où le processus « init » segfault. Ce type d'incident ne se produit pas souvent du coup c'est difficile de savoir ce qui doit se passer. Dans mon cas, il semble y avoir eu création d’environ 29300 processus dans un statut bizarre (zombie).

 

Je remercie Yahya pour m’avoir challengé sur cet incident. Sans lui, je serais passé à côté de l'état zombie d'init et jamais je n'aurais pensé à vérifier les dates de création des processus. Les apparences sont quelques fois trompeuses… n'oubliez pas !?

 

P.S. : Yahya est DBA Oracle...

 

 

Par gloumps - Publié dans : kernel
Ecrire un commentaire - Voir les 1 commentaires
Retour à l'accueil

Commentaires

Bruno,
share all and compute with your self!
Bravo à toi.
Commentaire n°1 posté par Yahya le 08/02/2013 à 22h12

Présentation

Informations personnelles

  • Passionné d'informatique, je travaille actuellement comme expert système Solaris. Vous trouverez plus de renseignements à mon sujet sur mon profil Linkedin.

Flux RSS

  • Flux RSS des articles

Recherche

Calendrier

Septembre 2014
L M M J V S D
1 2 3 4 5 6 7
8 9 10 11 12 13 14
15 16 17 18 19 20 21
22 23 24 25 26 27 28
29 30          
<< < > >>
Créer un blog gratuit sur over-blog.com - Contact - C.G.U. - Signaler un abus - Articles les plus commentés