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