Does ARCHIVE deletion records entry in alert log?

This morning I got a question that - Does archivelog deletion (manually or RMAN) records entries to the database alert log?

Well, this was asked in an interview to him.

Answer is "NO" - until you use OMF/FRA and configured the ARCHIVE DELETION POLICY in the RMAN.


Let me explain step by step, how archivelogs get deleted automatically when we have the "archivelog deletion policy" configured in the RMAN and archive deletion details gets recorded in the database alert log.


1 - First of all, Flash/Fast Recovery area must be configured - in my case, it is already configured.

SQL> archive log list
Database log mode              Archive Mode
Automatic archival             Enabled
Archive destination            USE_DB_RECOVERY_FILE_DEST
Oldest online log sequence     0
Next log sequence to archive   0
Current log sequence           0
SQL>

let's see the current usage of recovery area - it is 82.47% used as of now.

SQL> select * from v$recovery_area_usage;

FILE_TYPE               PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES     CON_ID
----------------------- ------------------ ------------------------- --------------- ----------
CONTROL FILE                           .14                         0               1          0
REDO LOG                                 0                         0               0          0
ARCHIVED LOG                         82.47                        81             376          0
BACKUP PIECE                             0                         0               0          0
IMAGE COPY                               0                         0               0          0
FLASHBACK LOG                            0                         0               0          0
FOREIGN ARCHIVED LOG                     0                         0               0          0
AUXILIARY DATAFILE COPY                  0                         0               0          0

2 - I have the the ARCHIVELOG DELETION POLICY set to delete archivelogs from the flash recovery area once that is applied on the standby database.

Remember, RMAN deletes the archives automatically once there is space pressure on the FRA, for example: when it crosses the 85% used percentage of recovery area(but not necessarily that deletion triggers immediately when it crosses 85% usage)

RMAN> show archivelog deletion policy;

using target database control file instead of recovery catalog
RMAN configuration parameters for database with db_unique_name MAXMP76AD are:
CONFIGURE ARCHIVELOG DELETION POLICY TO APPLIED ON STANDBY;

RMAN>

Since flash recovery area usage is currently at 82.47%, i.e. below the default warning threshold, so let's reduce the db_recovery_file_dest_size parameter value to lower so recovery area usage goes high and when it crosses 85% then RMAN assumes there is space pressure in the FRA and it started deleting the archive logs which are applied on the standby and - here in this case, it records the entry in the alert log for all the archives being deleted here.

SQL> show parameter recovery

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ------------------------------
db_recovery_file_dest                string                           +RECOC1
db_recovery_file_dest_size           big integer                      700G
recovery_parallelism                 integer                          0
SQL>

I am reducing the db_recovery_file_dest_size parameter to 600GB from 700GB to create pressure on the FRA.

SQL> alter system set db_recovery_file_dest_size=600g sid='*';

System altered.

SQL> show parameter recovery

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ------------------------------
db_recovery_file_dest                string                           +RECOC1
db_recovery_file_dest_size           big integer                      600G
recovery_parallelism                 integer                          0
SQL>




SQL> select * from v$recovery_area_usage;

FILE_TYPE               PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES     CON_ID
----------------------- ------------------ ------------------------- --------------- ----------
CONTROL FILE                           .16                         0               1          0
REDO LOG                                 0                         0               0          0
ARCHIVED LOG                         92.95                     92.37             363          0
BACKUP PIECE                             0                         0               0          0
IMAGE COPY                               0                         0               0          0
FLASHBACK LOG                            0                         0               0          0
FOREIGN ARCHIVED LOG                     0                         0               0          0
AUXILIARY DATAFILE COPY                  0                         0               0          0

8 rows selected.

Here you can see in the alert log that OMG manged archive log deletion logs recorded in the database alert log.

