Control file sequential read

There was a thread recently on the OTN forum (it’s currently down, that’s why I’m writing in the blog; here is a stale version of the page from Google cache; at the time of writing this version had 1 comment) about reasons for control file sequential read accounted to particular query.

The query in question uses a 9i (R1 or R2 – don’t know exactly) new feature called subquery factoring clause. Because I have seen earlier this a little bit strange behavior accompanied the subquery factoring materialization, I replied that it is caused by a “direct path writes” to the global temporary table (SYS_TEMP_% in the SYS schema with in-memory meta-data constructed by Oracle on the fly – if needed) required to check the data temporary file status – is it on/off-line. Then Jonathan Lewis replied that not all “direct path writes” causes this behavior and probably it is due to unknown behavior of the direct path load operation. It is very reasonable, so I’ve started to play with it on 11gR2 – trying to get more information – and it was evident Oracle 11gR2 “lacked” control files read in comparison with to the latest 10gR2+PSU (10.2.0.4.3). Here is how subquery materialization looks like in the 10.2.0.4 SQL trace file:

PARSING IN CURSOR #2 len=160 dep=1 uid=0 oct=1 lid=0 tim=1234611281051708 hv=1204571398 ad='7ea50d28'
CREATE GLOBAL TEMPORARY TABLE "SYS"."SYS_TEMP_0FD9D6601_198FEA" ("C0" NUMBER ) IN_MEMORY_METADATA CURSOR_SPECIFIC_SEGMENT STORAGE (OBJNO 4254950913 ) NOPARALLEL
END OF STMT
PARSE #2:c=0,e=463,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1234611281051703 
...
PARSING IN CURSOR #1 len=64 dep=0 uid=48 oct=3 lid=48 tim=1234611281063943 hv=3651613461 ad='7f8e3198'
with t1 as (select count(*) from t)
select * from t1 t11, t1 t12
END OF STMT
PARSE #1:c=23997,e=22964,p=0,cr=115,cu=2,mis=1,r=0,dep=0,og=1,tim=1234611281063936
WAIT #1: nam='control file sequential read' ela= 44 file#=0 block#=1 blocks=1 obj#=-1 tim=1234611281064892
WAIT #1: nam='control file sequential read' ela= 16 file#=1 block#=1 blocks=1 obj#=-1 tim=1234611281064938
WAIT #1: nam='control file sequential read' ela= 14 file#=2 block#=1 blocks=1 obj#=-1 tim=1234611281064970
WAIT #1: nam='control file sequential read' ela= 15 file#=0 block#=15 blocks=1 obj#=-1 tim=1234611281065027
WAIT #1: nam='control file sequential read' ela= 11 file#=0 block#=17 blocks=1 obj#=-1 tim=1234611281065056
WAIT #1: nam='direct path write temp' ela= 16 file number=201 first dba=12170 block cnt=1 obj#=-1 tim=1234611281076811
EXEC #1:c=13998,e=28014,p=0,cr=572,cu=7,mis=0,r=0,dep=0,og=1,tim=1234611281092034
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1234611281092088
WAIT #1: nam='db file sequential read' ela= 31 file#=201 block#=12170 blocks=1 obj#=-40016383 tim=1234611281092241
FETCH #1:c=0,e=264,p=1,cr=8,cu=1,mis=0,r=1,dep=0,og=1,tim=1234611281092387
WAIT #1: nam='log file sync' ela= 11576 buffer#=550 p2=0 p3=0 obj#=-40016383 tim=1234611281104003
WAIT #1: nam='SQL*Net message from client' ela= 191 driver id=1650815232 #bytes=1 p3=0 obj#=-40016383 tim=1234611281104254
FETCH #1:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1234611281104305
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-40016383 tim=1234611281104515
WAIT #1: nam='SQL*Net message from client' ela= 5630236 driver id=1650815232 #bytes=1 p3=0 obj#=-40016383 tim=1234611286734776 

