How many log switches per hour is normal?

we had a production database for one of our cloudera application.The application users started scheduled and batch jobs on the database.There was a complaint from application team about the slow performance.When we diagnosed the logfile,we found out that there was frequent log switches and archive generation which filled FRA space very fast.So we had to increase the number of redo groups and members and increase the size of the redolog files.

Redologs are the logs which records the changes happening in a database with a SCN value during every checkpoints.The LGWR is the process which writes or flushes the redos from log buffer to the online redolog files for every 3 seconds,1/3 rd of the redolog file full and when the user issues a commit.

If we have a production database which performs lot of transactions due to peak workload in the application activity,then the database instance generates high redos and these redos has to be switched between the groups

Hence the redolog file has to be sized properly for a production database.

I create a sample table

SQL> create table t1 (emp varchar2(10),emp_id number(10) not null,company varchar2(10),salary decimal(10));

Table created.

I insert some huge data into the table

SQL> set timing on
SQL> set time on
07:46:32 SQL> BEGIN
07:46:34   2  FOR I IN 10000 .. 200000 LOOP
07:46:37   3  INSERT INTO T1 values('xyz',i,'abc',i);
07:46:49   4  END LOOP;
07:46:52   5  COMMIT;
07:46:55   6  END;
07:46:57   7  /


The logs shows the redolog switch between groups with a new sequence number and redologs are archived in a physical file.

[oracle@orcl12x ~]$ tail -f /app01/base/diag/rdbms/orcl12x/orcl12x/trace/alert_orcl12x.log

Wed Sep 23 07:43:40 2020
Resize operation completed for file# 3, old size 706560K, new size 716800K
Wed Sep 23 07:47:26 2020
Resize operation completed for file# 1, old size 921600K, new size 931840K
Wed Sep 23 07:47:34 2020
Thread 1 advanced to log sequence 69 (LGWR switch)
  Current log# 3 seq# 69 mem# 0: /app01/base/oradata/orcl12x/redo03.log
Wed Sep 23 07:47:35 2020
Archived Log entry 57 added for thread 1 sequence 68 ID 0x741b2754 dest 1:
Wed Sep 23 07:50:58 2020
Thread 1 advanced to log sequence 70 (LGWR switch)
  Current log# 1 seq# 70 mem# 0: /app01/base/oradata/orcl12x/redo01.log
Wed Sep 23 07:51:01 2020
Archived Log entry 58 added for thread 1 sequence 69 ID 0x741b2754 dest 1:
Wed Sep 23 07:51:08 2020
Thread 1 cannot allocate new log, sequence 71
Checkpoint not complete
  Current log# 1 seq# 70 mem# 0: /app01/base/oradata/orcl12x/redo01.log
Wed Sep 23 07:51:08 2020
Resize operation completed for file# 1, old size 931840K, new size 942080K
Wed Sep 23 07:51:11 2020
Thread 1 advanced to log sequence 71 (LGWR switch)
  Current log# 2 seq# 71 mem# 0: /app01/base/oradata/orcl12x/redo02.log
Wed Sep 23 07:51:15 2020
Archived Log entry 59 added for thread 1 sequence 70 ID 0x741b2754 dest 1:
Wed Sep 23 07:51:21 2020
Thread 1 cannot allocate new log, sequence 72
Checkpoint not complete
  Current log# 2 seq# 71 mem# 0: /app01/base/oradata/orcl12x/redo02.log
Wed Sep 23 07:51:24 2020
Thread 1 advanced to log sequence 72 (LGWR switch)
  Current log# 3 seq# 72 mem# 0: /app01/base/oradata/orcl12x/redo03.log
Wed Sep 23 07:51:27 2020
Archived Log entry 60 added for thread 1 sequence 71 ID 0x741b2754 dest 1:
Wed Sep 23 07:51:36 2020
Thread 1 advanced to log sequence 73 (LGWR switch)
  Current log# 1 seq# 73 mem# 0: /app01/base/oradata/orcl12x/redo01.log
Wed Sep 23 07:51:40 2020
Archived Log entry 61 added for thread 1 sequence 72 ID 0x741b2754 dest 1:
Wed Sep 23 07:51:40 2020
Resize operation completed for file# 1, old size 942080K, new size 952320K
Wed Sep 23 07:51:49 2020
Thread 1 advanced to log sequence 74 (LGWR switch)
  Current log# 2 seq# 74 mem# 0: /app01/base/oradata/orcl12x/redo02.log
Wed Sep 23 07:51:53 2020
Archived Log entry 62 added for thread 1 sequence 73 ID 0x741b2754 dest 1:

Database has three redolog groups which switch more frequently when there is a transaction.

08:01:07 SQL> select * from v$log;

    GROUP#    THREAD#  SEQUENCE#      BYTES  BLOCKSIZE    MEMBERS ARC STATUS          FIRST_CHANGE# FIRST_TIM
---------- ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ---------
NEXT_CHANGE# NEXT_TIME     CON_ID
------------ --------- ----------
         1          1         73   52428800        512          1 YES INACTIVE      2153831 23-SEP-20
     2154410 23-SEP-20          0

         2          1         74   52428800        512          1 NO  CURRENT       2154410 23-SEP-20
  2.8147E+14                    0

         3          1         72   52428800        512          1 YES INACTIVE      2153252 23-SEP-20
     2153831 23-SEP-20          0


Elapsed: 00:00:00.04

The size of the redologs are too small to accomodate and handle the incoming flood of log and log switch which causes delay in processing of workload and performance issues in application.

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
-------------------- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
2020-SEP-23            0   0   0   0   0   0   17   33   0   0   0   0   0   0   0   0   0   0   0   0   0   0  0   0

