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.
