3 Replies Latest reply: Mar 21, 2013 11:40 AM by jgarry RSS

    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
        • 1. Re: M001 timing out, high "control file sequential read"
          mtefft
          We found this bug, which seems to be a match:
          Bug 13257247 - AWR Snapshot collection hangs due to slow inserts into WRH$_TEMPSTATXS. [ID 13257247.8]
          • 2. Re: M001 timing out, high "control file sequential read"
            damorgan
            To quote a book I am writing ... "No organization knows more about how to install an Oracle database than Oracle and no organization's default practice is worse."

            Let me guess ... you did a vanilla OUI or DBCA install with all three control files sharing the same directory as all of the datafiles? Did I get it right?

            Start here:
            http://www.confio.com/logicalread/oracle-control-file-read-write-wait-events/

            However ignore Confio's advice of using mirroring rather than multiplexing. On that point Confio is clueless. Delete the file and the mirror copy evaporates instantly. With multiplexing you can accidentally delete one file and the database will survive. Finally who is Confio talking to? Is there anyone out here that doesn't have mirrored storage except perhaps on a laptop?

            That said ... there have been bugs reported with various versions and it appears from your second comment you may have hit one.
            • 3. Re: M001 timing out, high "control file sequential read"
              jgarry
              Did you say you are writing a book?