We can observe high number of log switch due to small size of the redolog groups which is not good at all.In the below graph,there is a peak point from hour 6 to 8 due to the log switch frequency.

Graph makes it clear and simple to visualize the pattern

A picture describes 1000 words

As per my thought,Redolog switch per hour should be at most 10 which is acceptable.

If less than 10 log switches say 5 per hour,then the redologs are perfectly sized for the application workload.

When we create a database ,the default logfile size is 50MB.This is not sufficient for a production database with peak workloads.

SQL> select a.group#,a.bytes/1024/1024 from v$log a
  2  inner join v$logfile b on a.group# = b.group#;

    GROUP# A.BYTES/1024/1024
---------- -----------------
         3                50
         2                50
         1                50

So we can increase the size of the redologs to accomodate the incoming logs and reduce the log switch interval for higher database performance.

SQL> select session_id,sample_time,session_state,event,wait_time,time_waited from v$active_session_history where event like '%log%' order by time_waited desc;

SESSION_ID SAMPLE_TIME               SESSION EVENT                           WAIT_TIME TIME_WAITED
---------- ------------------------- ------- ------------------------------ ---------- -----------
        13 23-SEP-20 07.51.53.002 AM WAITING log file parallel write                0      3764935
        13 23-SEP-20 07.51.15.007 AM WAITING log file parallel write                0      3390574
        13 23-SEP-20 07.51.39.007 AM WAITING log file parallel write                0      3366487
         1 23-SEP-20 07.51.53.002 AM WAITING log file sync                          0      2953591
        13 23-SEP-20 07.51.26.007 AM WAITING log file parallel write                0      1747222
        13 23-SEP-20 07.47.34.949 AM WAITING log file parallel write                0      1452470
        13 23-SEP-20 07.51.00.997 AM WAITING log file parallel write                0      1179508
        48 23-SEP-20 10.33.53.221 AM WAITING log file sync                          0      1166026
        13 23-SEP-20 10.33.53.221 AM WAITING log file parallel write                0      1164236

Multiple log file sync and parallel wrtie wait events occured during the DML transaction which cause delay in acknowledging the user session about the redologs being written on the disk.

SQL> select * from v$log;

    GROUP#    THREAD#  SEQUENCE#      BYTES  BLOCKSIZE    MEMBERS ARC STATUS          FIRST_CHANGE# FIRST_TIM
---------- ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ---------
NEXT_CHANGE# NEXT_TIME     CON_ID
------------ --------- ----------
         1          1         73   52428800        512          1 YES INACTIVE      2153831 23-SEP-20
     2154410 23-SEP-20          0

         2          1         74   52428800        512          1 NO  CURRENT       2154410 23-SEP-20
  2.8147E+14                    0

         3          1         72   52428800        512          1 YES INACTIVE      2153252 23-SEP-20
     2153831 23-SEP-20          0


SQL> alter database drop logfile group 1;

Database altered.

SQL> alter database add logfile group 1 '/app01/base/oradata/orcl12x/redo01.log';

Database altered.

SQL> alter database drop logfile group 2;
alter database drop logfile group 2
*
ERROR at line 1:
ORA-01623: log 2 is current log for instance orcl12x (thread 1) - cannot drop
ORA-00312: online log 2 thread 1: '/app01/base/oradata/orcl12x/redo02.log'


SQL> alter database drop logfile group 3;

Database altered.

SQL> alter database add logfile group 3 '/app01/base/oradata/orcl12x/redo03.log' size 500M;

Database altered.

Switch the logfile to make the active redolog group to inactive.The redolog group should be inactive in order to drop the file.

SQL> alter system switch logfile;

System altered.

SQL> /
/

System altered.

SQL> alter database drop logfile group 2;

Database altered.

SQL> alter database add logfile group 2 '/app01/base/oradata/orcl12x/redo02'  size 500M;

Database altered.

All the redolog groups are resized and more logfile groups are added

SQL> alter database add logfile group 4 '/app01/base/oradata/orcl12x/redo04'  size 500M;

Database altered.

SQL> alter database add logfile group 5 '/app01/base/oradata/orcl12x/redo05'  size 500M;

Database altered.

SQL> alter database add logfile group 6 '/app01/base/oradata/orcl12x/redo06'  size 500M;

Database altered.

we insert some bulk row again into the table t1

SQL> BEGIN
  2  FOR I IN 30000 .. 400000 LOOP
  3  INSERT INTO T1 values('xyz',i,'abc',i);
  4  END LOOP;
  5  COMMIT;
  6  END;
  7  /

PL/SQL procedure successfully completed.

we can see the reduction in log switch frequency where there is only one log file switch at 12 hours

Wed Sep 23 12:56:20 2020
Thread 1 cannot allocate new log, sequence 80
Private strand flush not complete
  Current log# 3 seq# 79 mem# 0: /app01/base/oradata/orcl12x/redo03
Wed Sep 23 12:56:23 2020
Thread 1 advanced to log sequence 80 (LGWR switch)
  Current log# 2 seq# 80 mem# 0: /app01/base/oradata/orcl12x/redo02
Wed Sep 23 12:56:23 2020
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
-------------------- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
2020-SEP-23            0   0   0   0   0   0   17   33   0   0   0   0 1<-   0   0   0   0   0   0   0   0   0  0   0


The above scenario is just for testing purpose and not a production database.

Published by kishan

You will know about me.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

%d bloggers like this: