Mardi 20 novembre 2012 2 20 /11 /Nov /2012 22:06

 

Première partie d'une analyse effectuée sur un système Solaris 10 exécutant plusieurs bases de données Oracle. Les symptômes remontés par l'équipe DBA sont les suivants : temps de réponse long sur plusieurs bases. 

 

Un petit vmstat rapide, pour connaitre grossièrement l’utilisation du serveur.

 

# vmstat 5 100
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
9 0 0 10677368 22372512 680 5482 106 0 0 0 0 25 4 4 4 14735 114426 20380 46 27 27
[…]
23 0 0 9135032 22314120 4792 21638 0 0 0 0 0 1 0 0  0 11118 154028 16758 50 50 0
16 0 0 9137544 22315040 5294 23490 0 0 0 0 0 1 0 0  0 11380 153204 18659 48 52 0
17 0 0 9084960 22258160 2177 10563 0 0 0 0 0 1 0 10 10 9922 137140 14022 43 54 3
24 0 0 9179648 22320080 3362 15628 0 0 0 0 0 1 0 0  0 10750 128918 16896 43 57 0
30 0 0 8850312 22046056 288 2054 0 0 0 0 0 1  0  0  0 10807 99560 14018 31 63 6
126 0 0 8853432 22082880 41 616 0 0 0 0 0  1  0  6  6 5752 31932 6774 10 88 2
661 0 0 8923392 22133776 19 197 0 0 0 0 0  0  0  0  0 2263 5386 1704  3 97  0
465 0 0 8991776 22117088 25 287 0 0 0 0 0  1  0  3  3 2453 8860 2140  4 96  0
46 0 0 8953016 22085792 223 1502 0 0 0 0 0 1  0  0  0 5766 38776 7626 13 86 1
63 0 0 8920736 22079448 109 846 0 0 0 0 0  1  0  0  0 6630 52695 9918 15 83 2
67 0 0 9076624 22190944 1054 7254 0 0 0 0 0 1 0  4 20 5746 97461 7816 33 66 0
53 0 0 8993152 22164344 815 6238 0 0 0 0 0 2  0 176 173 7381 138464 13787 34 66 0
154 0 0 8815312 22116736 37 745 0 0 0 0 0  1  0  0  0 5150 54699 8493 15 85 0
168 0 0 8628120 22079000 22 399 0 0 0 0 0  1  0  0  0 3899 23637 5677 8 92  0
355 0 0 8558232 22016008 23 431 0 0 0 0 0  1  0  4  4 3364 14270 3970 6 94  0
130 0 0 8944384 22119872 949 6035 0 0 0 0 0 1 0  0  0 5608 64746 5932 23 77 0
94 0 0 8696336 22046504 73 782 0 0 0 0  0  1  0  4  4 5918 39593 6905 11 89 0
127 0 0 8570488 21995968 53 560 0 0 0 0 0  1  0  0  0 5745 26933 6982 9 91  0
75 0 0 8915344 22101408 531 4554 0 0 0 0 0 1  0  4  4 6366 81465 9546 23 77 0
26 0 0 8900360 22049976 86 1279 0 0 0 0 0  1  0  0  0 8994 95004 14896 28 71 1
36 0 0 8860368 22037360 184 1635 0 0 0 0 0 1  0  0  0 7535 89424 13136 23 77 0
49 0 0 8820896 22127776 22 1026 0 0 0 0 0  1  0  5  5 10203 71434 12679 22 73 5
427 0 0 8719360 22085440 13 157 0 0 0 0 0  1  0 227 205 3164 8480 2555 4 96 0
487 0 0 8812896 22104528 77 717 0 0 0 0 0  1  0  0  0 2769 9668 2381  5 95  0
42 0 0 9051608 22152568 588 4325 0 0 0 0 0 1  0  0  0 7835 82729 11531 30 69 1
151 0 0 9023256 22246008 188 2021 0 0 0 0 0 1 0  4  4 5405 40646 9076 14 86 0
[..]

 

Deux remarques vis-à-vis de ce résultat : d’une part la run queue globale est complètement saturée, d’autre part la répartition user/system est de 1 pour 3. Qu’une utilisation system soit supérieur à une utilisation user ne me choque pas forcément, tout dépend des applications, cependant dans mon cas (bases de données Oracle), ce ratio ne me plait pas.

 

Voyons voir qui utilise tout ce temps kernel.

 

# dtrace -n 'profile-997hz /arg0/ { @[execname] = count(); }'
dtrace: description 'profile-1001hz ' matched 1 probe
^C 
[…]
  pgrep                               156
  nmupm                               164
  dtrace                              166
  emdctl                              195
  check_bnp_proces                    225
  tnslsnr                             638
  fsflush                             846
  sldrm_coll                         1182
  perl                               7639
  sched                              9911
  oracle                            17735
  emagent                           26944

 

Intéressant, le temps system est utilisé majoritairement par l’agent Grid d’Oracle (emagent). Détaillons d’un peu plus près les fonctions du kernel sollicitées.

 

# dtrace -n 'profile-997hz /arg0/ { @[func(arg0)] = count(); }'
dtrace: description 'profile-997hz ' matched 1 probe
^C 
[…]
  unix`bzero                                437
  unix`_resume_from_idle                    446
  genunix`mstate_aggr_state                 448
  genunix`avl_walk                          502
  FJSV,SPARC64-VI`cpu_smt_pause             549
  unix`page_lookup_create                   625
  unix`mutex_exit                           870
  unix`utl0                                 877
  FJSV,SPARC64-VI`cpu_halt_cpu             1311
  unix`page_exists                         1765
  unix`mutex_delay_default                 2801
  FJSV,SPARC64-VI`copyout_more             2934
  unix`page_trylock                        3246
  unix`mutex_enter                         5078

 

Le temps kernel est utilisé principalement à la gestion de lock (mutex). Existe t'il une relation entre ces locks et l’agent Grid ?

 

# dtrace –n ‘lockstat::mutex_enter: { @[execname] = count(); }’
dtrace: description 'lockstat::mutex_enter: ' matched 3 probes
^C
[…]
  dtrace                    34218
  sh                        66256
  fsflush                   104986
  sldrm_hist                186238
  nmupm                     294968
  emdctl                    791171
  sched                     861038
  sldrm_coll               1250578
  tnslsnr                  2617337
  perl                     3111793
  oracle                  13825389
  emagent                 15498584

 

A priori oui, il existe une relation entre la forte utilisation kernel (mutex) et l'agent Grid (mais pas seulement). Analysons d’un peu plus près la stack de l'agent Grid au moment des locks.

 

# dtrace –n ‘lockstat::mutex_enter: /execname == “emagent”/ { @[stack()] = count() } \
tick-60s { trunc(@,5); exit(0); }’
dtrace: description 'lockstat::mutex_enter: ' matched 3 probes
[…]
              unix`page_trylock+0x38
              unix`page_trylock_cons+0xc
              unix`page_get_mnode_freelist+0x19c
              unix`page_get_replacement_page+0x30c
              unix`page_claim_contig_pages+0x178
              unix`page_geti_contig_pages+0x618
              unix`page_get_contig_pages+0x160
              unix`page_get_freelist+0x430
              unix`page_alloc_pages+0x110
              genunix`anon_map_privatepages+0xa4
              genunix`anon_map_getpages+0xad0
              genunix`segvn_fault_anonpages+0x32c
              genunix`segvn_fault+0x530
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0x910
              unix`ktl0+0x48
              genunix`poll_common+0x5c8
              genunix`pollsys+0xf8
              unix`syscall_trap32+0xcc
           114469

              unix`page_trylock+0x38
              unix`page_trylock_contig_pages+0x94
              unix`page_geti_contig_pages+0x5f4
              unix`page_get_contig_pages+0x160
              unix`page_get_freelist+0x430
              unix`page_alloc_pages+0x110
              genunix`anon_map_privatepages+0xa4
              genunix`anon_map_getpages+0xad0
              genunix`segvn_fault_anonpages+0x32c
              genunix`segvn_fault+0x530
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
           125499 

              unix`page_trylock+0x38
              unix`page_trylock_cons+0xc
              unix`page_get_mnode_freelist+0x19c
              unix`page_get_replacement_page+0x30c
              unix`page_claim_contig_pages+0x178
              unix`page_geti_contig_pages+0x618
              unix`page_get_contig_pages+0x160
              unix`page_get_freelist+0x430
              unix`page_alloc_pages+0x110
              genunix`anon_map_privatepages+0xa4
              genunix`anon_map_getpages+0xad0
              genunix`segvn_fault_anonpages+0x32c
              genunix`segvn_fault+0x530
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
         17880348

 

