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.

About these ads

2 Comments

  1. Jan
    Posted January 7, 2014 at 16:26 | Permalink | Reply

    Timur, do you have an explanation, why ‘control file sequential read’ is happening from all of the control files? Isn`t reading from the one file only sufficient enough?

    Thanks, Jan


    WAIT #1: nam=’control file sequential read’ ela= 44 file#=0 …
    WAIT #1: nam=’control file sequential read’ ela= 16 file#=1 …
    WAIT #1: nam=’control file sequential read’ ela= 14 file#=2 …

    • Posted January 12, 2014 at 18:39 | Permalink | Reply

      Hi Jan

      I don’t know why Oracle reads all control files’ headers.
      I think it may be related to the way control file is managed: all control files have to be available for normal DB operation, so these reads may be a check to ensure control files are indeed available and correct.

3 Trackbacks

  1. [...] 20-Controlfile sequential reads caused by subquery factoring Timur Akhadeev -Control File Sequential Read [...]

  2. By enq: CF – contention « Oracle mechanics on August 18, 2011 at 06:51

    [...] операции TEMP TABLE TRANSFORMATION – подробно описано в блоге Timur Akhmadeev «Control file sequential read», где указан и протестирован Bug 7515779, см.также [...]

  3. By Materialize « OraStory on January 17, 2012 at 14:48

    [...] In older versions as mentioned, you should find the recursive INSERT listed separately, e.g. (different database, different version, different temp table name and if you’re interested in the control file sequential read see this post by Timur Akhmadeev): [...]

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 289 other followers