At first, GTT is created with a special syntax available to internal Oracle code only. After that original statement is executed – and it starts with checking all control files headers (see file# & block# in the highlighted lines), then it gets 15th and 17th blocks (according to the documentation, itis file blocks) of the first control file (I don’t know what exactly is located there).

Something’s missing here, isn’t it? There’s no INSERT statement and “direct path write temp” wait is accounted to the top-level statement, as opposed to the Oracle 9i, which dumps it to trace as a separate cursor. I don’t know whether it is due to things changed between 9i-10g or it’s just a lost of the instrumentation calls (or both).

I found a Bug 7515779 which looks like a cause of the “control file sequential read”; it has a one-off patch for 10.2.0.4. Today I was able to test the bug-fix, and can confirm: this is it. I’ve used this script (requires new local connection):

set termout off

col spid new_value spid
select spid from v$process 
 where addr = (select paddr from v$session where sid = userenv('sid'));

set define on verify off termout on echo on serveroutput off linesize 120 pagesize 999
sho parameter control_files

!/usr/sbin/lsof -p &spid | grep control

with t1 as (select count(*) from t)
select * from t1 t11, t1 t12;

!/usr/sbin/lsof -p &spid | grep control

select * from table(dbms_xplan.display_cursor);

And results before patching:

SQL> @cf_read
SQL> sho parameter control_files

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
control_files                        string      /u02/oradata/db/control01.
                                                 ctl, /u02/oradata/db/contr
                                                 ol02.ctl, /u02/oradata/db/
                                                 control03.ctl
SQL>
SQL> !/usr/sbin/lsof -p &spid | grep control

SQL>
SQL> with t1 as (select count(*) from t)
  2  select * from t1 t11, t1 t12;

  COUNT(*)   COUNT(*)
---------- ----------
     40899      40899

SQL>
SQL> !/usr/sbin/lsof -p &spid | grep control
oracle  10193 oracle10   10u   REG    8,8   7061504  2812547 /u02/oradata/db/control01.ctl
oracle  10193 oracle10   12u   REG    8,8   7061504  2812548 /u02/oradata/db/control02.ctl
oracle  10193 oracle10   13u   REG    8,8   7061504  2812549 /u02/oradata/db/control03.ctl

SQL>
SQL> select * from table(dbms_xplan.display_cursor);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID  6qkw8ngcufcsp, child number 0
-------------------------------------
with t1 as (select count(*) from t) select * from t1 t11, t1 t12

Plan hash value: 1049590287

--------------------------------------------------------------------------------------------------------
| Id  | Operation                  | Name                      | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |                           |       |       |   135 (100)|          |
|   1 |  TEMP TABLE TRANSFORMATION |                           |       |       |            |          |
|   2 |   LOAD AS SELECT           |                           |       |       |            |          |
|   3 |    SORT AGGREGATE          |                           |     1 |       |            |          |
|   4 |     TABLE ACCESS FULL      | T                         | 32156 |       |   131   (1)| 00:00:02 |
|   5 |   MERGE JOIN CARTESIAN     |                           |     1 |    26 |     4   (0)| 00:00:01 |
|   6 |    VIEW                    |                           |     1 |    13 |     2   (0)| 00:00:01 |
|   7 |     TABLE ACCESS FULL      | SYS_TEMP_0FD9D6600_198FEA |     1 |    13 |     2   (0)| 00:00:01 |
|   8 |    BUFFER SORT             |                           |     1 |    13 |     4   (0)| 00:00:01 |
|   9 |     VIEW                   |                           |     1 |    13 |     2   (0)| 00:00:01 |
|  10 |      TABLE ACCESS FULL     | SYS_TEMP_0FD9D6600_198FEA |     1 |    13 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------

Note
-----
   - dynamic sampling used for this statement

Results after:

SQL> @cf_read
SQL> sho parameter control_files

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
control_files                        string      /u02/oradata/db/control01.
                                                 ctl, /u02/oradata/db/contr
                                                 ol02.ctl, /u02/oradata/db/
                                                 control03.ctl
SQL>
SQL> !/usr/sbin/lsof -p &spid | grep control

SQL>
SQL> with t1 as (select count(*) from t)
  2  select * from t1 t11, t1 t12;

  COUNT(*)   COUNT(*)
---------- ----------
     40899      40899

SQL>
SQL> !/usr/sbin/lsof -p &spid | grep control

SQL>
SQL> select * from table(dbms_xplan.display_cursor);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------
SQL_ID  6qkw8ngcufcsp, child number 0
-------------------------------------
with t1 as (select count(*) from t) select * from t1 t11, t1 t12

Plan hash value: 2339794764

--------------------------------------------------------------------------------------------------------
| Id  | Operation                  | Name                      | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |                           |       |       |   135 (100)|          |
|   1 |  TEMP TABLE TRANSFORMATION |                           |       |       |            |          |
|   2 |   LOAD AS SELECT           |                           |       |       |            |          |
|   3 |    SORT AGGREGATE          |                           |     1 |       |            |          |
|   4 |     TABLE ACCESS FULL      | T                         | 44108 |       |   131   (1)| 00:00:02 |
|   5 |   MERGE JOIN CARTESIAN     |                           |     1 |    26 |     4   (0)| 00:00:01 |
|   6 |    VIEW                    |                           |     1 |    13 |     2   (0)| 00:00:01 |
|   7 |     TABLE ACCESS FULL      | SYS_TEMP_0FD9D6604_1987D5 |     1 |    13 |     2   (0)| 00:00:01 |
|   8 |    BUFFER SORT             |                           |     1 |    13 |     4   (0)| 00:00:01 |
|   9 |     VIEW                   |                           |     1 |    13 |     2   (0)| 00:00:01 |
|  10 |      TABLE ACCESS FULL     | SYS_TEMP_0FD9D6604_1987D5 |     1 |    13 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------

Note
-----
   - dynamic sampling used for this statement

The bug-fix is included into 11gR2, some 11gR1 and will be in 10.2.0.5.