Autotrace : liste des statistiques différentes selon qu'on utilise SQL*Plus, SQLcl, Toad ou SQL Developer
Introduction
La commande AUTOTRACE permet d'afficher, pour un ordre SQL, un plan d'exécution mais aussi des statistiques relatives à cet ordre. Là où la situation se complique, c'est qu'Oracle, et les éditeurs tiers, proposent des stats différentes selon les outils utilisés; c'est ce que nous allons voir.
Points d'attention
Aucun.
Base de tests
Une base Oracle 12 avec au moins sqlcl installé.
Exemples
============================================================================================
Stats Autotrace avec SQL*Plus
============================================================================================
Etape 1 : créer la table de test.
SQL> create table zz01(id number primary key, name varchar2(50 CHAR), date_deb date);
Table creee.
SQL> insert into zz01 select rownum, 'PARKER' ||to_char(rownum), sysdate from dual connect by level < 10001;
10000 lignes creees.
SQL> commit;
Validation effectuee.
Activation de l'autotrace : en sortie, on a la liste classique des onze stats Oracle. C'est cette liste qui fait référence, ne serait-ce que si on fait une recherche AUTOTRACE sur Google.
SQL> set autotrace on
SQL> select * from zz01 where rownum < 6;
ID NAME DATE_DEB
---------- -------------------------------------------------- --------
1 PARKER1 04/01/19
2 PARKER2 04/01/19
3 PARKER3 04/01/19
4 PARKER4 04/01/19
5 PARKER5 04/01/19
Plan d'execution
----------------------------------------------------------
Plan hash value: 2489330668
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 5 | 245 | 2 (0)| 00:00:01 |
|* 1 | COUNT STOPKEY | | | | | |
| 2 | TABLE ACCESS FULL| ZZ01 | 10000 | 478K| 2 (0)| 00:00:01 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(ROWNUM<6)
Note
-----
- dynamic statistics used: dynamic sampling (level=2)
Statistiques
----------------------------------------------------------
8 recursive calls
0 db block gets
93 consistent gets
0 physical reads
0 redo size
846 bytes sent via SQL*Net to client
552 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
5 rows processed
============================================================================================
Stats Autotrace avec SQLcl
============================================================================================
Utilisons maintenant SQLcl, le "successeur" de SQL*Plus apparu avec Oracle 12.
Euh, que dire? J'en reste sans voix...
- 87 statistiques différentes
- il manque les stats suivantes dispos sous SQL*Plus :
- sorts (disk)
- rows processed
Certaines me semblent incompréhensibles : qu'en pensez-vous?
- CCursor + sql area evicted
- HSC Heap Segment Block Changes
- shared hash latch upgrades - no wait
- ...
SQL> set autotrace on
Autotrace Enabled
Shows the execution plan as well as statistics of the statement.
SQL> select * from zz01 where rownum < 6;
ID NAME DATE_DEB
---------- -------------------------------------------------- ---------
815 PARKER815 05-JAN-19
816 PARKER816 05-JAN-19
817 PARKER817 05-JAN-19
818 PARKER818 05-JAN-19
819 PARKER819 05-JAN-19
Explain Plan
-----------------------------------------------------------
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 2489330668
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 5 | 620 | 2 (0)| 00:00:01 |
|* 1 | COUNT STOPKEY | | | | | |
| 2 | TABLE ACCESS FULL| ZZ01 | 10000 | 1210K| 2 (0)| 00:00:01 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(ROWNUM<6)
Note
-----
- dynamic statistics used: dynamic sampling (level=2)
Statistics
-----------------------------------------------------------
1 ASSM cbk:blocks examined
1 ASSM gsp:L1 bitmaps examined
1 ASSM gsp:L2 bitmaps examined
1 ASSM gsp:get free block
11 CCursor + sql area evicted
3 CPU used by this session
8 CPU used when call started
24 DB time
3 HSC Heap Segment Block Changes
188 Requests to/from client
188 SQL*Net roundtrips to/from client
5 blocks cleaned out using minact
627 buffer is not pinned count
2 buffer is pinned count
3600 bytes received via SQL*Net from client
105942 bytes sent via SQL*Net to client
318 calls to get snapshot scn: kcmgss
3 calls to kcmgas
190 calls to kcmgcs
81920 cell physical IO interconnect bytes
87 cluster key scan block gets
76 cluster key scans
6 commit cleanouts
6 commit cleanouts successfully completed
1054 consistent gets
338 consistent gets examination
336 consistent gets examination (fastpath)
1054 consistent gets from cache
716 consistent gets pin
709 consistent gets pin (fastpath)
3 cursor authentications
21 db block changes
17 db block gets
17 db block gets from cache
13 db block gets from cache (fastpath)
3 deferred (CURRENT) block cleanout applications
25 enqueue releases
25 enqueue requests
303 execute count
20 file io service time
39978 file io wait time
10 free buffer requested
3 immediate (CURRENT) block cleanout applications
101 index fetch by key
116 index scans kdiixs1
8773632 logical read bytes from cache
1 messages sent
529 no work - consistent read gets
207 non-idle wait count
4 non-idle wait time
305 opened cursors cumulative
1 opened cursors current
23 parse count (hard)
35 parse count (total)
2 parse time cpu
9 parse time elapsed
10 physical read IO requests
81920 physical read bytes
10 physical read total IO requests
81920 physical read total bytes
10 physical reads
10 physical reads cache
1 process last non-idle time
699 recursive calls
3 recursive cpu usage
12 redo entries
3172 redo size
1154 redo synch time (usec)
24 redo synch time overhead (usec)
1 redo synch time overhead count ( 2ms)
1 redo synch writes
1 redo write info find
12 rows fetched via callback
293 session cursor cache hits
1071 session logical reads
1 shared hash latch upgrades - no wait
77 sorts (memory)
2306 sorts (rows)
31 sql area evicted
109 table fetch by rowid
222 table scan blocks gotten
18525 table scan disk non-IMC rows gotten
18530 table scan rows gotten
89 table scans (short tables)
708 undo change vector size
4 user I/O wait time
189 user calls
[EDIT 13/03/2021]
Deux ans après avoir écrit cet article, j'ai installé une Oracle v19 sur mon PC et, à ma surprise, les stats affichées ne sont plus les mêmes. Premièrement elles sont beaucoup moins nombreuses (je pense que les retours de la v12 ont été négatifs car 87 stats... c'est impossible de les comprendre toutes) mais elles diffèrent aussi en nombre selon que vous interrogez le dictionnaire de données ou une table applicatives avec un segment et donc des blocs à charger en mémoire.
SQL> select banner from v$version;
BANNER
--------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
SQL> set autotrace on
Autotrace Enabled
Shows the execution plan as well as statistics of the statement.
Je fais un SELECT sur dual pour voir les stats. Il y en a 22 et, surprise, rien sur les blocs lus en mémoire (Consistent gets).
SQL> select count(*) from dual;
COUNT(*)
----------
1
Explain Plan
-----------------------------------------------------------
PLAN_TABLE_OUTPUT
----------------------------------------------------------------
Plan hash value: 3910148636
-----------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-----------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 2 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | FAST DUAL | | 1 | 2 (0)| 00:00:01 |
-----------------------------------------------------------------
Statistics
-----------------------------------------------------------
1 CPU used by this session
2 CPU used when call started
3 DB time
44 Requests to/from client
44 SQL*Net roundtrips to/from client
1291 bytes received via SQL*Net from client
85684 bytes sent via SQL*Net to client
2 calls to get snapshot scn: kcmgss
2 calls to kcmgcs
1 cursor authentications
1 enqueue releases
1 enqueue requests
2 execute count
56 non-idle wait count
2 opened cursors cumulative
1 opened cursors current
1 parse count (hard)
2 parse count (total)
1 recursive calls
1 sorts (memory)
2010 sorts (rows)
45 user calls
Je refais un SELECT mais cette fois sur une table contenant des données, car le précédent SELECT interrogeait seulement le dictionnaire de données, la table DUAL n'a pas de segment donc de bloc de données sur le disque dur. Et là, on passe de 22 stats à 26 avec 4 stats sur les Consistent Gets en plus.
SQL> select count(*) from REGIONS;
COUNT(*)
----------
4
Explain Plan
-----------------------------------------------------------
PLAN_TABLE_OUTPUT
-----------------------------------------------------------
Plan hash value: 3504519686
----------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
----------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 1 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | INDEX FULL SCAN| REG_ID_PK | 4 | 1 (0)| 00:00:01 |
----------------------------------------------------------------------
Note
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------
- dynamic statistics used: dynamic sampling (level=2)
Statistics
-----------------------------------------------------------
1 CPU used by this session
1 CPU used when call started
1 DB time
44 Requests to/from client
44 SQL*Net roundtrips to/from client
1 buffer is not pinned count
1294 bytes received via SQL*Net from client
89757 bytes sent via SQL*Net to client
2 calls to get snapshot scn: kcmgss
2 calls to kcmgcs
1 consistent gets
1 consistent gets from cache
1 consistent gets pin
1 consistent gets pin (fastpath)
1 cursor authentications
2 execute count
1 index range scans
8192 logical read bytes from cache
44 non-idle wait count
2 opened cursors cumulative
1 opened cursors current
2 parse count (total)
1 session logical reads
1 sorts (memory)
2010 sorts (rows)
45 user calls
SQL> set autotrace off
Autotrace Disabled
On est passé de 87 à 22 voir à 26 stats, c'est bien plus lisible mais, avis personnel, cela ne remplace pas SQL*Plus où les stats sont plus simples à utiliser.
============================================================================================
Stats Autotrace avec SQL Developer
============================================================================================
Utilisons maintenant SQL Developer. Que dire? Troisième outil Oracle, troisième sortie différente pour la même commande... et à nouveau très très différente de SQL*Plus.
- 45 stats différentes
- il manque les stats suivantes de SQL*Plus :
- db block gets
- physical reads
- redo size
- rows processed
set autotrace on
Autotrace Enabled
Shows the execution plan as well as statistics of the statement.
Autotrace Enabled
Shows the execution plan as well as statistics of the statement.
ID NAME DATE_DEB
---------- -------------------------------------------------- ---------
815 PARKER815 05-JAN-19
816 PARKER816 05-JAN-19
817 PARKER817 05-JAN-19
818 PARKER818 05-JAN-19
819 PARKER819 05-JAN-19
Plan hash value: 2489330668
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 5 | 620 | 2 (0)| 00:00:01 |
|* 1 | COUNT STOPKEY | | | | | |
| 2 | TABLE ACCESS FULL| ZZ01 | 10000 | 1210K| 2 (0)| 00:00:01 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(ROWNUM<6)
Note
-----
- dynamic statistics used: dynamic sampling (level=2)
Statistics
-----------------------------------------------------------
1 CPU used by this session
3 CPU used when call started
9 DB time
38 Requests to/from client
38 SQL*Net roundtrips to/from client
76 buffer is not pinned count
547 bytes received via SQL*Net from client
70062 bytes sent via SQL*Net to client
38 calls to get snapshot scn: kcmgss
13 calls to kcmgcs
7 cluster key scan block gets
7 cluster key scans
111 consistent gets
47 consistent gets examination
47 consistent gets examination (fastpath)
111 consistent gets from cache
64 consistent gets pin
64 consistent gets pin (fastpath)
1 cursor authentications
4 enqueue releases
4 enqueue requests
33 execute count
13 index fetch by key
17 index scans kdiixs1
909312 logical read bytes from cache
53 no work - consistent read gets
46 non-idle wait count
33 opened cursors cumulative
1 opened cursors current
5 parse count (hard)
6 parse count (total)
1 parse time elapsed
1 process last non-idle time
52 recursive calls
3 rows fetched via callback
28 session cursor cache hits
111 session logical reads
5 sorts (memory)
1813 sorts (rows)
16 table fetch by rowid
15 table scan blocks gotten
1044 table scan disk non-IMC rows gotten
1044 table scan rows gotten
3 table scans (short tables)
39 user calls
============================================================================================
Stats Autotrace avec Toad 12.10
============================================================================================
Après avoir vu les trois outils officiels Oracle, voyons le produit tiers le plus connu, Toad. Honnêtement, je ne vois pas trop à quoi elles peuvent servir par rapport à celles de SQL*Plus, elles sont pour moi inexploitables vu qu'il manque toute la partie sur le nombre de blocs lus en mémoire ou sur disque dur. Peut-être qu'il s'agit d'un paramétrage de Toad à modifier mais en l'état actuel, je ne vois pas l'intérêt de ces infos.
- 11 stats différentes
- il manque les stats suivantes de SQL*Plus :
- db block gets
- consistent gets
- physical reads
- redo size
- bytes sent via SQL*Net to client
- bytes received via SQL*Net from client
- SQL*Net roundtrips to/from client
- sorts (memory)
- sorts (disk)
set autotrace on
select * from zz01 where rownum < 6;
ID NAME DATE_DEB
---------- -------------------------------------------------- --------
1 PARKER1 04/01/19
2 PARKER2 04/01/19
3 PARKER3 04/01/19
4 PARKER4 04/01/19
5 PARKER5 04/01/19
5 rows selected.
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer Mode=ALL_ROWS (Cost=2 Card=5 Bytes=245)
1 0 COUNT STOPKEY
2 1 TABLE ACCESS FULL ZZTEST.ZZ01 (Cost=2 Card=10 K Bytes=478 K)
Statistics
----------------------------------------------------------
0 recursive calls
0 spare statistic 11
0 spare statistic 15
0 spare statistic 24
0 commit cleanout failures: buffer being written
0 securefile direct read ops
0 securefile direct write ops
0 securefile inode read time
0 securefile uncompressed bytes
0 securefile bytes deduplicated
5 rows processed
============================================================================================
Conclusion
============================================================================================
Continuez à utiliser AUTOTRACE sous SQL*Plus, cette commande-ci a fait ses preuves depuis des décennies :-)
Pour ceux qui voudraient savoir à quoi correspondent les nouvelles stats, une explication ici :
https://docs.oracle.com/en/database/oracle/oracle-database/12.2/refrn/statistics-descriptions-2.html#GUID-2FBC1B7E-9123-41DD-8178-96176260A639
/https%3A%2F%2Fassets.over-blog.com%2Ft%2Fcedistic%2Fcamera.png)
/https%3A%2F%2Fprofilepics.canalblog.com%2Fprofilepics%2F1%2F5%2F1555182.jpg)