3 Replies Latest reply on Mar 21, 2013 4:40 PM by jgarry

    M001 timing out, high "control file sequential read"

    mtefft
      select * from v$version;
      
      BANNER
      --------------------------------------------------------------------------------
      Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
      PL/SQL Release 11.2.0.3.0 - Production
      CORE    11.2.0.3.0      Production
      TNS for Linux: Version 11.2.0.3.0 - Production
      NLSRTL Version 11.2.0.3.0 - Production
      
      5 rows selected.
      We are getting very high "control file sequential read" by M001 during our AWR snapshot collection. M001 is timing out after 15 minutes, with the following being reported in the trace file:
      ----- START DDE Actions Dump -----
      Executing SYNC actions
      Executing ASYNC actions
      ----- START DDE Action: 'ORA_12751_DUMP' (Sync) -----
      Runtime exceeded 900 seconds
      Time limit violation detected at:
      ksedsts()+461<-kspol_12751_dump()+145<-dbgdaExecuteAction()+1065<-dbgerRunAction()+109<-dbgerRunActions()+4053<-dbgexPhaseII()+1873<-dbgexProcessError()+2680<-dbgeExecuteForError()+88<-dbgePostErrorKGE()+2143<-dbkePostKGE_kgsf()+71<-kgeade()+351<-kgerelv()+140
      <-kgerev()+34<-kserec1()+170<-OCIKSEC()+189<-kewrose_oci_stmt_exec()+292<-kewrgwxf1_gwrsql_exft_1()+317<-kewrgwxf_gwrsql_exft()+487<-kewrews_execute_wr_sql()+52<-kewrftbs_flush_table_by_sql()+180<-kewrft_flush_table()+264<-kewrftec_flush_table_ehdlcx()+752
      <-kewrftms_flush_tempstat()+45<-kewrft_flush_table()+397<-kewrftec_flush_table_ehdlcx()+752<-kewrfat_flush_all_tables()+898<-kewrfos_flush_onesnap()+170<-kewrfsc_flush_snapshot_c()+623<-kewrafs_auto_flush_slave()+757<-kebm_slave_main()+580<-ksvrdp()+1779<-opirip()+674
      <-opidrv()+603<-sou2o()+103<-opimai_real()+266<-ssthrdmain()+252<-main()+201<-__libc_start_main()+253<-_start()+36Current Wait Stack:
        Not in wait; last wait ended 0.077559 sec ago 
      Wait State:
        fixed_waits=0 flags=0x21 boundary=(nil)/-1
      Session Wait History:
          elapsed time of 0.077586 sec since last wait
       0: waited for 'control file sequential read'
          file#=0x0, block#=0x20, blocks=0x1
          wait_id=5267025 seq_num=24226 snap_id=1
          wait times: snap=0.000128 sec, exc=0.000128 sec, total=0.000128 sec
          wait times: max=infinite
          wait counts: calls=0 os=0
          occurred after 0.000010 sec of elapsed time
       1: waited for 'control file sequential read'
          file#=0x0, block#=0x11, blocks=0x1
          wait_id=5267024 seq_num=24225 snap_id=1
          wait times: snap=0.000098 sec, exc=0.000098 sec, total=0.000098 sec
          wait times: max=infinite
          wait counts: calls=0 os=0
          occurred after 0.000010 sec of elapsed time
       2: waited for 'control file sequential read'
          file#=0x0, block#=0xf, blocks=0x1
          wait_id=5267023 seq_num=24224 snap_id=1
          wait times: snap=0.000114 sec, exc=0.000114 sec, total=0.000114 sec
          wait times: max=infinite
          wait counts: calls=0 os=0
          occurred after 0.000011 sec of elapsed time
      <snip>
      ----- END DDE Action: 'ORA_12751_DUMP' (SUCCESS, 2 csec) -----
      ----- END DDE Actions Dump (total 2 csec) -----
      *** KEWRAFM1: Error=13509 encountered by kewrfteh
      *** KEWRAFM1: Error=13509 encountered by kewrfteh
      *** KEWRAFS: Error=13509 encountered by Auto Flush Slave.
      KEBM: MMON slave action policy violation. kewrmafsa_; viol=1; err=13509
      1. Can anyone say 'Aha! I recognize that!'
      2. Is there any way to drill into localizing the specific file (file#=0x0, block=0x20, etc.) that is involved here?

      From what I can see, the waits are short (<= 1ms) but there are very many of them (> 5 million since our instance startup less than 2 hours ago).

      Thanks,
      Mike