Solaris mon amour

Continuons un peu cette formidable aventure dans la gestion de l'ISM sous Solaris x86. Dans l'article précédent, j'évoque un problème d'initialisation de l'ISM provenant des tailles de pages. Dans cet article, j'ai découvert un bug dans la gestion de l'ISM toujours sous Solaris x86.

Suite à une migration d'une base de données Oracle d'une architecture Solaris Sparc à une architecture Solaris x86, l'équipe DBA a décidé d'utiliser pleinement la mémoire disponible sur cette nouvelle infrastructure. Disposant d'un serveur avec 512 Go de mémoire, la SGA de la base Oracle a été positionnée à 290 Go (afin de diminuer les lectures physiques et d'éviter les locks R/W). L'augmentation de cette SGA a eu un bénéfice important sur les opérations de lectures (plus d'activité sur les disques SAN concernant les lectures) par contre le système Solaris saturait...

# vmstat 3
kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr s0 s1 s6 s7 in sy cs us sy id
11 2 0 274157192 335523004 1348 8439 1506 2 2 0 1 5 -1 158 105 15844 31218 10183 5 7 88
2 12 0 86340852 144652404 1996 43583 0 25 24 0 0 0 0 0 0 64086 182685 44871 13 34 53
2 0 0 86352032 144645428 4773 45640 0 17 17 0 0 0 0 0 0 179020 200275 59466 16 31 53
0 1 0 86327500 144637200 1680 42171 0 35 33 0 0 0 0 0 0 69311 178558 44632 14 40 46
2 0 0 86357008 144655832 2035 35481 0 13 13 0 0 0 0 0 0 62857 162021 45164 13 25 63
2 0 0 86334148 144631452 1940 44848 0 11 11 0 0 0 0 0 0 64294 188696 43993 13 38 49
1 1 0 86171376 144496048 3014 52949 0 5 5 0 0 0 0 0 0 64821 192942 46708 17 30 52
52 1 0 86025360 144381188 1779 38176 0 16 16 0 0 0 0 0 0 47234 129932 29021 13 64 24
2 0 0 85953152 144301940 1766 50384 0 21 20 0 0 5 0 0 0 68138 181369 40882 18 46 37
0 2 0 86124088 144497016 2889 38238 0 11 11 0 0 0 0 0 0 53142 151981 36137 11 46 43
50 0 0 86065384 144470520 1806 46570 0 27 24 0 0 0 0 0 0 41055 147273 26207 9 71 20
2 0 0 86020672 144434312 1818 30717 8 3 1 0 0 0 0 0 0 59711 155183 37919 11 55 33
20 1 0 86000472 144415592 2892 46429 0 24 23 0 0 0 0 0 0 48937 161600 32703 12 66 23

^C

Le système saturait complètement lors de l'utilisation massive de la base de données. Avec un load de plus 200 sur 5 minutes, un pourcentage de 80 pour le SYS et 20 pour le USER, quelques choses ne fonctionnait pas correctement.

Passons à l'analyse de ce problème. D'abord, qui utilise le temps système ?

# dtrace -n 'profile-1001hz /arg0/ { @[execname] = count(); }'
dtrace: description 'profile-1001hz ' matched 1 probe
^C
[…]
mpathadm 1102
fsflush 2160
tnslsnr 4541
sched 37200
oracle 496331

Le temps système provient des process Oracle DB. Une bonne chose mais cela reste étrange. Que fait Oracle pour consommer autant de temps système ?

# dtrace -n 'profile-1001hz /arg0 && execname == "oracle" / { @[stack()] = count(); } tick-60s { trunc(@,5); exit(0);}'
dtrace: description 'profile-1001hz ' matched 2 probes
CPU ID FUNCTION:NAME
19 73222 :tick-60s

unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0x99
ipc`ipc_get+0x62
shmsys`shmget+0x4a
shmsys`shmsys+0x7e
unix`sys_syscall+0x17b
83649

unix`mutex_delay_default+0xa
unix`mutex_vector_enter+0x99
ipc`ipc_lock_internal+0x4b
ipc`ipc_lock+0x11
shmsys`shm_detach+0x5c
shmsys`shmdt+0x90
shmsys`shmsys+0x6d
unix`sys_syscall+0x17b
94488

unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0x99
ipc`ipc_lock_internal+0x4b
ipc`ipc_lock+0x11
shmsys`shm_detach+0x5c
shmsys`shmdt+0x90
shmsys`shmsys+0x6d
unix`sys_syscall+0x17b
108405

unix`mutex_delay_default+0xa
unix`mutex_vector_enter+0x99
ipc`ipc_lock_internal+0x4b
ipc`ipc_lookup+0x29
shmsys`shmat+0x70
shmsys`shmsys+0x59
unix`sys_syscall+0x17b
129651

unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0x99
ipc`ipc_lock_internal+0x4b
ipc`ipc_lookup+0x29
shmsys`shmat+0x70
shmsys`shmsys+0x59
unix`sys_syscall+0x17b
147262

Fort intéressant !? Lors des appels systèmes shmat() et shmdt(), le système consomme son temps dans des mutex. Regardons cela de plus près. S'aggissant de locks type adaptive mutex, deux choses sont à vérifier : 

• le temps d'acquisition de la ressource (cpu off donc mutex adaptive block)
• le temps écoulé pendant l'obtention de la ressource (cpu on donc mutex spin)

J'ai écrit rapidement un petit script Dtrace me permettant de quantifier rapidement ces deux temps (j'utilise notamment la probe lockstat). Ci-joint le résultat

# ./ipc_lock.d

558462664068813 cpu  4 exec oracle pid 23796: adaptive-block(0) took 1015 ms
558461944173547 cpu 28 exe oracle pid 23864: adaptive-block(0) took 1185 ms
558462329451173 cpu 30 exe oracle pid 23886: adaptive-spin(0) took 2570 ms
558462329430767 cpu 31 exe oracle pid 23724: adaptive-spin(0) took 1930 ms
558463436775114 cpu  0 exec oracle pid 23906: adaptive-spin(0) took 1963 ms
558463900687630 cpu  0 exec oracle pid 22498: adaptive-spin(0) took 1598 ms
558463900815833 cpu  0 exec oracle pid 23165: adaptive-block(0) took 1088 ms
558463119973512 cpu  1 exec oracle pid 23840: adaptive-spin(0) took 2979 ms
558463900250335 cpu  2 exec oracle pid 23868: adaptive-spin(0) took 3515 ms
558463436925731 cpu  5 exec oracle pid 23786: adaptive-block(0) took 1397 ms
558463900448070 cpu  6 exec oracle pid 23808: adaptive-block(0) took 1199 ms
558463900426025 cpu 10 exec oracle pid 22343: adaptive-spin(0) took 1766 ms
558463436944972 cpu 14 exec oracle pid 23881: adaptive-block(0) took 1203 ms
558463775141403 cpu 15 exec oracle pid 23903: adaptive-spin(0) took 3979 ms
558463646477100 cpu 16 exec oracle pid 23858: adaptive-spin(0) took 3374 ms
558463545080417 cpu 17 exec oracle pid 23842: adaptive-block(0) took 1299 ms
558463775195434 cpu 20 exec oracle pid 23838: adaptive-block(0) took 1164 ms
558463775112272 cpu 21 exec oracle pid 23900: adaptive-spin(0) took 1893 ms
558464220990762 cpu  8 exec oracle pid 23471: adaptive-spin(0) took 1754 ms
558464221051681 cpu 15 exec oracle pid 23136: adaptive-spin(0) took 1967 ms
558466485966584 cpu  9 exec oracle pid 23903: adaptive-spin(0) took 1040 ms
558466153296593 cpu 16 exec oracle pid 23918: adaptive-spin(0) took 1597 ms
558467238545528 cpu  1 exec oracle pid 23855: adaptive-spin(0) took 1206 ms
558467660401004 cpu  8 exec oracle pid 23888: adaptive-spin(0) took 1917 ms
558466980614425 cpu  9 exec oracle pid 23938: adaptive-block(0) took 1141 ms
558466980595351 cpu 11 exec oracle pid 23930: adaptive-block(0) took 1354 ms
558467779687829 cpu 14 exec oracle pid 23955: adaptive-spin(0) took 2318 ms
558467976549814 cpu  4 exec oracle pid 23908: adaptive-spin(0) took 1210 ms
558467976490096 cpu  5 exec oracle pid 23641: adaptive-spin(0) took 1278 ms
558469750980230 cpu  3 exec oracle pid 23936: adaptive-spin(0) took 3297 ms
558469308862236 cpu  5 exec oracle pid 23911: adaptive-spin(0) took 1332 ms
558469308776939 cpu  7 exec oracle pid 23920: adaptive-spin(0) took 3390 ms
558469308793235 cpu  8 exec oracle pid 23890: adaptive-spin(0) took 3219 ms
558469308812116 cpu 10 exec oracle pid 23955: adaptive-spin(0) took 1413 ms
ˆC
558469750890183 cpu 11 exec oracle pid 23991: adaptive-spin(0) took 1774 ms

