Solaris mon amour

Petit compte rendu sur un problème de performance que je viens de rencontrer sur un serveur Solaris Sparc avec une base de donnée Oracle.  Le contexte étant le suivant : temps de réponse dégradés suite au reboot du serveur. Bien entendu, aucun changement entre les deux reboot et pourtant l'application fonctionne moins bien qu'avant.

Commençons par le début :

$ vmstat 1 60

 kthr      memory            page            disk          faults      cpu
 r b w   swap  free  re  mf pi po fr de sr s7 s8 s9 s1   in   sy   cs us sy id
 2 2 0 153281392 104614544 4824 7797 16312 457 457 0 0 6 2 0 0 12173 125078 25167 18 9 73
 4 1 0 110702776 64484544 8681 26172 36014 0 0 0 0 0 0 0 0 28270 284267 39452 51 45 4
 27 2 0 110701000 64466128 8187 25244 33717 0 0 0 0 0 0 0 0 30699 317983 40125 56 43 0
 58 4 0 110655752 64437344 6890 35606 35200 0 0 0 0 0 0 0 0 29945 270086 39936 51 46 4
 81 2 0 110652760 64419824 2422 4687 21878 0 0 0 0 0 0 0 0 19933 146223 21668 56 42 2
 68 1 0 110640232 64442472 3117 7019 36429 0 0 0 0 0 0 0 0 17947 153021 21306 56 40 4
 82 2 0 110673872 64459640 3740 19469 15517 0 0 0 0 0 0 0 0 17143 197402 23112 55 45 0
 53 1 0 110817840 64541056 16751 85478 37213 0 0 0 0 13 0 0 0 32290 400389 43440 50 49 2
 27 1 0 110804904 64526728 9514 25054 29034 0 0 0 0 24 24 24 24 32222 362887 43524 57 41 2
 22 3 0 110760264 64497288 8110 10600 27836 0 0 0 0 10 24 24 24 33012 368583 46368 54 42 4
 46 1 0 110219560 64480488 5238 9330 16615 0 0 0 0 24 24 24 24 33111 293475 41391 54 45 1
 31 2 0 109691888 64462816 6337 5855 35649 0 0 0 0 24 24 24 24 32564 324041 41930 51 47 3
 8 1 0 110828328 64515976 7183 15999 60116 7 0 0 0 24 24 24 24 30930 363314 48875 55 37 8
 4 3 0 110738808 64452664 4294 4912 33406 0 0 0 0 24 24 24 24 25878 284752 40035 49 43 9

[...]

La runqueue est quelque peu remplie, vous ne trouvez pas ? Normalement l'utilisation système de ce serveur avoisine les 15%. Actuellement nous consommons plus du double. Bizarre !?

En détaillant un peu plus l'utilisation par cpu, j'obient cela :

$ mpstat 1 60

CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0  130   2 3928   219    8   16   18    5  152    0    68   36  64   0   0
  1   52  17 668688   152   17  514   84  102  119    0  2700   19  78   0   3
  2  123  23 875479    80   11  190   41   37  273    0   835   20  78   0   2
  3   67  10 5639   186   19  596  108  171 2739    2  4200   45  50   0   5
  4   82   0 2238   359   10  715  278  131  315    0  4078   47  52   0   1
  5  106   0 3470   191   16  325  120   91  170    1  1498   46  53   0   1
  6   81   0 6341   893   24 2110  739  410  174    0 10915   72  25   0   2
  7   48   2 4116   198   16  378  103   90  139    0  1809   20  78   0   2
  8   30   0 1686   103   18  776   40  128 2272    0  6072   70  20   0  10
  9   77   1 2085   106   22  486   32  110 4239    1  5263   35  48   0  17
 10   57   1  830   119   25 1760   41  111 1146    1 11804   56  33   0  11
 11   50   0 39677   142   40  602   35  125   93    0  3952   67  15   0  18
 12   82   0 3574   156   15  607   72  143  298    1  3154   36  49   0  15
 13  118   0 1263    96   25  174   37   60  251    0  1072   47  49   0   4
 14   66   0  992   146   16  600   57  125   75    0  3470   66  12   0  22
 15   53   0  330    87   11  448   12   38   96    0  2328   30  57   0  12
 16   57   4 7363   318   36 1543  147  431  124    0  7300   52  24   0  25
 17   38   2 10889 10088 9791 1366  142  389  306    0  5889   20  59   0  20
 18   61   2 4960   251   33 1051  115  327  119    0  5081   49  32   0  20
 19   20   1 4050   235   22 1149  110  281  153    0  5047   28  49   0  23
 20   69   0 189652   226   22  579  131  155  224    0  3525   32  61   0   6
 21   12   1 1361611    57   16   27    4   13   96    0   131    4  95   0   1
 22   88   1 5381   423   38 1049  259  285  601    0  6239   60  30   0  10
 23  144   1 5722   374   40  899  223  246 2358    2  6196   41  50   0   8