Wed Aug 21 03:15:22 2019 
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736154.35917.1016826721
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736155.94249.1016826805
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744387.232116.1016826855
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744388.1236.1016826899
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736156.157025.1016826901
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736157.82181.1016827067
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736158.30084.1016827149
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744389.10761.1016827153
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736159.68978.1016827319
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736160.49575.1016827399
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744390.71236.1016827423
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744391.93291.1016827513
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744392.164222.1016827587
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736161.150312.1016827589
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744393.186625.1016827667
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744394.229726.1016827751
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744395.120898.1016827825
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736162.184211.1016827825
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744396.112965.1016827903
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736163.46774.1016828035
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744397.82871.1016828125
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744398.69882.1016828209
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_1_seq_744399.61173.1016828287
Deleted Oracle managed file +RECOC/standdb/ARCHIVELOG/2019_08_20/thread_2_seq_736164.126761.1016828287



Note: It is not necessary that RMAN would immediately start deleting the archive logs when it crosses 85% or so.


Twitter : @rajsoft8899
Linkedin : https://www.linkedin.com/in/raj-kumar-kushwaha-5a289219/

ORA-27154: post/wait create failed

Today, we were doing Exadata X7-2 QFSDP APR 2019 patching, but during post patch steps, some of the cluster database instances failed to start with following error  - Over-all 62 databases running on this Exadata Machine.

Note : Recently we added 2 more databases to this Exadata box.

SQL> startup
ORA-27154: post/wait create failed
ORA-27300: OS system dependent operation:semget failed with status: 28
ORA-27301: OS failure message: No space left on device
ORA-27302: failure occurred at: sskgpcreates
SQL> 

From one of the database alert log file:

Starting ORACLE instance (normal)
************************ Large Pages Information *******************
Per process system memlock (soft) limit = UNLIMITED

Total Shared Global Region in Large Pages = 0 KB (0%)

Large Pages used by this instance: 0 (0 KB)
Large Pages unused system wide = 0 (0 KB)
Large Pages configured system wide = 13833 (27 GB)
Large Page size = 2048 KB

RECOMMENDATION:
  Total System Global Area size is 2050 MB. For optimal performance,
  prior to the next instance restart:
  1. Increase the number of unused large pages by
 at least 1025 (page size 2048 KB, total size 2050 MB) system wide to
  get 100% of the System Global Area allocated with large pages
********************************************************************
Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_184111.trc:
ORA-27154: post/wait create failed
ORA-27300: OS system dependent operation:semget failed with status: 28
ORA-27301: OS failure message: No space left on device
ORA-27302: failure occurred at: sskgpcreates

From the trace file:

*** 2019-08-17 10:10:25.566
Switching to regular size pages for segment size 100663296
Switching to regular size pages for segment size 2046820352
Switching to regular size pages for segment size 2097152

*** 2019-08-17 10:10:25.595
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=0, mask=0x0)
----- Error Stack Dump -----
ORA-27154: post/wait create failed
ORA-27300: OS system dependent operation:semget failed with status: 28
ORA-27301: OS failure message: No space left on device
ORA-27302: failure occurred at: sskgpcreates

Semaphore current configuration in the system.

[root@exa01dbadm01 ~]# ipcs -ls

------ Semaphore Limits --------
max number of arrays = 256
max semaphores per array = 1024
max semaphores system wide = 60000
max ops per semop call = 1024
semaphore max value = 32767







Means 60000 semaphores are available in the system and one semaphore identifier can accommodate a maximum of 1024 semaphores with the configuration above.

But ipcs command shows each semaphore identifier accommodates maximum of 514 (some 752) semaphores by Oracle. 

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0x27219008 5242886    oracle     640        704
0x1d63fabc 5373959    oracle     640        514
0x1d63fabd 5406728    oracle     640        514
0x26f035f8 5603337    oracle     640        514
0x1d63fabe 5472266    oracle     640        514
0x26f035f9 5701643    oracle     640        514
0xeb773830 5898252    oracle     640        514
0x26f035fa 5832717    oracle     640        514
0x14422b02 11862119   oracle     640        514
0xa83d39fc 11993192   oracle     640        514
0xa83d39fd 12025961   oracle     640        514
0xa83d39fe 12058730   oracle     640        514
0xea1a4768 12189803   oracle     640        514
0xea1a4769 12222572   oracle     640        514
0xea1a476a 12255341   oracle     640        514
0xdcc4a7a4 12386414   oracle     640        514
0xdcc4a7a5 12419183   oracle     640        514
0xdcc4a7a6 12451952   oracle     640        514
0x75550980 12583025   oracle     600        514
0x75550981 12615794   oracle     600        514
0x75550982 12648563   oracle     600        514

So, maximum semaphores available on this system would be 514x256 = 131584

[root@exa01dbadm01 ~]# /sbin/sysctl -a | grep sem
kernel.sem = 1024       60000   1024    256

Per above, we see that we have less, max semaphores configured in the system i.e. 60000.
==================

SEMMNI should be increased to accomodate more semaphores.

[root@exa01dbadm01 ~]# /sbin/sysctl -a | grep sem
kernel.sem = 1024       60000   1024    256

I increased the max number of semaphores to be available on the system to 70000 from 60000

From :

[root@exa01dbadm01 ~]# /sbin/sysctl -a | grep sem
kernel.sem = 1024       60000   1024    256

To this:

[root@exa01dbadm01 ~]# /sbin/sysctl -a | grep sem
kernel.sem = 1024       70000   1024    256

And finally run the below to make new kernel values effective without server reboot.

/sbin/sysctl -p

Finally, tried to start the remaining DB instances and all came up normally.

[oracle@exa01dbadm01 ~]$ sqlplus "/as sysdba"

SQL*Plus: Release 12.1.0.2.0 Production on Sat Aug 17 10:32:13 2019

Copyright (c) 1982, 2014, Oracle.  All rights reserved.

Connected to an idle instance.

SQL> startup
ORACLE instance started.

Total System Global Area 2147483648 bytes
Fixed Size                  2926472 bytes
Variable Size            1318045816 bytes
Database Buffers          822083584 bytes
Redo Buffers                4427776 bytes
Database mounted.
Database opened.
SQL>

Hope it helps, subscribe to this blog to stay updated on latest Oracle Technologies and new articles.

Twitter : @rajsoft8899
Linkedin : https://www.linkedin.com/in/raj-kumar-kushwaha-5a289219/

Expanded controlfile section 27 from 1000 to 2000 records

Following entry in the alert log file is just an informational message means more information is getting added or updated in database controlfile sections. We already know that database control file records lots of information in it about its database, below you would see what all kinds of information, database control file stores in it.

All information age/length depends on the below parameter - i.e. for how long you want to retain all information inside the control file that it stores. In my case, we are storing the information for 38 days and my control file size is almost 1GB. We are generating almost 6000 archives per day.

SQL> show parameter control_file_record_keep_time

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ------------------------------
control_file_record_keep_time        integer                          38
SQL>

In my case, my standby database had to sync over 9000 pending archives shipping from the primary database to the DR. I have archivelog deletion policy set in the RMAN configuration on the standby so that applied archives get deleted(when there is space pressure on the FRA ) once applied to maintain the proper space inside the FRA.

Below is the alert log entry added in the standby where it says that controlfile section 27 has been expanded from 1000 to 2000 so it can record new/update information/values - archive apply speed very high - 32 to 33 archives per minute.

Fri Aug 16 05:58:37 2019
Expanded controlfile section 27 from 1000 to 2000 records
Requested to grow by 1000 records; added 2 blocks of records

SQL> select * from v$version;

BANNER                                                                               CON_ID
-------------------------------------------------------------------------------- ----------
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production              0
PL/SQL Release 12.1.0.2.0 - Production                                                    0
CORE    12.1.0.2.0      Production                                                                0
TNS for Linux: Version 12.1.0.2.0 - Production                                            0
NLSRTL Version 12.1.0.2.0 - Production                                                    0

SQL>

Below you can see that control file section 27 (REMOVABLE RECOVERY FILES) has been expanded to 2000 from 1000 since you can see its current value is 1318 i.e greater than 1000 hence the relevant section expanded to store more information in it.

