Skip to Main Content

Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

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

868234Feb 14 2013 — edited Feb 14 2013
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
Comments
Locked Post
New comments cannot be posted to this locked post.
Post Details
Locked on Mar 14 2013
Added on Feb 14 2013
2 comments
1,118 views