Ca se passe de commentaire non !? Plus de 3 secondes en moyenne pour les adaptive spin !!! Mais que se passe t'il exactement ? Lors de chaque attachement ou détachement à la SGA, le système lock la ressource IPC. En moyenne, il y a environ 20 attachements / détachements seconde sur cette base de données avec plus de 1000 connexions actives en simultanées (voir la colonne NATTCH).

# ipcs -mopi -z zonexxxx
IPC status from <running system> as of Tue Oct 23 10:14:51 CET 2011
T         ID      KEY        MODE        OWNER    GROUP NATTCH  CPID  LPID ISMATTCH
Shared Memory:
m  520093698   0x77adb4f8 --rw-rw----   oracle      dba   1338 29340 18826     1338    

Voyons un peu plus dans le détail les différentes stack() kernel obtenus lors des locks adaptive spin et block.

# ./ipc_stack.d

   unix`htable_release+0x93
   unix`hati_load_common+0x12d
   unix`hat_share+0x281
   genunix`segspt_shmattach+0xd2
   genunix`as_map_locked+0x102
   genunix`as_map+0x4a
   shmsys`shmat+0x500
   shmsys`shmsys+0x59
   genunix`dtrace_systrace_syscall+0xc7
   unix`sys_syscall+0x17b
   225

   unix`htable_lookup+0x8c
   unix`hati_load_common+0x5b
   unix`hat_share+0x281
   genunix`segspt_shmattach+0xd2
   genunix`as_map_locked+0x102
   genunix`as_map+0x4a
   shmsys`shmat+0x500
   shmsys`shmsys+0x59
   genunix`dtrace_systrace_syscall+0xc7
   unix`sys_syscall+0x17b
   606 

   unix`htable_lookup+0x8c
   unix`hat_unshare+0x7e
   genunix`segspt_shmunmap+0x81
   genunix`as_unmap+0x137
   shmsys`shm_detach+0x4b
   shmsys`shmdt+0x90
   shmsys`shmsys+0x6d
   genunix`dtrace_systrace_syscall+0xc7
   unix`sys_syscall+0x17b
   897

La fonction hat_share() semble assez intéressante à étudier. En regardant d'un peu plus près le code source, on constate l'élément suivant : suite à différentes conditions, soit la table de pages est partagée soit elle ne l'est pas (goto share - goto unshare). Si vous avez lu l'article précédant, un des avantages d'utiliser un segment ISM est justement de pouvois partager sa table de pages entre les différents processus se connectant à ce segment.

La fonction hati_load_command() exécutée dans la fonction hat_share() se déclenche uniquement dans le goto unshare. Tient donc, on utilise ISM et on ne partage pas la table de pages entre les différents processus !? Une des conditions provoque ce dysfonctionnement mais laquelle ? La taille de la SGA influence t'elle quelques choses ? Y a t'il une limite à la SGA ?

J'ai décidé de reprendre cette analyse sur différentes bases Oracles ayant des tailles de SGA différentes. Le résultat est surprenant... Pour chaque attachement à la SGA, la stack est identique. Cela veut dire que la table de pages n'est jamais partagée sur un Solaris 10x86 quand l'ISM est activé !!! Oupppsss !!! Cependant les temps de locks sont nettement inférieurs à la seconde et augementent quand la taille de la SGA augmente.

Pour résumé, l'ISM activé sur Solaris 10x86 ne partage pas la table de pages entre les différents processus qui y accèdent. Plus il y a d'attachements simultanés plus le phénomène s'accentue. Plus la taille de l'ISM est important plus les temps de locks sont importants. Avec toute ces petites informations j'ai ouvert un call chez Oracle. Le diagnostique s'avère exact, un bug a été ouvert en interne avec la référence suivante Bug 7127336: page table not shared for ISM segment on x64.

La correction du Bug semble assez complexe à mettre en oeuvre. J'ai donc travaillé avec les ingénieurs Oracle afin de trouver une solution temporaire à ce problème... Il va falloir attendre un peu pour les solutions...

Ci-joint quelques références sur ce sujet :

• Chapitre 4, chapitre 12 et chapitre 17 dans Solaris internals
• Shared memory uncovered par Jim Mauro