"REMOVABLE RECOVERY FILES" control file section was expanded because archives at standby database getting shipped and applied at very rapid speed (32 to 33 archives apply per minute) and applied archives are being marked as "REMOVABLE RECOVERY FILES" and eligible to be removed once there is space pressure on FRA hence control file requires to store this information in it and its relevant section needs some more blocks to store the growing information hence the section expanded.


Below are various control file sections that stores separate information into it.

SQL> select rownum,t.* from v$controlfile_record_section t;

ROWNUM TYPE                         RECORD_SIZE RECORDS_TOTAL RECORDS_USED FIRST_INDEX LAST_INDEX LAST_RECID     CON_ID
---------- ---------------------------- ----------- ------------- ------------ ----------- ---------- ---------- ---------- 
         1 DATABASE                             316             1            1           0          0          0          0
         2 CKPT PROGRESS                       8180            35            0           0          0          0          0
         3 REDO THREAD                          256            32            2           0          0        120          0
         4 REDO LOG                              72           192           20           0          0        162          0
         5 DATAFILE                             520          1024           76           0          0      10409          0
         6 FILENAME                             524          4674          121           0          0          0          0
         7 TABLESPACE                            68          1024           23           0          0         36          0
         8 TEMPORARY FILENAME                    56          1024            3           0          0      32716          0
         9 RMAN CONFIGURATION                  1108            50           11           0          0         55          0
        10 LOG HISTORY                           56        382842       382842      174193     174192    1473530          0
        11 OFFLINE RANGE                        200          1063            5           1          5          5          0
        12 ARCHIVED LOG                         584        696320         9496           1       9496       9496          0
        13 BACKUP SET                            96         32704        32704       31215      31214     129326          0
        14 BACKUP PIECE                         780         32192        32192         559        558     129326          0
        15 BACKUP DATAFILE                      200          6866         6866        2580       2579      48776          0
        16 BACKUP REDOLOG                        76        440320       417543      384410     361632    1462432          0
        17 DATAFILE COPY                        736          1000          152           1        152        152          0
        18 BACKUP CORRUPTION                     44          1115            0           0          0          0          0
        19 COPY CORRUPTION                       40          1227            0           0          0          0          0
        20 DELETED OBJECT                        20        803572       756216      545421     498064    1842356          0
        21 PROXY COPY                           928          1004            0           0          0          0          0
        22 BACKUP SPFILE                        124          1890         1890         555        554      17509          0
        23 DATABASE INCARNATION                  56           292            2           1          2          2          0
        24 FLASHBACK LOG                         84          2048            0           0          0          0          0
        25 RECOVERY DESTINATION                 180             1            1           0          0          0          0
        26 INSTANCE SPACE RESERVATION            28          1055            2           0          0          0          0
        27 REMOVABLE RECOVERY FILES              32          2000         1318           0          0          0          0
        28 RMAN STATUS                          116          7568         7568        1861       1860      98780          0
        29 THREAD INSTANCE NAME MAPPING          80            32           32           0          0          0          0
        30 MTTR                                 100            32            2           0          0          0          0
        31 DATAFILE HISTORY                     568            57            0           0          0          0          0
        32 STANDBY DATABASE MATRIX              400            31           31           0          0          0          0
        33 GUARANTEED RESTORE POINT             212          2048            0           0          0          0          0
        34 RESTORE POINT                        212          2083            0           0          0          0          0
        35 DATABASE BLOCK CORRUPTION             80          8384            0           0          0          0          0
        36 ACM OPERATION                        104            64            9           0          0          0          0
        37 FOREIGN ARCHIVED LOG                 604          1002            0           0          0          0          0
        38 PDB RECORD                           684            10            0           0          0          0          0
        39 AUXILIARY DATAFILE COPY              584           128            0           0          0          0          0
        40 MULTI INSTANCE REDO APPLY            556             1            0           0          0          0          0
        41 PDBINC RECORD                        144           113            0           0          0          0          0

41 rows selected. 

SQL>



