6f429244e498457b8400e72e4af683b0 Alberto Blog: AUTOTRACE - DB TIME

martedì 22 aprile 2014

AUTOTRACE - DB TIME

Today I write this post in English for better explain, (I hope) my previous post Oracle - Windows Sort Pushed Rank access, after Jocelyn's question about AUTOTRACE and statistics like DB TIME.
I used SqlDeveloper to capture autotrace in my previous post, and this is a trick in new version 4 of this software but I tryed to reproduce the same in sqlplus but in effect it's very hard or it's not simple like I think, so


[oracle@localhost ~]$ sqlplus pmuser/oracle@PDB1

SQL*Plus: Release 12.1.0.1.0 Production on Tue Apr 22 10:28:55 2014

Copyright (c) 1982, 2013, Oracle.  All rights reserved.

Last Successful login time: Tue Apr 22 2014 10:17:34 +02:00

Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

PDB1@ORCL> alter session set statistics_level= ALL;

Session altered.

PDB1@ORCL> set linesize 100;
PDB1@ORCL> SET AUTOTRACE ON
select  owner,object_name,object_id from t2
order by owner,object_name fetch first 5 rows only;PDB1@ORCL>   2  

OWNER
----------------------------------------------------------------------------------------------------
OBJECT_NAME
----------------------------------------------------------------------------------------------------
 OBJECT_ID
----------
APEX_040200
APEX
     93296

APEX_040200
APEX$ARCHIVE_CONTENTS
     94132

OWNER
----------------------------------------------------------------------------------------------------
OBJECT_NAME
----------------------------------------------------------------------------------------------------
 OBJECT_ID
----------

APEX_040200
APEX$ARCHIVE_CONTENTS_IDX1
     94136

APEX_040200
APEX$ARCHIVE_HEADER

OWNER
----------------------------------------------------------------------------------------------------
OBJECT_NAME
----------------------------------------------------------------------------------------------------
 OBJECT_ID
----------
     94130

APEX_040200
APEX$ARCHIVE_HISTORY
     94137



Execution Plan
----------------------------------------------------------
Plan hash value: 3975347511

-----------------------------------------------------------------------------------------
| Id  | Operation   | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  | | 89325 |    24M| |  1265   (1)| 00:00:01 |
|*  1 |  VIEW    | | 89325 |    24M| |  1265   (1)| 00:00:01 |
|*  2 |   WINDOW SORT PUSHED RANK| | 89325 |  3140K|  4216K|  1265   (1)| 00:00:01 |
|   3 |    TABLE ACCESS FULL  | T2 | 89325 |  3140K| |   418   (1)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("from$_subquery$_002"."rowlimit_$$_rownumber"<=5)
   2 - filter(ROW_NUMBER() OVER ( ORDER BY "OWNER","OBJECT_NAME")<=5)


Statistics
----------------------------------------------------------
  80  recursive calls
   0  db block gets
       1596  consistent gets
       1512  physical reads
   0  redo size
 890  bytes sent via SQL*Net to client
 543  bytes received via SQL*Net from client
   2  SQL*Net roundtrips to/from client
  12  sorts (memory)
   0  sorts (disk)
   5  rows processed

PDB1@ORCL>
In this case we have no db time in Statistics, while in SqlDeveloper there are.
Now I don't know why in this case this parameter is missing, but could be a nice workaround like this:
[oracle@localhost ~]$ sqlplus pmuser/oracle@PDB1

SQL*Plus: Release 12.1.0.1.0 Production on Tue Apr 22 11:40:11 2014

Copyright (c) 1982, 2013, Oracle.  All rights reserved.

Last Successful login time: Tue Apr 22 2014 10:29:23 +02:00

Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

PDB1@ORCL> set linesize 100
PDB1@ORCL> set heading off
PDB1@ORCL> select sys_context('USERENV','SID') from dual;

45

PDB1@ORCL> SET AUTOTRACE ON
select  owner,object_name,object_id from t2
order by owner,object_name fetch first 5 rows only;
PDB1@ORCL>   2  
APEX_040200
APEX
     93296

APEX_040200
APEX$ARCHIVE_CONTENTS
     94132

APEX_040200
APEX$ARCHIVE_CONTENTS_IDX1
     94136

APEX_040200

APEX$ARCHIVE_HEADER
     94130

APEX_040200
APEX$ARCHIVE_HISTORY
     94137



Execution Plan
----------------------------------------------------------
Plan hash value: 3975347511

-----------------------------------------------------------------------------------------
| Id  | Operation   | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  | | 89325 |    24M| |  1265   (1)| 00:00:01 |
|*  1 |  VIEW    | | 89325 |    24M| |  1265   (1)| 00:00:01 |
|*  2 |   WINDOW SORT PUSHED RANK| | 89325 |  3140K|  4216K|  1265   (1)| 00:00:01 |
|   3 |    TABLE ACCESS FULL  | T2 | 89325 |  3140K| |   418   (1)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("from$_subquery$_002"."rowlimit_$$_rownumber"<=5)
   2 - filter(ROW_NUMBER() OVER ( ORDER BY "OWNER","OBJECT_NAME")<=5)


