2 Replies Latest reply: Feb 14, 2013 5:35 AM by Step_Into_Oracle_DBA RSS

    Error - Thread 1 cannot allocate new log, sequence ---  CPU load goes high

    868234
      Hi Experts,

      Can somebody help me to resolve the issue below:

      Found message in alert log file "Thread 1 cannot allocate new log, sequence 7963, Private strand flush not complete"
      I have 4 redo log groups with one member each, size of each redo log file is 128 MB( By doing some research on internet I found the solution to increase the redo logs file size which I tried upto 400MB each still getting the same error. If there is any other way to check optimal size of REDO FILES, without changing the size of FAST_START_MTTR_TARGET please share with me).

      CPU load goes high usually, I don't have AWR license, did not find any long Idle query. I tried to collect some data for wait events, hope this would help to understand the situation. There might some other reason as well for CPU load. Open for your suggestions. Please help me.

      Database size 20GB, Running on Redhat-5 Enterprise edition, physical RAM 34GB

      SQL> show parameter memory_target
      NAME TYPE VALUE
      ------------------------------------ ----------- ----------------------------
      memory_target big integer 26112M

      SQL> show parameter CPU_COUNT
      NAME TYPE VALUE
      ------------------------------------ ----------- ------------------------------
      cpu_count integer 4


      WAIT_CLASS Redo Log Buffer TIME_SECS PCT
      ---------------------------------------------------------------- ------------------------------ ---------- ----------
      CPU server CPU 233452.23 54.56
      Application enq: TX - row lock contention 137406.97 32.11
      Commit log file sync 16885.79 3.95
      System I/O log file parallel write 11820.69 2.76
      User I/O db file sequential read 5203.97 1.22
      Concurrency latch: shared pool 3306.55 .77
      Network SQL*Net message to client 3261.35 .76
      Configuration log file switch (checkpoint in 2707.12 .63
      System I/O control file sequential read 2315.88 .54
      System I/O log file sequential read 2226.74 .52
      Concurrency library cache: mutex X 2198.97 .51
      System I/O control file parallel write 1502.29 .35
      Network SQL*Net more data to client 917.57 .21
      Network SQL*Net more data from client 841.16 .2
      Scheduler resmgr:cpu quantum 830.34 .19
      User I/O db file scattered read 758.68 .18
      Concurrency latch: row cache objects 359.34 .08
      Configuration log buffer space 287.33 .07
      Concurrency os thread startup 237.27 .06
      Other rdbms ipc reply 169.82 .04
      User I/O direct path read 140.75 .03
      Other SGA: allocation forcing compon 137.89 .03
      System I/O db file parallel write 109.76 .03
      Other latch free 102.31 .02
      Other buffer exterminate 101.99 .02
      User I/O db file parallel read 59.76 .01
      System I/O Log archive I/O 51.75 .01
      Other latch: call allocation 43.89 .01
      Configuration undo segment extension 40.35 .01
      User I/O Disk file operations I/O 35.28 .01
      Other enq: CR - block range reuse ck 33.14 .01


      SQL> SELECT SUBSTR(name,1,20) "Name",gets,misses,immediate_gets,immediate_misses
      FROM v$latch
      WHERE name in ('redo allocation', 'redo copy'); 2 3

      Redo Log Buffer GETS MISSES IMMEDIATE_GETS IMMEDIATE_MISSES
      ------------------------------ ---------- ---------- -------------- ----------------
      redo copy 91 13 223569098 24024
      redo allocation 248772805 140911 0 0


      SQL> select C.VALUE / D.VALUE as NR_RECC
      from V$SYSSTAT C,
      V$SYSSTAT D
      where C.NAME = 'recursive calls'
      and D.NAME = 'user calls' 2 3 4 5
      6 ;

      Parse per Execute [%]

      NR_RECC
      ---------
      0.08


      WAIT_CLASS Redo Log Buffer TIME_SECS PCT
      ------------------------------ ------------------------------ ---------- ----------
      CPU server CPU 233847.34 54.59
      Application enq: TX - row lock contention 137407.88 32.08
      Commit log file sync 16917.06 3.95
      System I/O log file parallel write 11842.69 2.76
      User I/O db file sequential read 5208.33 1.22
      Concurrency latch: shared pool 3326.52 .78
      Network SQL*Net message to client 3265.76 .76
      Configuration log file switch (checkpoint in 2707.12 .63
      System I/O control file sequential read 2317.32 .54
      System I/O log file sequential read 2228.2 .52
      Concurrency library cache: mutex X 2215.55 .52
      System I/O control file parallel write 1503.31 .35
      Network SQL*Net more data to client 919.41 .21
      Network SQL*Net more data from client 842.18 .2
      Scheduler resmgr:cpu quantum 830.34 .19
      User I/O db file scattered read 758.69 .18
      Concurrency latch: row cache objects 360.04 .08
      Configuration log buffer space 287.33 .07
      Concurrency os thread startup 237.97 .06
      Other rdbms ipc reply 169.83 .04
      User I/O direct path read 140.78 .03
      Other SGA: allocation forcing compon 137.89 .03
      System I/O db file parallel write 110.19 .03
      Other latch free 102.4 .02
      Other buffer exterminate 101.99 .02
      User I/O db file parallel read 59.76 .01
      System I/O Log archive I/O 51.76 .01
      Other latch: call allocation 43.89 .01
      Configuration undo segment extension 41.32 .01
      User I/O Disk file operations I/O 35.3 .01

      Daily Transactions Report:

      SQL> select v1 "Total Commits",
      2 v2 "Total Rollbacks",
      3 v3 "Total User Calls",
      stut "Startup Time",
      4 5 t1 "Uptime in days",
      6 s1/t1 "Avg Daily DML Transactions",
      7 v3/t1 "Avg Daily User Calls"
      8 from
      9 (select value v1 from v$sysstat where name='user commits'),
      10 (select value v2 from v$sysstat where name='user rollbacks'),
      11 (select sum(value) s1 from v$sysstat where name in ('user commits', 'user rollbacks')),
      12 (select value v3 from v$sysstat where name='user calls'),
      (select startup_time stut from v$instance),
      13 14 (select sysdate-startup_time t1 from v$instance);

      Total Commits Total Rollbacks Total User Calls Startup T Uptime in days Avg Daily DML Transactions Avg Daily User Calls
      ------------- --------------- ---------------- --------- -------------- -------------------------- --------------------
      3889090 112421 1790448280 08-FEB-13 5.59989583 714569.006 319728854

      LOG BUFFER SIZE

      select sum(value)/1024/1024 from v$parameter where name = 'log_buffer';

      SUM(VALUE)/1024/1024
      --------------------
      8.8984375

      LOG HISTORY RESULT

      SQL> SELECT to_date(first_time) DAY,
      2 to_char(sum(decode(to_char(first_time,'HH24'),'00',1,0)),'99') "00",
      3 to_char(sum(decode(to_char(first_time,'HH24'),'01',1,0)),'99') "01",
      4 to_char(sum(decode(to_char(first_time,'HH24'),'02',1,0)),'99') "02",
      5 to_char(sum(decode(to_char(first_time,'HH24'),'03',1,0)),'99') "03",
      6 to_char(sum(decode(to_char(first_time,'HH24'),'04',1,0)),'99') "04",
      7 to_char(sum(decode(to_char(first_time,'HH24'),'05',1,0)),'99') "05",
      8 to_char(sum(decode(to_char(first_time,'HH24'),'06',1,0)),'99') "06",
      9 to_char(sum(decode(to_char(first_time,'HH24'),'07',1,0)),'99') "07",
      10 to_char(sum(decode(to_char(first_time,'HH24'),'08',1,0)),'99') "08",
      11 to_char(sum(decode(to_char(first_time,'HH24'),'09',1,0)),'99') "09",
      12 to_char(sum(decode(to_char(first_time,'HH24'),'10',1,0)),'99') "10",
      13 to_char(sum(decode(to_char(first_time,'HH24'),'11',1,0)),'99') "11",
      14 to_char(sum(decode(to_char(first_time,'HH24'),'12',1,0)),'99') "12",
      15 to_char(sum(decode(to_char(first_time,'HH24'),'13',1,0)),'99') "13",
      to_char(sum(decode(to_char(first_time,'HH24'),'14',1,0)),'99') "14",
      16 17 to_char(sum(decode(to_char(first_time,'HH24'),'15',1,0)),'99') "15",
      18 to_char(sum(decode(to_char(first_time,'HH24'),'16',1,0)),'99') "16",
      19 to_char(sum(decode(to_char(first_time,'HH24'),'17',1,0)),'99') "17",
      20 to_char(sum(decode(to_char(first_time,'HH24'),'18',1,0)),'99') "18",
      21 to_char(sum(decode(to_char(first_time,'HH24'),'19',1,0)),'99') "19",
      22 to_char(sum(decode(to_char(first_time,'HH24'),'20',1,0)),'99') "20",
      23 to_char(sum(decode(to_char(first_time,'HH24'),'21',1,0)),'99') "21",
      24 to_char(sum(decode(to_char(first_time,'HH24'),'22',1,0)),'99') "22",
      25 to_char(sum(decode(to_char(first_time,'HH24'),'23',1,0)),'99') "23"
      from
      26 27 v$log_history
      28 where to_date(first_time) > sysdate -8
      GROUP by
      29 30 to_char(first_time,'YYYY-MON-DD'), to_date(first_time)
      31 order by to_date(first_time);

      DAY 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
      --------- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
      07-FEB-13 14 12 12 12 14 14 11 12 12 11 12 12 12 12 12 12 12 12 11 12 12 12 11 12
      08-FEB-13 12 12 16 12 12 11 12 13 15 13 12 11 12 12 12 12 12 12 14 17 12 16 12 13
      09-FEB-13 12 12 11 12 12 13 14 12 11 12 12 12 11 12 12 13 13 12 12 13 11 13 12 12
      10-FEB-13 11 13 12 12 11 14 14 12 14 12 12 12 12 12 13 11 12 12 12 12 12 11 12 12
      11-FEB-13 12 11 15 12 12 13 12 12 12 12 11 12 13 11 14 12 12 12 12 12 12 12 12 12
      12-FEB-13 11 12 12 12 14 13 12 12 13 11 12 14 12 12 12 12 13 11 14 13 11 12 14 14
      13-FEB-13 11 12 13 12 12 14 11 12 12 12 14 13 12 12 12 11 12 12 12 12 11 12 12 12
      14-FEB-13 11 12 12 12 12 14 11 12 12 4 0 0 0 0 0 0 0 0 0 0 0 0 0 0


      SQL> SELECT A.*,
      Round(A.Count#*B.AVG#/1024/1024) Daily_Avg_Mb
      2 3 FROM
      4 (
      5 SELECT
      6 To_Char(First_Time,'YYYY-MM-DD') DAY,
      7 Count(1) Count#,
      8 Min(RECID) Min#,
      9 Max(RECID) Max#
      10 FROM
      11 v$log_history
      12 GROUP
      13 BY To_Char(First_Time,'YYYY-MM-DD')
      14 ORDER
      15 BY 1 DESC
      16 ) A,
      17 (
      18 SELECT
      Avg(BYTES) AVG#,
      19 20 Count(1) Count#,
      21 Max(BYTES) Max_Bytes,
      22 Min(BYTES) Min_Bytes
      23 FROM
      24 v$log
      25 ) B;

      DAY COUNT# MIN# MAX# DAILY_AVG_MB
      ---------- ---------- ---------- ---------- ------------
      2013-02-14 112 12983 13094 14336
      2013-02-13 290 12693 12982 37120
      2013-02-12 298 12395 12692 38144
      2013-02-11 292 12103 12394 37376
      2013-02-10 292 11811 12102 37376
      2013-02-09 291 11520 11810 37248
      2013-02-08 307 11213 11519 39296
      2013-02-07 290 10923 11212 37120
      2013-02-06 299 10624 10922 38272
      2013-02-05 301 10323 10623 38528
      2013-02-04 148 10175 10322 18944

      Below are some more statistics which might help you to understand more:

      Monitor Cursor Activites

      Statistic Waits
      -------------------------------- -----------
      opened cursors cumulative....... ###########
      opened cursors current.......... 2,233
      user commits.................... 3,904,166
      user rollbacks.................. 112,844
      user calls...................... ###########
      recursive calls................. ###########
      pinned cursors current.......... 2,052
      session cursor cache hits....... 34,550,647
      session cursor cache count...... 1,232,517
      cursor authentications.......... 13,855,396
      parse time cpu.................. 8,433,285
      parse time elapsed.............. 14,428,318
      execute count................... ###########

      SQL> show parameter log_checkpoint_timeout

      NAME TYPE VALUE
      ------------------------------------ ----------- ------------------------------ (have tried to made it 0 and updated the checkpoint interval to 15 to increase the time of checkpointing)
      log_checkpoint_timeout integer 1800
      SQL>


      SQL> show parameter log_checkpoint_interval

      NAME TYPE VALUE
      ------------------------------------ ----------- ------------------------------
      log_checkpoint_interval integer 0

      Thanks in advance!!!!

      Edited by: 865231 on Feb 14, 2013 4:18 PM