En observant rapidement le résultat, on constaque que les locks proviennent d’allocation de pages mémoire !? Si on regarde un peu plus dans le détail, on constate quelque chose d’intéressant : le système tente d’allouer des pages mémoire de manières contiguës (fonction page_get_contig_pages). Il s’agit « normalement » d’une optimisation du système Solaris (évite la fragmentation mémoire, impact sur les mécanismes de translation d'adresses). Dans notre cas, cela semble pénaliser le fonctionnement du système.

 

Une petite explication du Support Oracle Solaris sur ce sujet.

 

The "Large Page Out Of the Box" (LPOOB) feature of the Oracle Solaris 10 memory management, first implemented in Oracle Solaris 10 1/06 (Update 1), can lead to performance problems when the system runs out of large chunks of free contiguous memory. This is because the Oracle Solaris 10 kernel by default will attempt to relocate memory pages to free up space for creating larger blocks of contiguous memory. Known symptoms are high %system CPU time in vmstat, high number of cross calls in mpstat, and Oracle calling mmap(2) to /dev/zero for getting more memory.

 

Il est possible de changer ce type de fonctionnement par défaut (on alloue des pages sans ce soucier de l’emplacement contiguës de celles-ci) en modifiant le paramètre kernel pg_contig_disable. Petite remarque : ce paramètre influence uniquement la mémoire PGA de la base de données Oracle (pas d'influence sur la mémoire SGA).

 

Testons rapidement la modification de ce paramètre sur notre système.

 

# mdb –kw
Loading modules: [ unix genunix specfs dtrace zfs sd mpt px ssd fcp fctl qlc mpt_sas ip hook neti sctp arp usba md cpc random crypto fcip logindmux ptm ufs sppp nfs lofs ipc ]
> pg_contig_disable/X
pg_contig_disable:
pg_contig_disable:              0              
> pg_contig_disable/W 1
pg_contig_disable:              0               =       0x1
> pg_contig_disable/X
pg_contig_disable:
pg_contig_disable:              1
> ::exit

 

# vmstat 5 30
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 10645464 22354816 680 5481 104 0 0 0 0 25 4 4 4 14733 114929 20416 46 27 27
8 0 0 8071552 21199136 865 6976 0 0 0 0 0  1  0  0  0 14630 138815 26507 54 45 1
13 0 0 7960624 21162752 898 6521 0 0 0 0 0 1  0  0  0 12945 115064 23913 46 54 0
6 0 0 8017848 21150384 657 6674 0 0 0 0 0  1  0  0  0 14140 128303 25855 54 45 0
8 0 0 7965472 21129192 704 6301 0 0 0 0 0  1  0  7  7 15013 130409 25934 55 44 1
39 0 0 7908096 21067600 678 6408 0 0 0 0 0 1  0  0  0 14324 113376 26509 46 54 0
11 0 0 7936560 21059424 717 6684 0 0 0 0 0 1  0  0  0 13445 124844 23464 52 47 1
4 0 0 7860976 20987424 880 6478 0 0 0 0 0  1  0  0  0 14499 129461 26395 53 46 0
13 0 0 7881128 21004464 660 6154 0 0 0 0 0 2  0  0  0 15000 124875 25740 50 48 2
5 0 0 7824424 20954160 709 5939 0 0 0 0 0  1  0  0  0 14831 138457 28836 54 45 1
9 0 0 7774880 20924240 1080 8938 0 0 0 0 0 1  0  5  5 13451 126547 24567 50 49 0
[…]

 

D'une part, la run queue globale est beaucoup moins saturée et, d'autre part, la répartition user/system semble s'être équilibrée. Reste à savoir si la consomation system provient toujours de l'agent Grid ?

 

# dtrace -n 'profile-997hz /arg0/ { @[execname] = count(); }'
dtrace: description 'profile-997hz ' matched 1 probe
^C
[…]
  nmupm                        439
  init                         541
  perl                        1158
  fsflush                     1165
  collectd                    1679
  sldrm_coll                  2630
  emagent                     4264
  tnslsnr                    10857
  sched                      13906
  oracle                    105798

 

La modification du paramètre pg_config_disable semble améliorer le fonctionnement du serveur. L'agent Grid utilise beaucoup moins les ressources system (une bonne chose). Les temps de réponses sont meilleurs mais... Mais voilà : le temps system reste anormalement élevé pour un serveur hébergeant des bases Oracles.

 

Suite de l'analyse lors d'un prochain article.

 

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

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

Calendrier

Décembre 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 31        
<< < > >>
Créer un blog gratuit sur over-blog.com - Contact - C.G.U. - Signaler un abus - Articles les plus commentés