Note: all tests are done in Oracle 12.1.0.2.0.
1. control file sequential read Watching
Run query and trace by Event 10046:
SQL (sid 35) > select name from v$database;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 1
Rows Row Source Operation
------- ---------------------------------------------------
1 MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=311 us cost=0 size=12 card=1)
1 FIXED TABLE FULL X$KCCDI (cr=0 pr=0 pw=0 time=176 us cost=0 size=12 card=1)
1 BUFFER SORT (cr=0 pr=0 pw=0 time=134 us cost=0 size=0 card=1)
1 FIXED TABLE FULL X$KCCDI2 (cr=0 pr=0 pw=0 time=121 us cost=0 size=0 card=1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
control file sequential read 7 0.00 0.00
********************************************************************************
We can see that each name query on v$database triggers 7 control file sequential read.
The similar statistics can be observed by:
select * from v$session_event where event = 'control file sequential read' and sid = 35;
select * from v$system_event where event = 'control file sequential read';
Run the same query again and truss unix process:
SQL (sid 35) > select name from v$database;
oracle@testdb $ truss -t pread -p 4326
pread(257, "15C2\0\001\0\0\0\0\0\0\0".., 16384, 16384) = 16384
pread(257, "15C2\0\007\0\0\08A141D\0".., 16384, 114688) = 16384
pread(257, "15C2\0\0\t\0\0\08A141D\0".., 16384, 147456) = 16384
pread(257, "15C2\0\001\0\0\0\0\0\0\0".., 16384, 16384) = 16384
pread(257, "15C2\0\007\0\0\08A141D\0".., 16384, 114688) = 16384
pread(257, "15C2\0\0\t\0\0\08A141D\0".., 16384, 147456) = 16384
pread(257, "15C2\0\08004\0\08A141D\0".., 16384, 0x01200000) = 16384
oracle@testdb $ pfiles 4326
257: S_IFREG mode:0640 dev:181,65553 ino:4300 uid:100 gid:101 size:24264704
O_RDWR|O_DSYNC|O_LARGEFILE FD_CLOEXEC
advisory write lock set by process 16900
/oratestdb/oradata/testdb/control01.ctl
-- where 4326 is pid of Oracle sid 35, 257 is fd of first control file.
-- 16384/8192 = 2 means 2 data blocks read per pread call
Monitoring the same query by dtrace:
oracle@testdb $ sudo dtrace -n 'pid$target::_pread:entry {@[arg0, ustack(12, 0)] = count();}' -p 4326
257
libc.so.1`_pread libc.so.1`_pread libc.so.1`_pread
libc.so.1`pread+0x85 libc.so.1`pread+0x85 libc.so.1`pread+0x85
oracle`skgfqio+0x284 oracle`skgfqio+0x284 oracle`skgfqio+0x284
oracle`ksfd_skgfqio+0x195 oracle`ksfd_skgfqio+0x195 oracle`ksfd_skgfqio+0x195
oracle`ksfd_io+0x2e79 oracle`ksfd_io+0x2e79 oracle`ksfd_io+0x2e79
oracle`ksfdread+0x746 oracle`ksfdread+0x746 oracle`ksfdread+0x746
a.out`kccrhd+0x208 a.out`kccrbp+0x279 a.out`kccrbp+0x279
a.out`kccgft_refresh_hdr+0x68 a.out`kccsed_rbl+0x1dc a.out`kccsed_rbl+0xfc
a.out`kccgftcs+0x2a2 a.out`kccgft_refresh_hdr+0x141 a.out`kccgft_refresh_hdr+0x141
a.out`kccxdi+0x8d a.out`kccgftcs+0x2a2 a.out`kccgftcs+0x2a2
a.out`qerfxFetch+0x5df a.out`kccxdi+0x8d a.out`kccxdi+0x8d
a.out`rwsfcd+0x6f a.out`qerfxFetch+0x5df a.out`qerfxFetch+0x5df
libc.so.1`_pread libc.so.1`_pread
libc.so.1`pread+0x85 libc.so.1`pread+0x85
oracle`skgfqio+0x284 oracle`skgfqio+0x284
oracle`ksfd_skgfqio+0x195 oracle`ksfd_skgfqio+0x195
oracle`ksfd_io+0x2e79 oracle`ksfd_io+0x2e79
oracle`ksfdread+0x746 oracle`ksfdread+0x746
a.out`kccrhd+0x208 a.out`kccrbp+0x279
a.out`kccgft_refresh_hdr+0x68 a.out`kccrec_rbl+0x1c2
a.out`kccgftcs+0x2a2 a.out`kccrec_read_write+0x19b
a.out`kccxdi2+0x8c a.out`kccgftcs+0x36a
a.out`qerfxFetch+0x5df a.out`kccxdi2+0x8c
a.out`qersoProcessULS+0x26f a.out`qerfxFetch+0x5df
libc.so.1`_pread libc.so.1`_pread
libc.so.1`pread+0x85 libc.so.1`pread+0x85
oracle`skgfqio+0x284 oracle`skgfqio+0x284
oracle`ksfd_skgfqio+0x195 oracle`ksfd_skgfqio+0x195
oracle`ksfd_io+0x2e79 oracle`ksfd_io+0x2e79
oracle`ksfdread+0x746 oracle`ksfdread+0x746
a.out`kccrbp+0x279 a.out`kccrbp+0x279
a.out`kccsed_rbl+0x1dc a.out`kccsed_rbl+0xfc
a.out`kccgft_refresh_hdr+0x141 a.out`kccgft_refresh_hdr+0x141
a.out`kccgftcs+0x2a2 a.out`kccgftcs+0x2a2
a.out`kccxdi2+0x8c a.out`kccxdi2+0x8c
a.out`qerfxFetch+0x5df a.out`qerfxFetch+0x5df
The above output shows all 7 I/O reads of first control file (fd: 257),
among which, there are 2 Calls of subroutine "kccrhd", and 5 Calls of subroutine"kccrbp".The xplan in Event 10046 trace contains two different row sources: "X$KCCDI" and "X$KCCDI2", Dtrace shows the respective Calls; 3 "kccxdi", and 4 "kccxdi2".
All are finalized by function "ksfdread", which probably denotes file direct read.
Since each select on v$database is implemented by a few disk I/O Reads (7 in above example, 14 if select all columns), concurrently accesses can entail severe wait event on control file sequential read, which often appears as one of AWR Top Wait Events.
As a test, run following Plsql on Sqlplus (Linux PID: 1303397) in one Linux DB:
begin
for i in 1..1e5 loop
for c in (select * from v$database) loop
null;
end loop;
end loop;
end;
/
$ > strace -ttT -p 1303397
10:34:47.844424 pread64(256, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4f\257\0\0\0\0\0\0\0\0\0\23\31H'?"..., 16384, 16384) = 16384 <0.000068>
10:34:47.844528 pread64(256, "\25\302\0\0\7\0\0\0\334@m\0\377\377\1\4\2538\0\0\0\230\360a\336n?\331\354}*\6"..., 16384, 114688) = 16384 <0.000059>
10:34:47.844620 pread64(256, "\25\302\0\0\t\0\0\0\334@m\0\377\377\1\4\35T\0\0\0\0\0\0\0\0\0\0\225\6\373H"..., 16384, 147456) = 16384 <0.000059>
$ > lsof -p 1303397
oracle_13 1303397 oracle 256u REG 8,1 32620544 645940932 /oratestdb/oradata/testdb/control01.ctl
oracle_13 1303397 oracle 257u REG 8,1 32620544 645940933 /oratestdb/oradata/testdb/control02.ctl
oracle_13 1303397 oracle 258u REG 8,1 32620544 645940934 /oratestdb/oradata/testdb/control03.ctl
2. Impact on WRH$ Tables
Under heavy "control file sequential read", only partial data can be flushed into WRH$ tables. MZnn shows MMON ORA-12751.
*** MODULE NAME:(MMON_SLAVE)
*** ACTION NAME:(Auto-DBFUS Action)
DDE rules only execution for: ORA 12751
----- START Event Driven Actions Dump ----
---- END Event Driven Actions Dump ----
----- START DDE Actions Dump -----
Executing SYNC actions
Executing ASYNC actions
----- START DDE Action: 'ORA_12751_DUMP' (Sync) -----
Runtime exceeded 3600 seconds
Time limit violation detected at:
----- Abridged Call Stack Trace -----
ksedsts()+426<-kspol_12751_dump()+168<-dbgdaExecuteAction()+354<-dbgerRunAction()+83<-dbgerRunActions()+1361<-dbgexPhaseII()+584<-dbgexProcessError()+1912<-dbgePost
ErrorKGE()+1853<-dbkePostKGE_kgsf()+71<-kgeade()+401<-kgeselv()+89<-ksesecl0()+189<-ksucin()+1461
<-qerfxFetch()+8202<-qerjotFetch()+450<-qerjotFetch()+631<-qerjotFetch()+631<-rwsfcd()+113<-qeruaFetch()+385<-qervwFetch()+166<-qerjotFetch()+450<-qerjotFetch()+631
<-qerjoFetch()+756<-qerghFetch()+584<-qervwFetch()+166<-qerghFetch()+584<-opifch2()+3316<-opifch()+61
<-opipls()+11918<-opiodr()+1264<-rpidrus()+198<-skgmstack()+65<-rpidru()+151<-rpiswu2()+543<-rpidrv()+1281<-psddr0()+467<-psdnal()+624<-pevm_BFTCHC()+322<-pfrinstr_
BFTCHC()+150<-pfrrun_no_tool()+52<-pfrrun()+904<-plsql_run()+752<-peicnt()+279<-kkxexe()+720
<-opiexe()+31522<-opiall0()+1382<-opikpr()+595<-opiodr()+1264<-rpidrus()+198<-skgmstack()+65<-rpidru()+151<-rpiswu2()+543<-kprball()+1055<-kkxspdbswitch_cbk()+1615<
-kkxsexr()+279<-kkxsexe()+661<-pevm_icd_call_common()+835<-pfrinstr_ICAL()+128<-pfrrun_no_tool()+52
<-pfrrun()+904<-plsql_run()+752<-peicnt()+279<-kkxexe()+720<-opiexe()+31522<-kpoal8()+2301<-opiodr()+1264<-kpoodrc()+40<-rpiswu2()+2004<-kpoodr()+695<-upirtrc()+314
4<-kpurcsc()+100<-kpuexec()+11450<-OCIStmtExecute()+41<-keuuxs_execute_statement()+706<-kewfeus_execute_usage_sampling()+300
<-kewfads_dbfus_slave_impl()+976<-kewfads_auto_dbfus_slave()+357<-kebmscw_slave_cb_wrapper()+21<-kebmiasc_invoke_action_switch_cb()+154<-kebmpsp_pdb_switch_private(
)+113<-kebm_slave_main()+1009<-ksvrdp_int()+2496<-opirip()+579<-opidrv()+581<-sou2o()+165<-opimai_real()+173
<-ssthrdmain()+417<-main()+256<-__libc_start_main()+229<-_start()+46
----- End of Abridged Call Stack Trace -----
declare
l_timeout_secs number := 3;
begin
-- Oracle knows that such an error can happen, hence conceived such a parameter to help their users.
DBMS_WORKLOAD_REPOSITORY.create_snapshot(flush_level => 'ALL', timeout_secs => l_timeout_secs);
exception when others then
if sqlcode = -13559 then --ORA-13559: CPU time or run time policy violation
dbms_output.put_line('Create AWR with l_timeout_secs (' || l_timeout_secs ||') '||sqlerrm);
else
raise;
end if;
end;
/
Create AWR with l_timeout_secs (3) ORA-13559: CPU time or run time policy
violation - AWR snapshot creation exceeded runtime limit of 3 seconds
AWR manual snapshot (109622) failed: DBID=1059538969, ERROR=12751
DDE rules only execution for: ORA 12751
----- START Event Driven Actions Dump ----
---- END Event Driven Actions Dump ----
----- START DDE Actions Dump -----
Executing SYNC actions
Executing ASYNC actions
----- START DDE Action: 'ORA_12751_DUMP' (Sync) -----
Runtime exceeded 3 seconds
Time limit violation detected at:
----- Abridged Call Stack Trace -----
ksedsts()+426<-kspol_12751_dump()+168<-dbgdaExecuteAction()+354<-dbgerRunAction()+83<-dbgerRunActions()+1361<-dbgexPhaseII()+584<-dbgexProcessError()+1912<-dbgePostErrorKGE()+1853<-dbkePostKGE_kgsf()+71<-kgeade()+401<-kgeselv()+89<-ksesecl0()+189<-ksucin()+1461
<-qerfxFetch()+8202<-qerjotFetch()+2094<-qerjotFetch()+2094<-qergsFetch()+25605<-qervwFetch()+166<-qerjotFetch()+631<-rwsfcd()+113<-qerltcFetch()+1058<-insexe()+736<-opiexe()+7179<-kpoal8()+2301<-opiodr()+1264<-kpoodrc()+40<-rpiswu2()+2004<-kpoodr()+695<-upirtrc()+3144
<-kpurcsc()+100<-kpuexec()+10396<-OCIStmtExecute()+41<-keuqsei_sql_exec_int()+432<-keuqser_sql_exec_reg()+518<-keuqsew_sql_exec_wec()+351<-kewrgwxf1_gwrsql_exft_1()+590<-kewrfdbs_flush_data_by_sql()+384<-kewrft_flush_table()+1083<-kewrftecpc_flush_table_ehdlcx_policy_cb()+566
<-keumpole_exec()+312<-kewrtftp_tbl_flush_task_policy()+330<-kewrfat1_flush_all_tables_1()+984<-kewrfat_flush_all_tables()+403<-kewrfop_flush_one_phase()+532<-kewrfap_flush_all_phases()+406<-kewrfmsp2_fos_srcdb_part2()+399<-kewrfos_flush_onesnap()+147<-kewrfsc_flush_snapshot_c()+886
<-kewrfmspc_flush_mdb_snap_policy_cb()+977<-keumpole_exec()+312<-kewrcmdbs_flush_mdb_snap()+435<-kewrpcs_create_snapshot_i()+731<-kewrpcstx_create_snapshot_wtxn()+694<-kewrpcs_create_snapshot()+899<-spefcpfa()+567<-spefmccallstd()+551<-peftrusted()+139<-psdexsp()+285
<-rpiswu2()+2004<-kxe_push_env_internal_pp_()+370<-kkx_push_env_for_ICD_for_new_session()+149<-psdextp()+387<-pefccal()+663<-pefcal()+223<-pevm_FCAL()+171<-pfrinstr_FCAL()+62<-pfrrun_no_tool()+52<-pfrrun()+904<-plsql_run()+752<-peicnt()+279<-kkxexe()+720<-opiexe()+31522
<-kpoal8()+2301<-opiodr()+1264<-ttcpip()+1255<-opitsk()+1925<-opiino()+935<-opiodr()+1264<-opidrv()+1094<-sou2o()+165<-opimai_real()+422<-ssthrdmain()+417<-main()+256<-__libc_start_main()+229<-_start()+46
----- End of Abridged Call Stack Trace -----
[1 sample, 16:08:35]
waited for 'control file sequential read', seq_num: 4032
p1: 'file#'=0x0
p2: 'block#'=0x1
p3: 'blocks'=0x1
3. Other control file related Objects
There are a few control files based views, which can be listed by:
select * from v$fixed_view_definition where lower(view_definition) like '%x$kcc%';
for example, gv$archive, v$block_change_tracking, gv$deleted_object, v$tablespace.
Any access to them will lead to similar effect as v$database.As a test, run query below, the session event shows "control file sequential read" since v$tablespace is defined on X$KCCTS and xplan rowsource accesses X$KCCTS by FIXED TABLE FULL:
with sq as (select level from dual connect by level <= 1e6)
select /*+ leading(s) use_nl(tbs) */ count(*) from sq s, v$tablespace tbs;
-------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 7 | 2 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 7 | | |
| 2 | NESTED LOOPS | | 1557 | 10899 | 2 (0)| 00:00:01 |
| 3 | VIEW | | 1 | | 2 (0)| 00:00:01 |
|* 4 | CONNECT BY WITHOUT FILTERING| | | | | |
| 5 | FAST DUAL | | 1 | | 2 (0)| 00:00:01 |
|* 6 | FIXED TABLE FULL | X$KCCTS | 1557 | 10899 | 0 (0)| 00:00:01 |
-------------------------------------------------------------------------------------------
dba_scheduler_jobs dba_scheduler_running_jobswhose definitions containing v$database. They can be listed by:
select * from dba_dependencies where referenced_name = 'V$DATABASE';
Further more, there are also Oracle applications, which is using v$database, for example,
MMON Slave Process.
4. Control File Size
Two queries can be used to display Control File size, and details per section.
select v.*, round(block_size*file_size_blks/1024/1024, 2) MB from v$controlfile v;
select v.*, round(record_size*records_total/1024/1024, 2) MB from v$controlfile_record_section v order by MB desc;
select * from v$parameter where name = 'control_file_record_keep_time';