Statistics
----------------------------------------------------------
  79  recursive calls
   0  db block gets
       1597  consistent gets
       1516  physical reads
   0  redo size
 890  bytes sent via SQL*Net to client
 543  bytes received via SQL*Net from client
   2  SQL*Net roundtrips to/from client
   7  sorts (memory)
   0  sorts (disk)
   5  rows processed

PDB1@ORCL> set autotrace off
PDB1@ORCL> select name, value from  v$statname a, v$mystat b
where
        b.value <> 0
and     b.statistic# = a.statistic#
and b.SID = 45;

Requests to/from client        31
logons cumulative         1
logons current          1
opened cursors cumulative      919
opened cursors current        11
user calls         51
recursive calls              5978
recursive cpu usage        27
pinned cursors current        11
session logical reads             8394
CPU used when call started       29
CPU used by this session       30
DB time         249

user I/O wait time       136
non-idle wait time       136
non-idle wait count       731
session connect time       1398159611
process last non-idle time      1398159611
session uga memory          2933728
session uga memory max          2933728
messages sent          2
session pga memory         10064008
session pga memory max         10260616
enqueue requests        89
enqueue releases        84
physical read total IO requests      695

physical read total bytes        16588800
cell physical IO interconnect bytes       16588800
db block gets         36
db block gets from cache       36
db block gets from cache (fastpath)       2
consistent gets              8358
consistent gets from cache            6856
consistent gets pin             3327
consistent gets pin (fastpath)            2915
consistent gets examination            3529
consistent gets examination (fastpath)           3438
consistent gets direct             1502
logical read bytes from cache        56459264

physical reads              2025
physical reads cache       523
physical reads direct             1502
physical read IO requests      695
physical read bytes         16588800
db block changes        37
consistent changes        20
free buffer requested       531
dirty buffers inspected        12
pinned buffers inspected        1
hot buffers moved to head of LRU           2957
free buffer inspected       638
commit cleanouts         2

commit cleanouts successfully completed       2
switch current to new buffer        2
physical reads cache prefetch       20
shared hash latch upgrades - no wait      84
calls to kcmgcs        155
calls to kcmgas          6
calls to get snapshot scn: kcmgss           1817
redo entries         12
redo size              5420
redo synch time (usec)         1
redo synch time overhead (usec)      146
redo synch time overhead count (  2ms)       1
redo synch writes         2

redo write info find         1
file io wait time          1178238
Number of read IOs issued      192
temp space allocated (bytes)         3145728
undo change vector size             3712
no work - consistent read gets            4677
deferred (CURRENT) block cleanout applications      1
IMU Flushes          1
IMU ktichg flush         1
CLI Thru Wrt          1
table scans (short tables)       42
table scans (long tables)        1
table scans (direct read)        1

table scan rows gotten           102715
table scan blocks gotten            1603
table fetch by rowid             2311
table fetch continued row       37
cluster key scans       187
cluster key scan block gets      190
rows fetched via callback      724
lob writes          1
lob writes unaligned         1
index fetch by key       962
index scans kdiixs1       852
HSC Heap Segment Block Changes       10
sql area evicted        29

CCursor + sql area evicted       18
session cursor cache hits      850
session cursor cache count       49
cursor authentications        31
buffer is pinned count       723
buffer is not pinned count            5962
workarea memory allocated      658
workarea executions - optimal      133
parse time cpu         10
parse time elapsed        66
parse count (total)       487
parse count (hard)        71
execute count              1086

bytes sent via SQL*Net to client          12451
bytes received via SQL*Net from client           8880
SQL*Net roundtrips to/from client      31
sorts (memory)        283
sorts (rows)             91107

109 rows selected.

PDB1@ORCL> 
In this case we have all statistics DB TIME also. We need to ask to Jeff Smith more explanation about... Your comments are welcome, as usual.... HTH

2 commenti:

Cristian Cudizio ha detto...

may be useful to do some tests enabling event 10046, just for curiosity i've tried and with sqldeveloper 3.0 i've found in trace the query "select ms.Statistic# stat,ms.value,sn.name from v$mystat ms, v$statname sn where sn.statistic# = ms.statistic# and ms.Statistic# in (7,47,50,54,134,335,336,337,341,342) order by 1", with sqldeveloper 4.0 the query is select ms.Statistic# stat,ms.value,sn.name from v$mystat ms, v$statname sn where sn.statistic# = ms.statistic# order by 1 and stastics displayed change with the type of statement, so i think in sqldeveloper is implemented some logic of selection of interesting statistics.
Finally, with instant client sql*plus 11.2.0.3 i've found: SELECT STATISTIC# S, NAME FROM SYS.V_$STATNAME WHERE NAME IN ('recursive calls','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)') ORDER BY S
Sorry for my poor English :)
P.S.
Tom Kyte uses some scripts to collect statistics about a statement, ever using v$mystat...

Alberto ha detto...

Ciao Cristian,
thanks for your comment, there are several statements to obtain statistics of trace but my dilemma (I'm particularly curious) is why in sqlplus was not implemented this feature on the db and time, with autotrace and statistic level set to all?
db time is missing, while other statistics there are, as block gets, physical reads and so on.
Is there any reason?
here Jeff Smith's answer, but not clear at all.
http://www.thatjeffsmith.com/ask-a-question/#comment-48741
Thanks a lot...
Ciao
Alberto

Posta un commento