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
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:
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...
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