Discussion :

[Ikebukuro]

Bonjour amis DBA,

J'ai lu de la part de Franck Pachot un excellent article sur comment lire un rapport AWR à cette adresse : https://www.doag.org/formes/pubfiles...esentation.pdf.

Mais, vous me connaissez, il y a plusieurs points que je ne comprends pas et j'aimerais qu'on me les explique.
Je préfère poster ici plutôt que de te contacter par mail Franck car je pense que ça peut intéresser beaucoup de monde.

1) Page 12 je vois que la somme de la colonne %DB TIME dépasse 100%. Est-ce parce que la ligne DB CPU est comptée deux fois, une fois seule et une fois incluse dans toutes les actions listées? Par exemple "sql execute elapsed time" représente 4358 s mais il doit y avoir une partie de 608 s du DB CPU dans ces 4358 s? Si oui, est-ce qu'on doit enlever la ligne DB CPU de cette partie pour avoir une "vraie" répartition du DB Time par opérations?

2) Page 16 il est marqué que le host a 8 CPUs et 4 Cores. C'est normal d'avoir moins de cores que de CPU? Un CPU n'est pas au minimum mono-core?

3) Page 26 je ne comprends pas le calcul du DB CPU load. Que représente le 0.65? Par seconde écoulée, le CPU travaille 0.65 secondes ou c'est pour les 8 CPUs?

4) Page 28 que représente le pourcentage 95.1 de la colonne %Total pour la première requête? Cette requête, à un instant t, a pris 95.1% de l'activité d'un CPU? de l'activité de tous les CPU?
Quand il y a deux requêtes, l'une avec 95.1% et l'autre avec 93.7% du %Total, ça signifie que ces deux requêtes se sont exécutées et terminées à deux instants différents et chacune a monopolisé les CPU?

5) Page 35 il est marqué que 5 000 commits attendent LGWR. D'où sort ce nombre? C'est en référence aux 5 676 waits de type log file sync? Si oui, on peut dire que tous les waits de type log file sync sont des commit? J'ai bien vu que la classe était COMMIT mais c'est le lien entre le nombre de waits et le nombre de commit qui serait de 1 pour 1 qui m'interpelle. Pour moi on avait 5 676 évènements d'attente de type log file sync mais peut-être que 100 Commits. A vrai dire je ne m'étais jamais posé la question de comment interpréter ces nombres et c'est donc l'occasion d'y voir plus clair.


Merci pour vos éclaircissements!

[Pomalaix]

C'est agréable d'avoir des questions claires et bien posées !
Voici quelques premiers éléments de réponse.

Q1
La page 12 fait référence au modèle temporel, c'est à dire le découpage du temps passé dans différents types d'activité (temps d'exécution SQL, temps CPU, etc), issu de la vue V$SYS_TIME_MODEL. La subtilité, c'est qu'il ne faut pas cumuler ces temps, car il y a une certaine imbrication de ces différentes rubriques. En particulier, le temps SQL comporte une certaine part de temps CPU.
La doc Oracle précise cette imbrication, j'ajouterai le lien dès que je l'aurai retrouvé.

Q2
CPU ici indique le nombre de CPU logiques, tenant compte du mode multithread.
On a ici un CPU physique à 4 coeurs physiques, chaque coeur émulant 2 processeurs. Soit 8 CPU logiques au total.

Q3
L'objectif est de déterminer quelle proportion de CPU l'instance utilise, par rapport à la puissance CPU totale que la machine peut délivrer.
Le rapport AWR couvre une période de 15,64 minutes (soit 938 secondes), et le temps CPU est de 608 secondes. Si on avait un seul CPU, il aurait été sollicité à 65% de sa capacité.
Ici Franck semble considérer que la véritable capacité d'un processeur dépend de son nombre de coeurs (4) et non de son nombre de threads (les fameux 8 CPU logiques).
Donc on divise par 4 pour dire que l'équipement CPU de la machine a été sollicité à 16% de ses capacités.

[Ikebukuro]

Merci pour tes réponses Pomalaix, c'est déjà plus clair dans ma tête

[Pomalaix]

Voici la suite de mes commentaires.

Q4
On est dans la rubrique "SQL ordered by CPU Time".
La colonne "%Total" est censée indiquer, pour chaque requête de cette rubrique, quelle part sa consommation CPU représente dans la charge CPU totale consommée par l'instance sur la période traitée par le rapport AWR.
Le fait qu'on ait 95,1 et 93,7 est pour moi une anomalie, car le total devrait atteindre 100%.

Mais il est essentiel, quand on analyse un rapport AWR, de bien regarder ce que dit l'en-tête de cette rubrique, (et qui n'est pas visible à la page 28).
On trouve une mention du genre "Captured SQL account for 99.5% of Total CPU Time (s): 14,692", et parfois ce pourcentage est très inférieur ou très supérieur à 100%, ce qui fausse l'interprétation.

