Solaris mon amour

Cela fait déjà un petit moment que j'ai écrit la 1er partie de cet article et j'imagine que vous aviez hâte dans connaître le dénouement ?

Pour rappel, la forte consommation CPU (notamment le temps system) provenait de l'agent Grid d'Oracle. Suite à la modification dans le kernel du mode d'allocation des pages (pg_contig_disable), la charge CPU semblait se répartir plus équitablement entre le temps system et le temps user. Mais... quelque chose me choquait encore...

# vmstat 5
kthr      memory            page            disk          faults      cpu
r b w   swap  free  re  mf pi po fr de sr m1 m1 s0 s1   in   sy   cs us sy id
10 0 0 10703368 22253264 686 5492 144 0 0 0 0 25 4 4 4 14772 115284 20499 46 28 26
6 0 0 25164544 7403960 1041 8609 0 0 0 0 0 1  0  0  0 13946 131868 24255 45 52 3
5 0 0 25236360 7412640 892 7452 0 0 0 0 0  1  0  0  0 17576 142221 28069 47 44 9
0 0 0 25265688 7406912 960 8391 0 0 0 0 0  1  0  0  0 17918 151723 29192 46 45 8
0 0 0 25273088 7403816 1053 9120 0 0 0 0 0 1  0  6  6 17035 189702 29475 47 45 8
1 0 0 25212800 7387888 861 7344 0 0 0 0 0  1  0  0  0 17021 148306 27156 48 46 6
1 0 0 25269080 7405256 996 8419 0 0 0 0 0  1  0  0  0 17066 143782 27059 45 44 12

La répartition du temps system et du temps user est bien égale. Ce qui me semble surprenant c'est d'avoir un temps system aussi important pour ce type d'application : exécution de bases Oracle. Du temps system pour des bases de données, je veux comprendre pourquoi.  

# dtrace -n 'profile-997hz /arg0/ { @[func(arg0)] = count(); }'
dtrace: description 'profile-997hz ' matched 1 probe
^C
[…]
  unix`page_lookup_create               463
  unix`bzero                            509
  unix`utl0                             510
  unix`mutex_exit                       693
  genunix`avl_walk                      843
  FJSV,SPARC64-VI`cpu_halt_cpu         1243
  unix`page_exists                     2782
  unix`mutex_delay_default             2887
  unix`page_trylock                    3086
  FJSV,SPARC64-VI`copyout_more         3455
  unix`mutex_enter                     5212

Encore des mutex !! Toujours des mutex !? Si vous avez bien suivie la 1er partie de cette analyse, après l'agent Grid, le deuxième contributeur des muxtex était Oracle. Mais vérifions tout de même.

# dtrace -n 'lockstat::mutex_enter: { @[execname] = count(); }'
dtrace: description 'lockstat::mutex_enter: ' matched 3 probes
^C
[…]
  emdctl                    15109
  init                      19896
  dtrace                    21512
  sldrm_hist                61435
  zpool-zone039             85352
  sched                    236548
  sldrm_coll               508763
  perl                     697386
  fsflush                 1168071
  emagent                 1590809
  tnslsnr                 2150743
  oracle                 10154578

Regardons dans le détails la ressource utilisée pour ce type de mutex.

# dtrace -n 'lockstat::mutex_enter: /execname == "oracle"/ \
{ @[stack()] = count(); } tick-60s { trunc(@,5); exit(0); }'
dtrace: description 'lockstat::mutex_enter: ' matched 4 probes
CPU     ID                    FUNCTION:NAME
  3  65327                        :tick-60s

 […]

          unix`page_trylock+0x38
          unix`page_trylock_cons+0xc
          unix`page_get_mnode_freelist+0x19c
          unix`page_get_freelist+0x430
          unix`page_create_va+0x258
          genunix`swap_getapage+0x168
          genunix`swap_getpage+0x4c
          genunix`fop_getpage+0x44
          genunix`anon_private+0x140
          genunix`segvn_faultpage+0x808 
          genunix`segvn_fault+0xbf0
          genunix`as_fault+0x4c8
          unix`pagefault+0xac
          unix`trap+0xd50         
          unix`utl0+0x4c
       3818149

          unix`page_trylock+0x38
          unix`page_trylock_cons+0xc
          unix`page_get_mnode_freelist+0x19c
          unix`page_get_freelist+0x430
          unix`page_create_va+0x258
          genunix`swap_getapage+0x168
          genunix`swap_getpage+0x4c
          genunix`fop_getpage+0x44
          genunix`anon_zero+0x88
          genunix`segvn_faultpage+0x1e0
          genunix`segvn_fault+0xbf0
          genunix`as_fault+0x4c8
          unix`pagefault+0xac
          unix`trap+0xd50
          unix`utl0+0x4c
      26458018

Ce résultat est vraiment intéressant : mon temps system (induit par des mutex) est consécutif à des pagefault. Oracle effectue des opérations ZFOD (anon_zero) pour allouer de nouvelles pages type anonymous memory (l'info en plus : le backing store des pages anonymous memory est le swap space - explications des opérations types swap_getpage).

Le serveur dispose de plusieurs zones qui exécutent plusieurs bases de données Oracle. Le problème est'il localisé à une zone, une base ? Ou bien une problème générale sur le serveur ? Vérifions cela. 

# dtrace -n '::anon_zero:entry /execname == "oracle"/ \
{ @[zonename] = count(); }'                                     
dtrace: description '::anon_zero:entry ' matched 1 probe
^C 

  global                 1004
  zone013                2775
  zone015                3266
  zone034                7206
  zone043               16857
  zone039              319582

# dtrace -n '::anon_zero:entry /zonename == "zone039" \
&& execname == "oracle"/ { @[pid] = count(); }'
dtrace: description '::anon_zero:entry ' matched 1 probe
^C
[…]

     4387              599
     3903              815
    29484              930
    17591              991
    13001             3763
    18422             6550

Deux PID semblent sortir du lot lors de ma prise de mesures.

# ptree 18422
18422 oracleXXXX1 (LOCAL=NO)

# ptree 13001
13001 oracleXXXX1 (LOCAL=NO)

Pour résumé, mes mutex proviennent d'allocation ZFOD effectuée par des sessions Oracle à une base spécifique. On se rapproche de la conclusion. Mais avant essayons dans savoir plus en affichant ce qui se passe en temps user pour un des process trouvé.

# dtrace -n '::anon_zero:entry /pid == 18422/ \
{ @[ustack()] = count(); } tick-30s { trunc(@,5); exit(0); }'
dtrace: description '::anon_zero:entry ' matched 2 probes
CPU     ID                    FUNCTION:NAME
11  65327                        :tick-30s

         libc_psr.so.1`memset+0x140
         oracle`klmalf+0x3c
         oracle`kllcqas+0xb8
         oracle`kcblasm+0x48
         oracle`kxhfNewBuffer+0x270
         oracle`qerhjSplitBuild+0x250
         oracle`qerixtFetch+0x558
         oracle`rwsfcd+0x6c
         oracle`qerhjFetch+0x530
         oracle`qervwFetch+0x94
         oracle`rwsfcd+0x6c
         oracle`qerhjFetch+0x530
         oracle`qerjotFetch+0x1f0
         oracle`qerjotFetch+0x1f0
         oracle`qerjotFetch+0x1f0
         oracle`opifch2+0x28f4
         oracle`opiall0+0x884
         oracle`opial7+0x390
         oracle`opiodr+0x590
         oracle`ttcpip+0x420
        1200

         oracle`qerhjBuildHashTable+0x784
         oracle`qerhjInnerProbeHashTable+0x250
         oracle`qerixtFetch+0x558
         oracle`rwsfcd+0x6c
         oracle`qerhjFetch+0x1c8
         oracle`qervwFetch+0x94
         oracle`rwsfcd+0x6c
         oracle`qerhjFetch+0x530
         oracle`qerjotFetch+0x1f0
         oracle`qerjotFetch+0x1f0
         oracle`qerjotFetch+0x1f0
         oracle`opifch2+0x28f4
         oracle`opiall0+0x884
         oracle`opial7+0x390
         oracle`opiodr+0x590
         oracle`ttcpip+0x420
         oracle`opitsk+0x5e8
         oracle`opiino+0x3e8
         oracle`opiodr+0x590
         oracle`opidrv+0x448
        1405
 

          libc_psr.so.1`memset+0x140
          oracle`klmalf+0x3c
          oracle`kllcqas+0xb8
          oracle`kcblasm+0x48
          oracle`kxhfNewBuffer+0x270
          oracle`qerhjGetNewBuffer+0x24
          oracle`ksxb1bqb+0xa0
          oracle`kxhrPack+0x564
          oracle`qerhjSplitBuild+0x164
          oracle`qerixtFetch+0x558
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qervwFetch+0x94
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`opifch2+0x28f4
          oracle`opiall0+0x884
         2400

          libc_psr.so.1`memset+0x140
          oracle`qerhjBuildHashTable+0x228
          oracle`qerhjInnerProbeHashTable+0x250
          oracle`qerixtFetch+0x558
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x1c8
          oracle`qervwFetch+0x94
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`opifch2+0x28f4
          oracle`opiall0+0x884
          oracle`opial7+0x390
          oracle`opiodr+0x590
          oracle`ttcpip+0x420
          oracle`opitsk+0x5e8
          oracle`opiino+0x3e8
          oracle`opiodr+0x590
         5110

          libc_psr.so.1`memset+0x140
          oracle`klmalf+0x3c
          oracle`kllcqas+0xb8
          oracle`kcblasm+0x48
          oracle`kxhfNewBuffer+0x270
          oracle`qerhjGetNewBuffer+0x24
          oracle`ksxb1bqb+0xa0
          oracle`kxhrPack+0x534
          oracle`qerhjSplitBuild+0x164
          oracle`qerixtFetch+0x558
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qervwFetch+0x94
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`opifch2+0x28f4
          oracle`opiall0+0x884
         6000

Je suis loin d’être spécialiste Oracle DB, mais d’après les ustack il s’agit d’une "hash join" (kxhf*). La zone mémoire utilisée pour ce genre d’opérations est normalement la zone SQL Work Areas (sous-ensemble de la PGA). Deux pistes sont donc à vérifier : n’y a-t-il pas un problème avec la requête SQL (pb de jointure ?) ou bien n’y a-t-il pas un problème de dimensionnement de la PGA ?

Un petit passage par l’équipe DBA Oracle s’impose…

Epilogue : en recherchant dans l’historique du monitoring, le problème de l’agent Grid provenait aussi de cette base. Bizarre non !? Comme l'a souligné Eric G. dans son commentaire sur la 1er partie, si un élément de surveillance (ici l'agent Grid) pose problème, il doit y avoir un autre problème. Pour cette fois c'est exact...