People – not just People rather they are your resources!
Other people are your greatest resources! They give birth to you; they feed you, dress you, provide you with money, make you laugh and cry. They comfort you, heal you, invest your money, service your car and bury you. We can’t live without them. We can’t even die without them.
Bind peeking and session cached cursor
Bind peeking is a nice feature in Oracle to have many optimized plans for an SQL for various bind values. DBAs believe that bind peeking happens during a soft parse which will identify an alternate plan. Why do I say that?
Hard Parse: Parsing first time, nothing exists to bind peek
Soft Parse : SQL cursor is existing and executing not the first time. Under the soft parse, bind peeking will happen and the new plan will be generated based on the selectivity for that literal.
Session Cached cursor (Softer Soft Parse): Cursor is existing in the PGA, bind the new value and just execute. This is the optimal way of an SQL execution – parse once and execute many. Less CPU, less or no latches – just bind and execute.
Question for the session cached cursor – since there is no soft parsing , can bind peeking happen to a session cached cursor? Can binding will force a ‘bind peeking’ and force for soft parse if the bind value is not safe? I asked this question to an industry expert and he believes that a session cached cursor can never do bind peeking – it will just bind and execute. But, that is a dangerous situation as it can produce inefficient plans just because it is executing a cached SQL.
So, let me test it!
My test table ABC got 117455 rows for OBJECT_ID=2 and just one row for OBJECT_ID=1 with an index on OBJECT_ID. For the bind peeking test, 10046 trace shows me two different plans for OBJECT_ID=1 and 2 – one is full table scan while other is index scan.
The test SQL is,
select count(OBJECT_TYPE) from abc where object_id=:oid ;
With object_id=1
PARSING IN CURSOR #47782675682600 len=56 dep=0 uid=70 oct=3 lid=70 tim=1421932643763296 hv=3165798175 ad='1f7dd8570' sqlid='99pd5nyyb4gsz' select count(OBJECT_TYPE) from abc where object_id=:oid END OF STMT PARSE #47782675682600:c=0,e=440,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1421932643763295 BINDS #47782675682600: Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0 kxsbbbfp=2b7545793550 bln=22 avl=02 flg=05 value=1 EXEC #47782675682600:c=1000,e=1336,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2627152604,tim=1421932643764692 WAIT #47782675682600: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932643764734 FETCH #47782675682600:c=0,e=54,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2627152604,tim=1421932643764817 STAT #47782675682600 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=4 pr=0 pw=0 time=63 us)' STAT #47782675682600 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=43 us cost=4 size=11 card=1)' STAT #47782675682600 id=3 cnt=1 pid=2 pos=1 obj=20551 op='INDEX RANGE SCAN I_OBJECT_ID (cr=3 pr=0 pw=0 time=33 us cost=3 size=0 card=1)' WAIT #47782675682600: nam='SQL*Net message from client' ela= 220 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932643765178 FETCH #47782675682600:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2627152604,tim=1421932643765213 WAIT #47782675682600: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932643765253 WAIT #47782675682600: nam='SQL*Net message from client' ela= 219 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932643765489 *** SESSION ID:(2299.43369) 2015-01-22 07:17:23.767
And with OBJECT_ID=2, is a FULL table scan
PARSING IN CURSOR #47782683021480 len=57 dep=0 uid=70 oct=3 lid=70 tim=1421932662564677 hv=860935858 ad='2353e0480' sqlid='am229vwtp1ppk' select count(OBJECT_TYPE) from abc where object_id=:oid END OF STMT PARSE #47782683021480:c=0,e=374,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1421932662564676 BINDS #47782683021480: Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0 kxsbbbfp=2b75455c03a0 bln=22 avl=02 flg=05 value=2 EXEC #47782683021480:c=1000,e=1225,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1045519631,tim=1421932662565992 WAIT #47782683021480: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932662566033 FETCH #47782683021480:c=20996,e=21498,p=0,cr=1590,cu=0,mis=0,r=1,dep=0,og=1,plh=1045519631,tim=1421932662587561 STAT #47782683021480 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1590 pr=0 pw=0 time=21489 us)' STAT #47782683021480 id=2 cnt=117455 pid=1 pos=1 obj=20550 op='TABLE ACCESS FULL ABC (cr=1590 pr=0 pw=0 time=27469 us cost=447 size=1305040 card=118640)' WAIT #47782683021480: nam='SQL*Net message from client' ela= 252 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932662588004 FETCH #47782683021480:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1045519631,tim=1421932662588047 WAIT #47782683021480: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932662588069 WAIT #47782683021480: nam='SQL*Net message from client' ela= 379 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932662588485 *** SESSION ID:(2299.43369) 2015-01-22 07:17:42.589
Then I executed the below SQL, to see the behavior –
ALTER SESSION SET events '10046 trace name context forever, level 12'; VARIABLE oid NUMBER; EXECUTE :oid := 1; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ;
Looking at the cursor closing type=3 shows that, the cursor closing with caching and that is the expected behavior.
$: grep 47370175687784 xxxx_ora_10255.trc | grep type CLOSE #47370175687784:c=0,e=15,dep=0,type=1,tim=1421938140372548 CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140493515 CLOSE #47370175687784:c=0,e=13,dep=0,type=3,tim=1421938140509940 CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140560694 CLOSE #47370175687784:c=0,e=10,dep=0,type=3,tim=1421938140584517 CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140593613 CLOSE #47370175687784:c=0,e=12,dep=0,type=3,tim=1421938140681558 CLOSE #47370175687784:c=0,e=12,dep=0,type=3,tim=1421938140788580 CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140793258 CLOSE #47370175687784:c=0,e=12,dep=0,type=3,tim=1421938140797589 CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140815194 CLOSE #47370175687784:c=0,e=12,dep=0,type=3,tim=1421938140866576 CLOSE #47370175687784:c=0,e=10,dep=0,type=3,tim=1421938140890609 CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140901529 CLOSE #47370175687784:c=0,e=10,dep=0,type=3,tim=1421938140914521 CLOSE #47370175687784:c=0,e=8,dep=0,type=0,tim=1421938145465058
Here are the various values for TYPE while closing the cursor.
- type 0 : Cursor is closed and not added to the session cache
- type 1 : Cursor is closed but added to the session cache without flushing out an existing cursor
- type 2 : Cursor is closed but added to the session cache after flushing out an existing cursor in cache
- type 3 : Cursor is already existing in the cache
Now, let us see what will happen when we execute the below statement –
ALTER SESSION SET events '10046 trace name context forever, level 12'; VARIABLE oid NUMBER; EXECUTE :oid := 1; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; EXECUTE :oid := 2; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; EXECUTE :oid := 1; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ; select count(OBJECT_TYPE) from abc where object_id=:oid ;
First 5 times, execute with a bind value 1 which will cache Indexed read plan cursor in the session cache and switch the bind to 2 which will do a full table scan if it is doing a bind peeking. If bind peeking is not happening, it will end up with a wrong plan. Looking at the trace files
$ : grep obj=20550 xxxxxx_ora_15962.trc STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=57 us cost=4 size=11 card=1)' STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=39 us cost=4 size=11 card=1)' STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=39 us cost=4 size=11 card=1)' STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=36 us cost=4 size=11 card=1)' STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=40 us cost=4 size=11 card=1)' STAT #48000122321672 id=2 cnt=1879295 pid=1 pos=1 obj=20550 op='TABLE ACCESS FULL ABC (cr=24667 pr=0 pw=0 time=226535 us cost=6907 size=20702825 card=117455)' STAT #48000122321672 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=12 us cost=4 size=11 card=1)' STAT #48000122321672 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=15 us cost=4 size=11 card=1)' STAT #48000122321672 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=36 us cost=4 size=11 card=1)' STAT #48000122321672 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=13 us cost=4 size=11 card=1)'
Interesting, bind peeking is happening for a session cached SQL! If you look closely SQL started with a cursor ID 48000122322616 for the initial index read and closed that session cached cursor and opened a new cursor 48000122321672 for FULL table scan. However, when the bind value change back to 1, plan got changed under the same cursor ID. I assume this is because, both plans were cached under the same cursor, so that a session cached cursor was able to execute both plans under the same cursor ID. Oracle is doing a great job here and avoiding sub-optimal plans for a session cached cursor. But an unanswered question is, how Oracle was able to do bind peeking under ‘softer soft parse’.
CRS Timezone
Interesting problem – database was running normally without any issues and added to OCR. But the log file started reporting a different time for all activities – for example.
Database and server is showing a time 4:25 while alertlog is ahead of 5 hours @9:25!
<pre> oracle@prod # tail alert_xxxxxxx.log Recovery of Online Redo Log: Thread 2 Group 16 Seq 129057 Reading mem 0 Mem# 0: +ORAINDEX1/prod/onlinelog/group_16.282.864560747 Mon Jan 12 09:20:39 2015 Media Recovery Waiting for thread 1 sequence 129049 (in transit) Recovery of Online Redo Log: Thread 1 Group 15 Seq 129049 Reading mem 0 Mem# 0: +FLASH/prod/onlinelog/group_15.5059.864560603 Mon Jan 12 09:20:55 2015
Both database and server was showing almost 5 hrs less than the alert long entries.
oracle@prod # date Mon Jan 12 04:26:34 EST 2015 SQL> select to_char(sysdate,'DD-Mon HH24:MI:SS') from dual; TO_CHAR(SYSDATE,'DD-MONHH24:MI:SS') --------------------------------------------------------------------------- 12-Jan 04:28:46
Also, found the CSSD log is showing 5 hrs ahead of DB and server time!
grid@prod # tail ocssd.log 2015-01-12 09:12:16.373: [ CSSD][24]clssnmSendingThread: sending status msg to all nodes 2015-01-12 09:12:16.373: [ CSSD][24]clssnmSendingThread: sent 4 status msgs to all nodes 2015-01-12 09:12:20.375: [ CSSD][24]clssnmSendingThread: sending status msg to all nodes 2015-01-12 09:12:20.375: [ CSSD][24]clssnmSendingThread: sent 4 status msgs to all nodes 2015-01-12 09:12:24.377: [ CSSD][24]clssnmSendingThread: sending status msg to all nodes 2015-01-12 09:12:24.377: [ CSSD][24]clssnmSendingThread: sent 4 status msgs to all nodes 2015-01-12 09:12:28.379: [ CSSD][24]clssnmSendingThread: sending status msg to all nodes 2015-01-12 09:12:28.379: [ CSSD][24]clssnmSendingThread: sent 4 status msgs to all nodes 2015-01-12 09:12:32.381: [ CSSD][24]clssnmSendingThread: sending status msg to all nodes 2015-01-12 09:12:32.381: [ CSSD][24]clssnmSendingThread: sent 4 status msgs to all nodes
The problem was – the server was setup with a time zone TZ=US/Eastern while the CRS was installed with the time zone GMT. You can check the CRS time zone at $GRID_HOME/crs/install/ s_crsconfig_<SERVER NAME>_env.txt
<pre> grid@ # more s_crsconfig_xxxxxx_env.txt ### This file can be used to modify the NLS_LANG environment variable, which determines the charset to be used for messages. ### For example, a new charset can be configured by setting NLS_LANG=JAPANESE_JAPAN.UTF8 ### Do not modify this file except to change NLS_LANG, or under the direction of Oracle Support Services TZ=GMT NLS_LANG=ENGLISH_UNITED KINGDOM.WE8ISO8859P1
Then, why the database was showing same as server time? Being a CRS resource, should have been inherited the CRS time? Remember, you can configure the database with a different time zone other than the CRS timezone – means in the same server – each database can take its own timezone. You can view / set time zone for a database by
oracle@prod # srvctl getenv database -d xxxxxx xxxxxx: TZ=EST5EDT LIBPATH=/xxxs/app/oracle/product/11.2.0/db_1/lib
So, even though CRS time zone is GMT, database level timezone is set to EST5EDT which is US/Eastern.
You may set DB level timezone by
srvctl setenv database -d <dbname> -t 'TZ=<the required time zone>'
enq: SQ – contention
Yesterday, I have seen huge waits “enq SQ – contention’” – in every snapshot there were thousands of waits. But the fix was so simple! Here is the root cause of the issue –
When you select from a sequence, the NEXTVAL generated from a the seq$ table if it is not cached. If it is cached, it will be available in a memory structure and no need to generate the value which is a costly affair under the wait enq SQ – contention. Below test shows what will happen for this wait from NOCACHE to CACHE 1000 NEXTVALs.
I have executed the below SQL from 20 concurrent sessions..
<pre> declare col1 number; begin for a in 1..20000 loop select s.nextval into col1 from dual; end loop; end; /
Used below statements to run this SQL from 20 different sessions.
<pre>nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s & nohup sqlplus abc/abc @s &
With NOCACHE
SQL> create sequence s; select count(*),sum(time_waited) from v$active_session_history where event='enq: SQ - contention' and to_char(SAMPLE_TIME,'DDMONHH24')='09JAN04' and to_char(SAMPLE_TIME,'MI') in (14,15,16,17,18,19,20); COUNT(*) SUM(TIME_WAITED) ---------- ---------------- 2336 1677503813
With CACHE 50
SQL> alter sequence s cache 50; Sequence altered. SQL> select count(*),sum(time_waited) from v$active_session_history where event='enq: SQ - contention' and to_char(SAMPLE_TIME,'DDMONHH24')='09JAN04' and to_char(SAMPLE_TIME,'MI') in (21,22,23,24,25,26,27); COUNT(*) SUM(TIME_WAITED) ---------- ---------------- 701 459026341
With CACHE 500
SQL> alter sequence s cache 500; Sequence altered. SQL> select count(*),sum(time_waited) from v$active_session_history where event='enq: SQ - contention' and to_char(SAMPLE_TIME,'DDMONHH24')='09JAN04' and to_char(SAMPLE_TIME,'MI') in (23,24,25,26,27); COUNT(*) SUM(TIME_WAITED) ---------- ---------------- 192 96392664
With CACHE 1000
SQL> alter sequence s cache 1000 ; Sequence altered. SQL> select count(*),sum(time_waited) from v$active_session_history where event='enq: SQ - contention' and to_char(SAMPLE_TIME,'DDMONHH24')='09JAN04' and to_char(SAMPLE_TIME,'MI') in (29,30,31,32,33,34,35,36,37); COUNT(*) SUM(TIME_WAITED) ---------- ---------------- 84 23352139
With huge concurrency, the number of waits comes down from 2336 (time:1677503813 ) to 84 (time: 23352139) by adjusting the sequence CACHE.
Version:
SQL> select * from v$version; BANNER -------------------------------------------------------------------------------- Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production PL/SQL Release 11.2.0.1.0 - Production CORE 11.2.0.1.0 Production TNS for Solaris: Version 11.2.0.1.0 - Production NLSRTL Version 11.2.0.1.0 - Production
Autotrace
Happy New Year!
Oracle supplied various tools to trace the SQL and identify execution plans for the SQLs. 10046 Event, AUTOTRACE, DBMS.XPLAN etc are some of the most used tracing methods in DBAs daily life. Sometimes, we need to be very careful while using these tools specially using bind variables. Following are some test cases where wrong plans reported by the above tracing tools.
Most easiest method to get the execution plan is AUTOTRACE both estimate and actual after execution it. For example I have below tables ABC
SQL> desc abc Name Null? Type ----------------------------------------------------------------------------------------- -------- ------------------------------------------------------------ OWNER NOT NULL VARCHAR2(30) OBJECT_NAME NOT NULL VARCHAR2(30) SUBOBJECT_NAME VARCHAR2(30) OBJECT_ID NUMBER DATA_OBJECT_ID NUMBER OBJECT_TYPE VARCHAR2(19) CREATED NOT NULL DATE LAST_DDL_TIME NOT NULL DATE TIMESTAMP VARCHAR2(19) STATUS VARCHAR2(7) TEMPORARY VARCHAR2(1) GENERATED VARCHAR2(1) SECONDARY VARCHAR2(1) NAMESPACE NOT NULL NUMBER EDITION_NAME VARCHAR2(30) SQL> select OBJECT_ID,count(*) from abc group by OBJECT_ID; OBJECT_ID COUNT(*) ---------- ---------- 1 1 2 117455
ABC table got 1 row OBJECT_ID=1 and 117455 rows with OBJECT_ID=2. Created an index OBJECT_ID, so that OBEJCT_ID=1 will always use and index while OBJECT_ID=2 a FTS.
My first test was using literals, and AUTOTRACE reported correct execution plans.
SQL> select count(OBJECT_TYPE) from abc where object_id=2;
COUNT(OBJECT_TYPE)
------------------
117455
Elapsed: 00:00:00.01
Execution Plan
---------------------------------------------------------
Plan hash value: 1045519631
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 11 | 447 (1)| 00:00:06 |
| 1 | SORT AGGREGATE | | 1 | 11 | | |
|* 2 | TABLE ACCESS FULL| ABC | 118K| 1274K| 447 (1)| 00:00:06 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("OBJECT_ID"=2)
FTS for OBJECT_ID=2 and Index Range Scan for OBJECT_ID=1.
SQL> select count(OBJECT_TYPE) from abc where object_id=1;
COUNT(OBJECT_TYPE)
------------------
1
Elapsed: 00:00:00.01
Execution Plan
----------------------------------------------------------
Plan hash value: 2627152604
--------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 11 | 4 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 11 | | |
| 2 | TABLE ACCESS BY INDEX ROWID| ABC | 1 | 11 | 4 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | I_OBJECT_ID | 1 | | 3 (0)| 00:00:01 |
--------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("OBJECT_ID"=1)
Then I moved to the next level – get the AUTOTRACE plans using BIND Variables.
SQL> set autotrace traceonly
SQL> VARIABLE oid NUMBER;
SQL> EXECUTE :oid := 1;
SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;SQL>
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
SQL>
Elapsed: 00:00:00.01
Execution Plan
----------------------------------------------------------
Plan hash value: 1045519631
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 11 | 448 (1)| 00:00:06 |
| 1 | SORT AGGREGATE | | 1 | 11 | | |
|* 2 | TABLE ACCESS FULL| ABC | 118K| 1274K| 448 (1)| 00:00:06 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("OBJECT_ID"=TO_NUMBER(:OID))
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
4 consistent gets
0 physical reads
0 redo size
536 bytes sent via SQL*Net to client
520 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> VARIABLE oid NUMBER;
SQL> EXECUTE :oid := 2;
SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;SQL>
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
SQL>
Elapsed: 00:00:00.04
Execution Plan
----------------------------------------------------------
Plan hash value: 1045519631
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 11 | 448 (1)| 00:00:06 |
| 1 | SORT AGGREGATE | | 1 | 11 | | |
|* 2 | TABLE ACCESS FULL| ABC | 118K| 1274K| 448 (1)| 00:00:06 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("OBJECT_ID"=TO_NUMBER(:OID))
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
1964 consistent gets
0 physical reads
0 redo size
538 bytes sent via SQL*Net to client
520 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)</pre>
<ul>
<li>rows processed</li>
</ul>
<pre>
The AUTOTRACE TRACEONLY reported both plans as FTS, though OBJECT_ID-=1 is just reading one row from the table while OBJECT_ID is an indexed column. I agree to the fact that, AUTOTRACE TRACEONLY is showing an estimated plan, so may be reporting the wrong plan. Experts say that, AUTOTRACE TRACEONLY never a dependable way of plan generation. Interestingly OBJECT_ID=1 reported just 4 consistent gets while OBJECT_ID=2 shows 1964 gets – so the estimation theory is not really going well here as I was expecting 1964 CR reads if the estimated plan is FTS.
Then moved to the next test – use AUTOTRACE EXPLAIN STAT. I had some faith in this level as the SQL statement will get execute first and report the executed plan. So the plan tends to be accurate.
SQL> set autotrace on exp stat
SQL> EXECUTE :oid := 2;
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;
COUNT(OBJECT_TYPE)
------------------
117455
Elapsed: 00:00:00.02
Execution Plan
----------------------------------------------------------
Plan hash value: 1045519631
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 11 | 448 (1)| 00:00:06 |
| 1 | SORT AGGREGATE | | 1 | 11 | | |
|* 2 | TABLE ACCESS FULL| ABC | 118K| 1274K| 448 (1)| 00:00:06 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("OBJECT_ID"=TO_NUMBER(:OID))
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
1590 consistent gets
0 physical reads
0 redo size
538 bytes sent via SQL*Net to client
520 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> EXECUTE :oid := 1
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;
COUNT(OBJECT_TYPE)
------------------
1
Elapsed: 00:00:00.02
Execution Plan
----------------------------------------------------------
Plan hash value: 1045519631
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 11 | 448 (1)| 00:00:06 |
| 1 | SORT AGGREGATE | | 1 | 11 | | |
|* 2 | TABLE ACCESS FULL| ABC | 118K| 1274K| 448 (1)| 00:00:06 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("OBJECT_ID"=TO_NUMBER(:OID))
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
1590 consistent gets
0 physical reads
0 redo size
536 bytes sent via SQL*Net to client
520 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)</pre>
<ul>
<li>rows processed</li>
</ul>
<pre>
To my surprise, both plans reported FTS regardless of the selectivity. 10046 trace shows Oracle is doing index range scan for OBEJCT_ID=1. Using BINDS, the plan may not report correctly in the AUTOTRACE as there may be multiple child cursors existing due to Bind Peeking. So, using BIND values in AUTOTRACE is really not working at all when we have multiple child cursors. I am not sure, why Oracle can’t fix this issue, as AUTOTRACE just need to report the last executed plan, not from the estimation.
Then I turn to DBMS_XPLAN, and the results were surprised me even more. For OBJECT_ID=1 reported a FTS, as
SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;
COUNT(OBJECT_TYPE)
------------------
1
Elapsed: 00:00:00.01
SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST '));
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------
SQL_ID 99pd5nyyb4gsz, child number 1
-------------------------------------
select count(OBJECT_TYPE) from abc where object_id=:oid
Plan hash value: 1045519631
--------------------------------------------
| Id | Operation | Name | E-Rows |
--------------------------------------------
| 0 | SELECT STATEMENT | | |
| 1 | SORT AGGREGATE | | 1 |
|* 2 | TABLE ACCESS FULL| ABC | 118K|
--------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("OBJECT_ID"=:OID)
I was not really expecting FTS using DBMS_XPLAN for OBJECT_ID=1, that was bit shocking. Then I changed the option to ‘ALLSTATS LAST +PEEKED_BINDS’ from ‘ALLSTATS LAST ‘ and started reporting correct plans.
SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST +PEEKED_BINDS'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------
SQL_ID am229vwtp1ppk, child number 0
-------------------------------------
select count(OBJECT_TYPE) from abc where object_id=:oid
Plan hash value: 2627152604
-------------------------------------------------------------
| Id | Operation | Name | E-Rows |
-------------------------------------------------------------
| 0 | SELECT STATEMENT | | |
| 1 | SORT AGGREGATE | | 1 |
| 2 | TABLE ACCESS BY INDEX ROWID| ABC | 1 |
|* 3 | INDEX RANGE SCAN | I_OBJECT_ID | 1 |
-------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - :SYS_B_0 (NUMBER): 1
Predicate Information (identified by operation id):
---------------------------------------------------
</pre>
<ul>
<li>- access("OBJECT_ID"=:OID)</li>
</ul>
<pre>
So, be careful when you use AUTOTRACE or any tools when you use BIND variables. Oracle should put some more efforts to make it more dependable. Always use 10046 event and tkprof to get a real picture.
SQL> select * from v$version; BANNER -------------------------------------------------------------------------------- Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production PL/SQL Release 11.2.0.4.0 - Production CORE 11.2.0.4.0 Production TNS for Linux: Version 11.2.0.4.0 - Production NLSRTL Version 11.2.0.4.0 – Production
APPEND and PARALLEL
APPEND hint in oracle is very useful, there are many benefits
Fragmented data loading – data will clustered above the HWM so that similar data will be together. Otherwise Oracle will place the records in blocks using PCT_FREE rule
- No undo will be generated – in large direct path insert will free up large amount of data blocks
- Less CBC latches (because of no UNDO blocks), less CPU usage
- Readers need not undo the records, consistent reads are less costly – just read below HWM
- Rollback will be faster – Oracle will just discard all the blocks above the HWM and it is instant.
- Less REDO as UNDO blocks are not generated. In case of NOARCHIVELOG mode, very limited REDO, only to manage the internal operations. Both instance recovery and media recovery is out of scope from REDO.
- No UNDO – no infamous ORA-1555 Snapshoot too old error!
To achieve direct path loading- we typically use /*+ APPEND */ clause and that will not generate UNDO.
SQL> insert /*+ APPEND */ into t1 select * from t; 1803136 rows created. Elapsed: 00:00:03.09 SQL> set linesize 180 SQL> col status for a8 SQL> col undousage for 999999999999.99 SQL> SELECT b.INST_ID,a.sid, a.username, a.status,b.xidusn, b.used_urec, b.used_ublk,flag,sql_id,b.used_ublk*8/1024/1024 undousage FROM gv$session a, gv$transaction b WHERE a.saddr(+) = b.ses_addr and a.INST_ID(+) = b.INST_ID ; INST_ID SID USERNAME STATUS XIDUSN USED_UREC USED_UBLK FLAG SQL_ID UNDOUSAGE ---------- ---------- ------------------------------ -------- ---------- ---------- ---------- ---------- ------------- ---------------- 2 2299 TEST INACTIVE 15 1 1 16782851 djzyaz5uj6vnr .00
We just got one UNDO record which may be used for internal operation including extent management. While a traditional load with same data generated 43599 undo records in 950 blocks which is 7600KB in size.
<pre>SQL> insert into t1 select * from t; 1803136 rows created. Elapsed: 00:00:03.87 SQL> set linesize 180 SQL> col status for a8 SQL> col undousage for 999999999999.99 SQL> SELECT b.INST_ID,a.sid, a.username, a.status,b.xidusn, b.used_urec, b.used_ublk,flag,sql_id,b.used_ublk*8/1024/1024 undousage 2 FROM gv$session a, gv$transaction b 3 WHERE a.saddr(+) = b.ses_addr and a.INST_ID(+) = b.INST_ID ; INST_ID SID USERNAME STATUS XIDUSN USED_UREC USED_UBLK FLAG SQL_ID UNDOUSAGE ---------- ---------- ------------------------------ -------- ---------- ---------- ---------- ---------- ------------- ---------------- 2 2299 TEST INACTIVE 12 43599 950 7683 9c7qck66f77c0 .01
Using a direct path load is always useful. Oracle did a wonderful thing and is documented it says – When you use PARALLEL insert it will be direct path and to enable traditional load, you should explicitly use the hint NOAPPEND.
https://docs.oracle.com/cd/E11882_01/server.112/e41573/hintsref.htm#PFGRF50101
Well, may be true and it is false as well. I am not sure what meant by DIRECT path load here. All the above mentioned benefits of APPEND are getting while using PARALLEL hint? I thought it was true, till I test it. It may be true that Oracle is placing all the blocks above the HWM, but is it reducing the UNDO. One of the beauty of APPEND is reducing UNDO and if that is not achieved, a direct path load is less beneficial.
I ran the above test again in parallel –
<pre>SQL> insert /*+ parallel (t1,5) */ into t1 select * from t; 1803136 rows created. Elapsed: 00:00:02.75 SQL> set linesize 180 SQL> col status for a8 SQL> col undousage for 999999999999.99 SQL> SELECT b.INST_ID,a.sid, a.username, a.status,b.xidusn, b.used_urec, b.used_ublk,flag,sql_id,b.used_ublk*8/1024/1024 undousage 2 FROM gv$session a, gv$transaction b 3 WHERE a.saddr(+) = b.ses_addr and a.INST_ID(+) = b.INST_ID ; INST_ID SID USERNAME STATUS XIDUSN USED_UREC USED_UBLK FLAG SQL_ID UNDOUSAGE ---------- ---------- ------------------------------ -------- ---------- ---------- ---------- ---------- ------------- ---------------- 2 2299 TEST INACTIVE 12 43743 952 7683 29hu6nmj0g66w .01
To my surprise Oracle generated more UNDO records and blocks in a single thread. So, Oracle is saying PARALLEL is APPENDing, but not all APPEND features are available in PARALLEL load. Many times in the past I took a decision to use PARALLEL thinking it is real APPEND. I re-tried the insert with both PARALLEL and APPEND – and it works as expected – but the it took more time to complete.
<pre>QL> insert /*+ parallel (t1,5) APPEND */ into t1 select * from t; 1803136 rows created. Elapsed: 00:00:05.94 SQL> set linesize 180 SQL> col status for a8 SQL> col undousage for 999999999999.99 SQL> SELECT b.INST_ID,a.sid, a.username, a.status,b.xidusn, b.used_urec, b.used_ublk,flag,sql_id,b.used_ublk*8/1024/1024 undousage 2 FROM gv$session a, gv$transaction b 3 WHERE a.saddr(+) = b.ses_addr and a.INST_ID(+) = b.INST_ID ; INST_ID SID USERNAME STATUS XIDUSN USED_UREC USED_UBLK FLAG SQL_ID UNDOUSAGE ---------- ---------- ------------------------------ -------- ---------- ---------- ---------- ---------- ------------- ---------------- 2 2299 TEST INACTIVE 15 1 1 16782851 avnd4v97v389t .00
Well, it is just generated 1 UNDO block confirming my assumption.
Consistent gets – How Many?
When you execute an SQL – why there is a difference in Consistent gets on the same set of data for same SQL. For any SELECT query, oracle need to prepare the consistent data in the buffer cache using undo records then forward the data the requesting session as of a specific SCN. Touching any block in buffer cache to prepare the blocks for consistent data is known as Consistent Reads.
In an ideal situation, to read a row from a block just need one consistent get.
SQL> select * from test where rowid='AAAPaVAABAAAzfJAAA'; C1 C2 ---------- ---------- 1 CON$ Execution Plan ---------------------------------------------------------- Plan hash value: 2153624467 ----------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 32 | 1 (0)| 00:00:01 | | 1 | TABLE ACCESS BY USER ROWID| TEST | 1 | 32 | 1 (0)| 00:00:01 | ----------------------------------------------------------------------------------- Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 1 consistent gets 0 physical reads 0 redo size 589 bytes sent via SQL*Net to client 520 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processed
But when I run the same SQL again after a transaction from different session, the number of consistent gets gone up to 3, just to read a single row.
SQL> select * from test where rowid='AAAPaVAABAAAzfJAAA'; C1 C2 ---------- ---------- 1 ABC Execution Plan ---------------------------------------------------------- Plan hash value: 2153624467 ----------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 32 | 1 (0)| 00:00:01 | | 1 | TABLE ACCESS BY USER ROWID| TEST | 1 | 32 | 1 (0)| 00:00:01 | ----------------------------------------------------------------------------------- Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 3 consistent gets 0 physical reads 108 redo size 588 bytes sent via SQL*Net to client 520 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processed
The 3 consistent gets may be (but later found to be incorrect!!)
- Access the current block
- Create a new CONSISTENT block and copy the CURRENT block contents
- Access the undo block and rollback the uncommitted transaction
So, what if I have one more transaction going on a different row on the same block? Need to access one more undo block to rollback the second uncommitted transaction, so that you will get 4 consistent gets.
SQL> select * from test where rowid='AAAPaVAABAAAzfJAAA'; C1 C2 ---------- ---------- 1 ABC Execution Plan ---------------------------------------------------------- Plan hash value: 2153624467 ----------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 32 | 1 (0)| 00:00:01 | | 1 | TABLE ACCESS BY USER ROWID| TEST | 1 | 32 | 1 (0)| 00:00:01 | ----------------------------------------------------------------------------------- Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 5 consistent gets 0 physical reads 108 redo size 588 bytes sent via SQL*Net to client 520 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processed
Contrary to my expectation of one more consistent get, the number of consistent gets grown by 2 reaching to 5 gets. I am sure, that I need to read one extra undo block for the uncommitted transaction, but what is the 5th block?
10046 trace show me that I was totally wrong – even my earlier assumption. There were only one block read from the table and rest of the 4 reads from the UNDO file.
WAIT #2: nam='db file sequential read' ela= 34 file#=1 block#=210889 blocks=1 obj#=63125 tim=39307229867247 WAIT #2: nam='db file sequential read' ela= 25 file#=3 block#=208 blocks=1 obj#=0 tim=39307229867390 WAIT #2: nam='db file sequential read' ela= 22 file#=3 block#=224 blocks=1 obj#=0 tim=39307229867454 WAIT #2: nam='db file sequential read' ela= 22 file#=3 block#=439 blocks=1 obj#=0 tim=39307229867585 WAIT #2: nam='db file sequential read' ela= 21 file#=3 block#=157 blocks=1 obj#=0 tim=39307229867696
First undo block
Block dump from disk: buffer tsn: 2 rdba: 0x00c000d0 (3/208) scn: 0x01a7.37e301cf seq: 0x01 flg: 0x04 tail: 0x01cf2601 frmt: 0x02 chkval: 0xd8b1 type: 0x26=KTU SMU HEADER BLOCK
Second undo block
buffer tsn: 2 rdba: 0x00c000e0 (3/224) scn: 0x01a7.37e300bb seq: 0x01 flg: 0x04 tail: 0x00bb2601 frmt: 0x02 chkval: 0xa4d2 type: 0x26=KTU SMU HEADER BLOCK
3rd undo block
buffer tsn: 2 rdba: 0x00c001b7 (3/439) scn: 0x01a7.37e301cf seq: 0x01 flg: 0x04 tail: 0x01cf0201 frmt: 0x02 chkval: 0xc91c type: 0x02=KTU UNDO BLOCK
4th undo block
buffer tsn: 2 rdba: 0x00c0009d (3/157) scn: 0x01a7.37e300bb seq: 0x01 flg: 0x04 tail: 0x00bb0201 frmt: 0x02 chkval: 0x5f27 type: 0x02=KTU UNDO BLOCK
If you look closely, a pair of blocks under same SCN and the first block type is “KTU SMU HEADER BLOCK” is the undo header block and the second one is the undo block of type “KTU UNDO BLOCK”. So, oracle is reading 1 consistent get to copy the current block, and for each transaction 1 undo block header and 1 undo block. X$bh was also showing one more block in STATE 3, which I felt, is not reported in the consistent gets. That is the block read from the data file with the uncommitted transaction. Repeated the test with one more transaction, and got 7 consistent gets.
SQL> select * from test where rowid='AAAPaVAABAAAzfJAAA'; C1 C2 ---------- ---------- 1 ABC Execution Plan ---------------------------------------------------------- Plan hash value: 2153624467 ----------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 32 | 1 (0)| 00:00:01 | | 1 | TABLE ACCESS BY USER ROWID| TEST | 1 | 32 | 1 (0)| 00:00:01 | ----------------------------------------------------------------------------------- Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 7 consistent gets 0 physical reads 108 redo size 588 bytes sent via SQL*Net to client 520 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processed
In nutshell, how many maximum consistent gets can happen just to read one row from a table got 1 block with 50 different rows in the block? In theory, there can be 50 different transactions can happen to the block concurrently. So, the maximum number consistent get can be 2n+1 where n is the number of rows in the block. So, there can be up to 101 consistent gets to read one row!
Elapsed Checkpoint Time
Adieu to 2013 with this small post! Happy new year to every one.
Oracle controls the incremental checkpoint frequency or interval based on the parameter FAST_START_MTTR_TARGET or LOG_CHECKPOINT_INTERVAL. But, can you see the real checkpoint interval values? What is the elapsed time between checkpoints?
Yes, you can. The fixed table X$KCCDI holds SCN information about last checkpoint SCN and current SCN. Column DICKP_SCN is the last checkpoint SCN and DICUR_SCN is the current SCN.
We get the CURRENT_SCN from v$database as,
SQL> select current_scn from v$database; CURRENT_SCN ----------- 102707163
And looking at the X$KCCDI fixed tables, you can get the same SCN values.
SQL> select DICKP_SCN,DICUR_SCN from X$KCCDI; DICKP_SCN DICUR_SCN ---------------- ---------------- 102711050 102711285 SQL> select current_scn from v$database; CURRENT_SCN ----------- 102711289
Using the SCN_TO_TIMESTAMP function, you can convert the SCN values to time stamps.
SQL> select scn_to_timestamp(DICKP_SCN), scn_to_timestamp(DICUR_SCN) from X$KCCDI; SCN_TO_TIMESTAMP(DICKP_SCN) SCN_TO_TIMESTAMP(DICUR_SCN) --------------------------------------------------------------------------- --------------------------------------------------------------------------- 31-DEC-13 01.18.54.000000000 AM 31-DEC-13 01.31.31.000000000 AM
Now, it is easy to find the elapsed time of last SCN.
SQL> select scn_to_timestamp(DICUR_SCN) - scn_to_timestamp(DICKP_SCN) from X$KCCDI; SCN_TO_TIMESTAMP(DICUR_SCN)-SCN_TO_TIMESTAMP(DICKP_SCN) --------------------------------------------------------------------------- +000000000 00:1:51.000000000
The checkpoint elapsed time is depends on the load on the database. When the database is idle, it took 3 minutes between the checkpoints – but that is not a hard limit.
SQL> select scn_to_timestamp(DICUR_SCN) - scn_to_timestamp(DICKP_SCN) from X$KCCDI; SCN_TO_TIMESTAMP(DICUR_SCN)-SCN_TO_TIMESTAMP(DICKP_SCN) --------------------------------------------------------------------------- +000000000 00:03:00.000000000 SQL> select scn_to_timestamp(DICUR_SCN) - scn_to_timestamp(DICKP_SCN) from X$KCCDI; SCN_TO_TIMESTAMP(DICUR_SCN)-SCN_TO_TIMESTAMP(DICKP_SCN) --------------------------------------------------------------------------- +000000000 00:00:00.000000000
But the elapsed time went down to few seconds when I increased the load.
SQL> select scn_to_timestamp(DICUR_SCN) - scn_to_timestamp(DICKP_SCN) from X$KCCDI; SCN_TO_TIMESTAMP(DICUR_SCN)-SCN_TO_TIMESTAMP(DICKP_SCN) --------------------------------------------------------------------------- +000000000 00:00:20.000000000 SQL> select scn_to_timestamp(DICUR_SCN) - scn_to_timestamp(DICKP_SCN) from X$KCCDI; SCN_TO_TIMESTAMP(DICUR_SCN)-SCN_TO_TIMESTAMP(DICKP_SCN) --------------------------------------------------------------------------- +000000000 00:00:00.000000000 SQL> select scn_to_timestamp(DICUR_SCN) - scn_to_timestamp(DICKP_SCN) from X$KCCDI; SCN_TO_TIMESTAMP(DICUR_SCN)-SCN_TO_TIMESTAMP(DICKP_SCN) --------------------------------------------------------------------------- +000000000 00:00:03.000000000 SQL> select scn_to_timestamp(DICUR_SCN) - scn_to_timestamp(DICKP_SCN) from X$KCCDI; SCN_TO_TIMESTAMP(DICUR_SCN)-SCN_TO_TIMESTAMP(DICKP_SCN) --------------------------------------------------------------------------- +000000000 00:00:00.000000000
And a big good bye to 2013!