Q5
La doc indique que l'attente "log file sync" est relative aux commits, et donc les 5000 évoqués sont un arrondi des 5676.
Les écritures dans les redo logs correspondant au corps de la transaction (sans le commit donc) ne génèrent pas d'attente "log file sync".
A vrai dire, elles ne semblent même générer aucune attente identifiée, ce qui est assez surprenant.

Test à faire pour s'en convaincre :
Mettre la session en trace et faire un UPDATE unique sur un gros volume de données (par exemple 1 G d'un coup), dans une base où chaque redo log est assez gros pour supporter la transaction complète.
Examiner le fichier de trace qui en résulte : bien qu'on ait en toute vraisemblance écrit des dizaines voire des centaines de fois dans les fichiers redo logs, on ne trouve aucun événement d'attente relatif à des écritures quelconques (voir la partie en rouge ci-dessous).

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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
32
33
update obj2
set object_id=object_id+1
where rownum <3000000


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.04          0        154          0           0
Execute      1     69.76      75.69      71168    3138528    3349252     2999999
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     69.77      75.74      71168    3138682    3349252     2999999

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 5  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  UPDATE  OBJ2 (cr=3117345 pr=60184 pw=0 time=0 us starts=61719790)
   6745593    6745593    6745593   COUNT STOPKEY (cr=3138462 pr=70787 pw=0 time=0 us starts=41181644)
   6745593    6745593    6745593    TABLE ACCESS FULL OBJ2 (cr=3138462 pr=70787 pw=0 time=38569 us starts=39686318 cost=38569 size=134700527 card=10361579)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file scattered read                       1227        0.01          1.68
  Disk file operations I/O                        1        0.00          0.00
  db file sequential read                     25553        0.01          5.02
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

[pachot]

Bonjour,

Très bonne idée ces questions

Je n'ai pas grand chose à rajouter à Q1 Q2 Q3 par rapport à ce que Pomalais a dit.


Q4: 95.1% du temps est passé sur l'appel PL/SQL et 93.7% du temps est passé sur le SQL. En fait, le PL/SQL exécute la requête. Le temps passé dans le SQL et compté à la fois pour la requête, et pour l'exécution du PL/SQL. C'est pas toujours intuitif. En fait Oracle met des compteurs (à l'appel d'une procédure, à l'exécution d'une requête...) et parfois les uns couvrent aussi les autres.


Q5: 'log file sync' est l'évènement d'attente d'une session qui attend que le redo log soit sur disque. Il n'y a qu'au commit que c'est nécessaire (car seule les transactions commitées doivent être récupérées lors d'un crash).
Donc en général le nombre de 'log file sync' est le nombre de commit. Je ne vois pas dans quels cas il pouraît y avoir plus de 'log file sync' que de commits. Il n'y a qu'au commit qu'il faut s'assurer de la synchronisation sur disque.
Effectivement, 5000 ici est l'arrondi de 5676. ce sont des 'commit wait'. Mais il y a des commits qui n'attendent pas ('commit nowait') donc on peut avoir plus de commits que de 'log file sync'. C'est d'ailleurs le cas ici, la page 37 montre 16296 commits. En fait environ 1 commit sur 3 attend sur 'log file sync' ici (5676/16296). C'est une optimisation de PL/SQL qui fait des 'commit nowait' implicitement tant qu'il n'y a pas de retour à l'utilisateur. Donc à chaque appel de la procédure, il y a peut-être 3 commits dans le code PL/SQL. Mais PL/SQL ne fait un 'wait' que pour le dernier, lorsqu'il dit au client: "c'est commité" car là il doit s'assurer que le redo est sur un support persistent. Les commits intermédiaires peuvent être perdus en cas de crash, vu qu'on a dit à personne que c'était commité.

Cordialement,
Franck.

[Ikebukuro]

Merci à vous deux pour ces précisions, ça m'aide à progresser


Concernant la Q4, effectivement dans l'exemple il y a un module JDBC puis le SQL, donc on est bien sur deux "entités" différentes donc on a 99% sur deux parties distinctes.

J'ai une autre question :
Q6 : page 13 il est marqué "Always check if you have all statements".
Voici un exemple de prod où ce n'est pas le cas. Concrètement ça veut dire quoi? Que seul un tiers des requêtes SQL de la base se trouve dans le tableau "SQL ordered by Executions"? Si oui, est-ce que les infos pour ces requêtes présentes sont pertinentes?
Est-ce que l'on sait pourquoi 66% des requêtes sont absentes? Est-ce que celles absentes sont les moins exécutées et donc ce n'est pas si grave que ça?

"
SQL ordered by Executions
%CPU - CPU Time as a percentage of Elapsed Time
%IO - User I/O Time as a percentage of Elapsed Time
Total Executions: 1,186,532
Captured SQL account for 34.6% of Total
"

[pachot]

Bonjour,
Captured SQL account for 34.6% of Total
Veut dire que le détail des requêtes ne couvre que 34% du total. Donc on risque de passer à côté du vrai problème.
Les requêtes capturée par le aport AWR sont celles qui soont toujours en shared pool au moment du snaphsot de fin du rapport.
S'il en manque, c'est peut-être que le rapport couvre une période trop large: des requêtes exécutées en début de batch ne sont peut-être plus en cache à la fin.
Ou alors que l'application n'utilise pas de bind variables et lance à chaque fois des requêtes différentes. Elles rentrent et sortent du cache rapidement, et on n'a que les dernières dans le rapport.
Cordialement,
Franck.

[Ikebukuro]

Merci pour ta réponse franck.

[Pomalaix]

... la vue V$SYS_TIME_MODEL. La subtilité, c'est qu'il ne faut pas cumuler ces temps, car il y a une certaine imbrication de ces différentes rubriques. En particulier, le temps SQL comporte une certaine part de temps CPU.
La doc Oracle précise cette imbrication, j'ajouterai le lien dès que je l'aurai retrouvé...

Concernant l'imbrication des temps dans V$SYS_TIME_MODEL, j'ai fini par retomber dessus, par exemple en bas de cette page : https://docs.oracle.com/en/database/...8-0873FA32A5C0
Ce qui est dommage, c'est que l'imbrication présentée n'intègre pas toutes les rubriques présentes dans V$SYS_TIME_MODEL, sachant qu'il y en a de plus en plus à mesure qu'on avance dans les versions d'Oracle.

J'ai aussi retrouvé dans mes archives une requête qui matérialise cette imbrication.

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
---------------------------------------------------
-- SYS_TIME_MODEL indenté
---------------------------------------------------
set linesize 120
set pagesize 100
col stat_name format A80
SELECT LPAD(' ', 2*level-1)||stat_name stat_name, 
       to_char(trunc(value/1e6,2), '999G999G990D99') seconds 
  FROM (
select 0 id, 9 pid, null stat_name, null value from dual union
select decode(stat_name,'DB time',10) id ,
       decode(stat_name,'DB time',0) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'DB time' union
select decode(stat_name,'DB CPU',20) id ,
       decode(stat_name,'DB CPU',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'DB CPU' union
select decode(stat_name,'connection management call elapsed time',21) id ,
       decode(stat_name,'connection management call elapsed time',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'connection management call elapsed time' union
select decode(stat_name,'sequence load elapsed time',22) id ,
       decode(stat_name,'sequence load elapsed time',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'sequence load elapsed time' union
select decode(stat_name,'sql execute elapsed time',23) id ,
       decode(stat_name,'sql execute elapsed time',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'sql execute elapsed time' union
select decode(stat_name,'parse time elapsed',24) id ,
       decode(stat_name,'parse time elapsed',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'parse time elapsed' union
select decode(stat_name,'hard parse elapsed time',30) id ,
       decode(stat_name,'hard parse elapsed time',24) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'hard parse elapsed time' union
select decode(stat_name,'hard parse (sharing criteria) elapsed time',40) id ,
       decode(stat_name,'hard parse (sharing criteria) elapsed time',30) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'hard parse (sharing criteria) elapsed time' union
select decode(stat_name,'hard parse (bind mismatch) elapsed time',50) id ,
       decode(stat_name,'hard parse (bind mismatch) elapsed time',40) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'hard parse (bind mismatch) elapsed time' union
select decode(stat_name,'failed parse elapsed time',31) id ,
       decode(stat_name,'failed parse elapsed time',24) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'failed parse elapsed time' union
select decode(stat_name,'failed parse (out of shared memory) elapsed time',41) id ,
       decode(stat_name,'failed parse (out of shared memory) elapsed time',31) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'failed parse (out of shared memory) elapsed time' union
select decode(stat_name,'PL/SQL execution elapsed time',25) id ,
       decode(stat_name,'PL/SQL execution elapsed time',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'PL/SQL execution elapsed time' union
select decode(stat_name,'inbound PL/SQL rpc elapsed time',26) id ,
       decode(stat_name,'inbound PL/SQL rpc elapsed time',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'inbound PL/SQL rpc elapsed time' union
select decode(stat_name,'PL/SQL compilation elapsed time',27) id ,
       decode(stat_name,'PL/SQL compilation elapsed time',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'PL/SQL compilation elapsed time' union
select decode(stat_name,'Java execution elapsed time',28) id ,
       decode(stat_name,'Java execution elapsed time',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'Java execution elapsed time' union
select decode(stat_name,'repeated bind elapsed time',29) id ,
       decode(stat_name,'repeated bind elapsed time',10) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'repeated bind elapsed time' union
select decode(stat_name,'background elapsed time',1) id ,
       decode(stat_name,'background elapsed time',0) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'background elapsed time' union
select decode(stat_name,'background cpu time',2) id ,
       decode(stat_name,'background cpu time',1) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'background cpu time' union
select decode(stat_name,'RMAN cpu time (backup/restore)',3) id ,
       decode(stat_name,'RMAN cpu time (backup/restore)',2) pid , stat_name, value
  from v$sys_time_model
 where stat_name = 'RMAN cpu time (backup/restore)')
CONNECT BY PRIOR id = pid START WITH id = 0;

Exemple de résultat :

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
STAT_NAME                                                                        SECONDS
-------------------------------------------------------------------------------- ---------------
   background elapsed time                                                                229,74
     background cpu time                                                                   23,38
       RMAN cpu time (backup/restore)                                                       0,00
   DB time                                                                                 44,31
     DB CPU                                                                                 4,11
     connection management call elapsed time                                                0,19
     sequence load elapsed time                                                             0,00
     sql execute elapsed time                                                               8,59
     parse time elapsed                                                                     2,49
       hard parse elapsed time                                                              2,39
         hard parse (sharing criteria) elapsed time                                         0,37
           hard parse (bind mismatch) elapsed time                                          0,00
       failed parse elapsed time                                                            0,00
         failed parse (out of shared memory) elapsed time                                   0,00
     PL/SQL execution elapsed time                                                          0,01
     inbound PL/SQL rpc elapsed time                                                        0,00
     PL/SQL compilation elapsed time                                                        0,08
     Java execution elapsed time                                                            0,00
     repeated bind elapsed time                                                             0,01