512   33   2 17331    65   10  102   22   31  499    0   923   12  86   0   2
513   33  19 120216   279   22  717  143  170  106    0  3107   43  55   0   2
514   53  20 14957   582   29 2035  398  480  215    1  9802   46  43   0  11
515    5  13 2871  1303 1218  139   24   32 2545    0   952    6  93   0   1
516   57   0 4672   243   14  475  175  110  170    0  2339   42  57   0   1
517   83   0 2163  1314 1250   23    5    3   84    0    86   25  75   0   0
518  106   1 8336  1001   25 2445  863  415  231    2 11656   65  32   0   3
519   56   0 5720   819   25 1905  655  415  229    1  9969   61  38   0   2
520   45   0 3534   139   36  411   28  141  139    0  1675   43  28   0  29
521   27   2 4369   167   37  677   27  149  184    0  2423   31  24   0  45
522   49   0 2994   128   27  644   20  114  143    0  2822   44  20   0  36
523   52   0 5220   176   27  819   56  151 2977    1  6423   25  38   0  37
524  172   1  310    55    8  304   10   27  233    0  1564   55  32   0  13
525   73   2 1535   123   13  597   46  115   86    0  3898   64  22   0  14
526   77   1 3821   242   29 1059   94  225  202    0  5572   50  28   0  22
527   52   1 2318   234   25 1106   87  234 1026    0  4908   39  25   0  36
528   59   0 4609   248   33 1145   98  285  164    0  5014   38  36   0  26
529   25   0 11442   341   41 1818  149  454   97    0  8854   37  31   0  32
530   33   0  553    81   10    4    5    1   48    0     0   34  66   0   0
531   51   1 6084   393   50 1754  172  468  113    0  7707   43  21   0  36
532   30   0 700781   139   12  263   85   65  135    0  1747   30  68   0   2
533   59   2 368218   183   29  394   73   95  252    0  2593   31  65   0   4
534  250   2 150619   255   32  685  145  228 2420    1  3932   39  59   0   2
535  108   4 906001   134   20  360   59  104  215    0  1804   24  72   0   4

[...]

Le nombre de smtx est anormalement haut. Regardons avec Dtrace ce qui se passe en mode kernel :

# ./hotkernel

Sampling... Hit Ctrl-C to end.
^C

FUNCTION                        COUNT   PCNT
genunix`rctl_set_tearoff            1   0.0%
[...]

unix`idle                        6622   2.8%
SUNW,UltraSPARC-IV              15472   6.6%
unix`default_lock_delay         18426   7.8%
unix`disp_getwork               44618  19.0%
unix`mutex_delay_default       115315  49.0%

Voilà pourquoi le nombre de smtx est élevé. Le temps d'utilisation kernel provient essentiellement de mutex. Voyons qui les génèrent :

# dtrace -n 'profile:::profile-1001hz /arg0/ { @[func(arg0), execname] = count(); }'

[...]

  SUNW,UltraSPARC-IV+`gettick      oracle            5062
  unix`mutex_enter                 oracle            6222
  unix`mutex_delay_default         svc.startd        6768
  unix`kcage_cageout               pageout           8347
  unix`mutex_delay_default         tnslsnr           8811
  unix`page_numtopp_nolock         pageout           9325
  unix`generic_idle_cpu            sched             9829
  unix`idle                        sched            76849
  unix`default_lock_delay          oracle           96305
  unix`disp_getwork                sched           275834
  unix`mutex_delay_default         oracle          573610

Il s'agit des process Oracle. L'analyse de la stack() peut nous en dire un peu plus :

# dtrace -n 'profile:::profile-1001hz /arg0 && execname == "oracle"/ \
{ @[stack()] = count(); } tick-60s { trunc(@,10); exit(0); }'
 

dtrace: description 'profile:::profile-1001hz ' matched 2 probes
CPU     ID                    FUNCTION:NAME
 16  85099                        :tick-60s

[...]
              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_tlb_range_demap+0x88
              unix`hat_unload_callback+0x7dc
              genunix`segvn_unmap+0x28c
              genunix`as_unmap+0xf0
              genunix`munmap+0x78
              unix`syscall_trap+0xac
             5736
[...]
              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_size_tsb+0x4
              unix`sfmmu_check_page_sizes+0x17c
              unix`hat_do_memload+0xf4
              genunix`segvn_faultpage+0x560
              genunix`segvn_fault+0xbf0
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
             7342

              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_size_tsb+0x4
              unix`sfmmu_check_page_sizes+0x17c
              unix`hat_unload_callback+0x898
              genunix`segvn_unmap+0x28c
              genunix`as_unmap+0xf0
              mm`mmsegmap+0xa8
              genunix`cdev_segmap+0x60
              specfs`spec_char_map+0x104
              specfs`spec_map+0x94
              genunix`fop_map+0x40
              genunix`smmap_common+0x3ac
              genunix`smmap64+0x80
              unix`syscall_trap+0xac
             8367

              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_tlb_range_demap+0x88
              unix`hat_unload_callback+0x7dc
              genunix`anon_private+0x20c
              genunix`segvn_faultpage+0x7d4
              genunix`segvn_fault+0xbf0
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
            12659

              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_size_tsb+0x4
              unix`sfmmu_check_page_sizes+0x17c
              unix`hat_do_memload+0xf4
              genunix`segvn_faultpage+0x32c
              genunix`segvn_fault+0xbf0
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
            27669

              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_tsbmiss_exception+0x6c
              unix`utl0+0x4c
            98775

Un des avantages de l'ISM est de diminuer l'impact sur les tables TLB/TSB. Au vu des appels, il semble que cela soit le contraire. L'appel à la fonctions sfmmu_check_page_sizes() est assez étrange : normalement un segment ISM utilise des larges de 4Mo sur Sparc. Alors pourquoi rechercher une taille de page ?

En parcourant le code source d'Opensolaris pour la fonction sfmmu_tsbmiss_exception() on peut lire cela :

/*
* Handle exceptions for low level tsb_handler.
*
* There are many scenarios that could land us here:
*
* If the context is invalid we land here. The context can be invalid
* for 3 reasons: 1) we couldn't allocate a new context and now need to
* perform a wrap around operation in order to allocate a new context.
* 2) Context was invalidated to change pagesize programming 3) ISMs or
* TSBs configuration is changeing for this process and we are forced into
* here to do a syncronization operation. If the context is valid we can
* be here from window trap hanlder. In this case just call trap to handle
* the fault.
*
[...]

Le cas 3 est assez surprenant : un changement de configuration ISM pour un process donné ? Vérifions un peu le mapping mémoire du segment ISM :

# pmap -xs 5514 | more

5514:   ora_pmon_XXXX01
         Address   Kbytes     RSS   Anon   Locked Pgsz Mode   Mapped File
0000000100000000    73728   73728      -        -   4M r-x--  oracle
0000000104800000     8192    8192      -        -    - r-x--  oracle
0000000105000000    20480   20480      -        -   4M r-x--  oracle
[...]

0000000380000000     8192    8192      -     8192   4M rwxsR  [ ism shmid=0x3 ]
0000000380800000    16384   16384      -    16384    - rwxsR  [ ism shmid=0x3 ]
0000000381800000    16384   16384      -    16384   4M rwxsR  [ ism shmid=0x3 ]
0000000382800000     4096    4096      -     4096    - rwxsR  [ ism shmid=0x3 ]
0000000382C00000    20480   20480      -    20480   4M rwxsR  [ ism shmid=0x3 ]
0000000384000000     4096    4096      -     4096   8K rwxsR  [ ism shmid=0x3 ]
0000000384400000    36864   36864      -    36864   4M rwxsR  [ ism shmid=0x3 ]
0000000386800000       16      16      -       16    - rwxsR  [ ism shmid=0x3 ]
0000000386804000        8       8      -        8   8K rwxsR  [ ism shmid=0x3 ]
0000000386806000        8       8      -        8    - rwxsR  [ ism shmid=0x3 ]
0000000386808000       24      24      -       24   8K rwxsR  [ ism shmid=0x3 ]
000000038680E000       32      32      -       32    - rwxsR  [ ism shmid=0x3 ]
0000000386816000       16      16      -       16   8K rwxsR  [ ism shmid=0x3 ]
000000038681A000        8       8      -        8    - rwxsR  [ ism shmid=0x3 ]
[...]
000000038683A000        8       8      -        8   8K rwxsR  [ ism shmid=0x3 ]
000000038683C000       24      24      -       24    - rwxsR  [ ism shmid=0x3 ]
0000000386842000       16      16      -       16   8K rwxsR  [ ism shmid=0x3 ]
0000000386846000        8       8      -        8    - rwxsR  [ ism shmid=0x3 ]
0000000386848000        8       8      -        8   8K rwxsR  [ ism shmid=0x3 ]

[...]

Quelque chose cloche !! Pour le même segment ISM nous avons une multitude de pages de tailles différentes mais surtout l'allocation du segment ISM est complètement fragmentée. Les sessions Oracle perdent un temps important dans la gestion de mémoire ISM. L'origne reste cependant inconnu !

L'ouverture d'un call au support Oracle confirme bien cette analyse (merci Alain). Cependant rien de bien précis concernant l'origine. Lors d'une activitée mémoire soutenue sur un serveur, ce bug peut se produire mais dans notre cas le serveur venait de rebooter. S'agissant d'une base Oracle 10.2.0.4, l'option NUMA est activée. Du coup le segment ISM est découpé entre les différents lgrp disponibles sur le serveur. La recherche de page par sous segment ISM lors de l'activation du NUMA peut poser un peu plus de problème (cela fonctionnait avant non ?). La taille de l'ARC peut aussi influencer lors de la recherche des pages pour la création de l'ISM. Mystère...

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

• Chapitre 12 "Hardware Address Translation" dans Solaris Internals
• Chapitre 16 "Support for NUMA and CMT Hardware" dans Solaris internals
• Architecture NUMA dans Solaris (10 et 11)
• ISM sous Solaris 10x86 (Partie 1, Partie 2 et Workarounds)
• Optimizing Applications with Large Working Sets in Solaris 8 and 9
• Opensolaris code : hat_sfmmu.c
• Opensolaris code : hat.h