Since archivelog shipping and apply was massive hence you would see below that control file section 27 expanded again from 2000 to 4000

Fri Aug 16 07:28:38 2019
Expanded controlfile section 27 from 2000 to 4000 records
Requested to grow by 2000 records; added 4 blocks of records

SQL> select rownum,t.* from v$controlfile_record_section t;

ROWNUM TYPE                         RECORD_SIZE RECORDS_TOTAL RECORDS_USED FIRST_INDEX LAST_INDEX LAST_RECID     CON_ID

---------- ---------------------------- ----------- ------------- ------------ ----------- ---------- ---------- ----------  

         1 DATABASE                             316             1            1           0          0          0          0

         2 CKPT PROGRESS                       8180            35            0           0          0          0          0

         3 REDO THREAD                          256            32            2           0          0        120          0

         4 REDO LOG                              72           192           20           0          0        162          0

         5 DATAFILE                             520          1024           76           0          0      10409          0

         6 FILENAME                             524          4674          121           0          0          0          0

         7 TABLESPACE                            68          1024           23           0          0         36          0

         8 TEMPORARY FILENAME                    56          1024            3           0          0      32716          0

         9 RMAN CONFIGURATION                  1108            50           11           0          0         55          0

        10 LOG HISTORY                           56        382842       382842      174718     174717    1474055          0

        11 OFFLINE RANGE                        200          1063            5           1          5          5          0

        12 ARCHIVED LOG                         584        696320         9580           1       9580       9580          0

        13 BACKUP SET                            96         32704        32704       31215      31214     129326          0

        14 BACKUP PIECE                         780         32192        32192         559        558     129326          0

        15 BACKUP DATAFILE                      200          6866         6866        2580       2579      48776          0

        16 BACKUP REDOLOG                        76        440320       417543      384410     361632    1462432          0

        17 DATAFILE COPY                        736          1000          152           1        152        152          0

        18 BACKUP CORRUPTION                     44          1115            0           0          0          0          0

        19 COPY CORRUPTION                       40          1227            0           0          0          0          0

        20 DELETED OBJECT                        20        803572       756216      545421     498064    1842356          0

        21 PROXY COPY                           928          1004            0           0          0          0          0

        22 BACKUP SPFILE                        124          1890         1890         555        554      17509          0

        23 DATABASE INCARNATION                  56           292            2           1          2          2          0

        24 FLASHBACK LOG                         84          2048            0           0          0          0          0

        25 RECOVERY DESTINATION                 180             1            1           0          0          0          0

        26 INSTANCE SPACE RESERVATION            28          1055            2           0          0          0          0

        27 REMOVABLE RECOVERY FILES              32          4000         2013           0          0          0          0

        28 RMAN STATUS                          116          7568         7568        1861       1860      98780          0

        29 THREAD INSTANCE NAME MAPPING          80            32           32           0          0          0          0

        30 MTTR                                 100            32            2           0          0          0          0

        31 DATAFILE HISTORY                     568            57            0           0          0          0          0

        32 STANDBY DATABASE MATRIX              400            31           31           0          0          0          0

        33 GUARANTEED RESTORE POINT             212          2048            0           0          0          0          0

        34 RESTORE POINT                        212          2083            0           0          0          0          0

        35 DATABASE BLOCK CORRUPTION             80          8384            0           0          0          0          0

        36 ACM OPERATION                        104            64            9           0          0          0          0

        37 FOREIGN ARCHIVED LOG                 604          1002            0           0          0          0          0

        38 PDB RECORD                           684            10            0           0          0          0          0

        39 AUXILIARY DATAFILE COPY              584           128            0           0          0          0          0

        40 MULTI INSTANCE REDO APPLY            556             1            0           0          0          0          0

        41 PDBINC RECORD                        144           113            0           0          0          0          0

41 rows selected. 

SQL>


Hope it helps, subscribe to this blog to stay updated on latest Oracle Technologies and new articles.

Twitter : @rajsoft8899
Linkedin : https://www.linkedin.com/in/raj-kumar-kushwaha-5a289219/