Data Guard Failover surprise

Ran into a interesting scenario after reinstating the previous primary DB after an emergency failover.

A Data Guard failover is done during emergencies (an actual DR situation) and the old standby gets activated as a Primary database with RESETLOGS after an incomplete recovery. 

Here's the alert.log from the new Primary database:

Tue Oct 02 16:07:34 2018
 Data Guard Broker: A failover will now be attempted
Tue Oct 02 16:07:34 2018
ALTER DATABASE FAILOVER TO TMSBY
...
Tue Oct 02 16:07:40 2018
ALTER DATABASE SWITCHOVER TO PRIMARY (TMSBY1)
RESETLOGS after incomplete recovery UNTIL CHANGE 14297961467966 time 10/02/2018 16:02:10
...
Tue Oct 02 16:07:40 2018
Setting recovery target incarnation to 3
Tue Oct 02 16:07:41 2018
Switchover: Complete - Database mounted as primary

A few hours later the old Primary DB (TMPRD) was fixed, started in MOUNT mode and reinstated via the Broker:

DGMGRL> show configuration
Configuration - tmdg
  Protection Mode: MaxPerformance
  Members:
  TMSBY  - Primary database
    TMPRD - Physical standby database (disabled)
      ORA-16661: the standby database needs to be reinstated
Fast-Start Failover: DISABLED
Configuration Status:
SUCCESS   (status updated 26 seconds ago)
DGMGRL> reinstate database TMPRD
Reinstating database "TMPRD", please wait...
Reinstatement of database "TMPRD" succeeded

Reinstatement completed successfully, but the new standby (TMPRD) was not applying logs, the alert.log confirmed that it was waiting for an Archivelog that was only created on the previous standby site. 

Media Recovery Waiting for thread 2 sequence 358 branch(resetlogs_id) 987409798

But that archivelog has already been backed up and deleted via RMAN. A straight forward restore on TMSBY should work but then it failed with: 

RMAN> restore archivelog sequence 358 thread 2;
Starting restore at 03-OCT-18 08:40
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=232 instance=TMSBY1 device type=DISK
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of restore command at 10/03/2018 08:40:15
RMAN-20242: specification does not match any archived log in the repository

Remember the Failover forced a RESETLOGS so the incarnation of the DB changed, so the trick is:

RMAN> list incarnation;
List of Database Incarnations
DB Key  Inc Key DB Name  DB ID            STATUS  Reset SCN  Reset Time
------- ------- -------- ---------------- --- ---------- ----------
1       1       TMPRD   645377540        PARENT  1594143    31-AUG-18 10:37
2       2       TMPRD   645377540        PARENT  5368114    21-SEP-18 08:29
3       3       TMPRD   645377540        CURRENT 14297961467967 02-OCT-18 16:07

RMAN> restore archivelog sequence 358 thread 2 Incarnation 2;

Starting restore at 03-OCT-18 08:44
using channel ORA_DISK_1
channel ORA_DISK_1: starting archived log restore to default destination
channel ORA_DISK_1: restoring archived log
archived log thread=2 sequence=358
channel ORA_DISK_1: reading from backup piece +DG_FRA/TMSBY/BACKUPSET/2018_10_02/annnf0_TMSBY1_arch_0.337.988488123
channel ORA_DISK_1: piece handle=+DG_FRA/TMSBY/BACKUPSET/2018_10_02/annnf0_TMSBY1_arch_0.337.988488123 tag=TMSBY1_ARCH
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:00:15
Finished restore at 03-OCT-18 08:45

And within a few minutes the restored Archivelog gets picked up by the FAL process, transfered and applied on the new standby (TMPRD). Alert.log contents:

RFS[3]: Opened log for thread 2 sequence 358 dbid 645377540 branch 987409798
...
Archived Log entry 1627 added for thread 2 sequence 358 rlc 987409798 ID 0x0 dest 2:
...
Media Recovery Log +DG_ARCHIVE/TMPRD/ARCHIVELOG/2018_10_03/thread_2_seq_358.49304.988533935

All in all I was impressed with the smooth failover and reinstatement via the broker, but even then, not everything can get automated and there's always some hicup where the DBA should roll up their sleeves and dig in in order to get things back to normal again.

Connection Pooling for Scalability and Performance

Got a call from our web support team, seems that a critical database transaction with a 2 second SLA is sometimes taking 6 seconds to complete. They have been investigating the problem for a day and have concluded that it is a Database problem. They thought there must be some type of short spike in the database that affects their transactions.

First step was to look at the health of the database, the load profile and wait events of ACTIVE sessions, nothing jumped out as a problem. I even did a session trace of one of the web service sessions in question and did not find any SQL query taking longer than a few milliseconds.

An AWR report showed an average of 50 logons per second over a 20 minute period. That set off the alarm bells as database connections are expensive (just think of the overhead of establishing a network connection and then also initializing a database connection which requires user authentication, authentication protocols, establishing transactional contexts etc.).

The web development team assured me that they are using connection pooling and the number of sessions was far below the processes parameter, but it was when I queried 2 sources: the DBA_AUDIT_SESSION view and the listener.ora log file that my suspicions where confirmed. Hundreds of LOGONS and LOGOFFS per minute for one specific database username connecting from 4 userhosts/clients.

select os_username, username, userhost, action_name, count(*)

from DBA_AUDIT_SESSION

where timestamp > sysdate - 1/24

having count(*) > 100

group by  os_username, username, userhost, action_name

order by count(*);

As I said nothing stood out in my initial investigation and count from V$SESSION, but now that I have the offending username and userhost I could look more closely at V$SESSION. Although the general count of sessions for this spesific username stayed constant at about 50, the LOGON_TIME was never more than 2 seconds older than the current time! The database sessions had a very short life: logon, executes one or a few queries, logoff. Everytime I queries V$SESSION I was looking at 50 different sessions than a few seconds before.

select to_char(sysdate, 'yyyy-mm-dd hh24:mi:ss') right_now,

to_char(logon_time, 'yyyy-mm-dd hh24:mi:ss') logon_time

from V$SESSION

where username = ‘XX’

and userhost in (‘HOST1’,’HOST2’,’HOST3’,’HOST4’);

It turned out that we have multiple apps and web teams using this database and a totally separate team added a transaction without using connection pooling! This affected all new database connections. The original team who brought the issue to my attention where using connection pooling, but every now and again even they had to create new connections, and it is while establishing these new connections on a already overloaded database connection function that slowed their transactions down. After alerting the teams of my findings, they made the desired changes and within a few hours the original team gave the thumbs up and wanted to know what I did to make the database faster.

24 hours later I used this query from DBA_HIST_SYSMETRIC_SUMMARY to create a graph to show how the Logons per Second metric came down, the timing matched a graph from the app team that showed when all web transactions stabilized to less than 1 second again.

select to_char(s.end_interval_time,'mm-dd_hh24:mi') snap_time, sy.average

from DBA_HIST_SNAPSHOT s, DBA_HIST_SYSMETRIC_SUMMARY sy

where s.dbid = sy.dbid

and s.instance_number = sy.instance_number

and s.snap_id = sy.snap_id

and sy.metric_name = 'Logons Per Sec'

and s.end_interval_time > trunc(sysdate-2)

order by snap_time

/

Cloning a RAC DB on the same cluster

We are using OMF in ASM so will include the following 3 lines in the RMAN DUPLICATE TARGET command:

SET DB_FILE_NAME_CONVERT '+DG_DATA','+DG_DATA'

SET LOG_FILE_NAME_CONVERT '+DG_DATA','+DG_DATA'

SET CONTROL_FILES='+DG_DATA','+DG_DATA'

Do NOT use NOFILENAMECHECK when closing to the same server, any error in your script and RMAN might overwrite the target DBs db files!

Also need to SET CLUSTER_DATABASE='FALSE' in the RMAN DUPLICATE TARGET command because I will clone a RAC to single instance and then convert the single instance to a RAC.

Prep includes creating a pwd file and a init.ora file with 3 lines

db_name=TMTEST

db_unique_name=TMTEST

compatible=12.1.0.2.0

I added the 3^rd line after getting “RMAN-06136: ORACLE error from auxiliary database: ORA-00201: control file version 12.1.0.2.0 incompatible with ORACLE version 12.0.0.0.0” on my first clone attempt

Set ORACLE_SID to the new DB (TMTEST) and startup nomount. When launching RMAN connect to the TARGET via a TNS entry

rman target sys/XX@DLIOWCC auxiliary sys/XX

RMAN> DUPLICATE TARGET DATABASE TO TMTEST FROM ACTIVE DATABASE

SPFILE

SET CONTROL_FILES='+DG_DATA','+DG_DATA';

SET DB_FILE_NAME_CONVERT '+DG_DATA','+DG_DATA'

SET LOG_FILE_NAME_CONVERT '+DG_DATA','+DG_DATA'

SET CLUSTER_DATABASE='FALSE';

10 minutes later I had a Cloned DB with ORACLE_SID=TMTEST

Some post cloning tasks in order to make it a RAC:

SQL> show parameter spfile

NAME    TYPE    VALUE

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

spfile  string  /u01/oracle/product/12.1.0/db_1/dbs/spfileTMTEST.ora

SQL> alter system set cluster_database=TRUE scope=spfile sid='*';

SQL> create pfile ‘initTMTESTcloned.ora’ from spfile;

vi initTMTESTcloned.ora

Found a few entries I had to change from:

DLIOWCC2.instance_number=2

DLIOWCC1.instance_number=1

DLIOWCC2.thread=2

DLIOWCC1.thread=1

DLIOWCC1.undo_tablespace='UNDOTBS1'

DLIOWCC2.undo_tablespace='UNDOTBS2'

To

TMTEST2.instance_number=2

TMTEST1.instance_number=1

TMTEST2.thread=2

TMTEST1.thread=1

TMTEST1.undo_tablespace='UNDOTBS1'

TMTEST2.undo_tablespace='UNDOTBS2'

SQL> create spfile='+DG_DATA/TMTEST/spfileTMTEST.ora' from pfile='initTMTESTcloned.ora';

vi initTMTEST1.ora

add line spfile='+DG_DATA/TMTEST/spfileTMTEST.ora'

copy the init.ora and orapw file to node 2

Register the database and modify the configuration

srvctl add database -db TMTEST -oraclehome /u01/app/oracle/product/12.1.0/dbhome_1 -spfile +DG_DATA/TMTEST/spfileTMTEST.ora

srvctl add instance -db TMTEST -i TMTEST1 -node node1za

srvctl add instance -db TMTEST -i TMTEST2 -node node2za

srvctl config database -db TMTEST

shutdown the instance (remember ORACLE_SID=TMTEST)

and start the DB from srvctl

srvctl start database -db TMTEST

Remember to change ORACLE_SID from TMTEST to TMTEST1 if you want to connect via sqlplus on the DB node node1za

ORA-16047 - DGID mismatch between destination setting and target database

A few days after a DG planned switchover I got a call from the DBAs. OEM and v$dataguard_stats shows no lag, but archives have not shipped from the Primary DB to the Physical Standby DB since the switchover.

After confirming their suspicions by querying V$archived_log and v$dataguard_stats I went to the 3 primary sources for DG troubleshooting.

1.) DGMGRL

the command "show configuration" indicated that the Standby database was disabled.

2.) Primary and Standby Alert.log files

The Primary DB had this peculiar error in its Alert.log file:

Fri Sep 14 13:55:31 2018

ORA-16047: DGID mismatch between destination setting and target database

using the oerr utility I found the full descrition of the error:

Error:  ORA-16047 DGID mismatch between destination setting and target database 
---------------------------------------------------------------------------
Cause:  The DB_UNIQUE_NAME specified for the destination did not match the 
 DB_UNIQUE_NAME at the target database. 
Action: Make sure the DB_UNIQUE_NAME specified in the LOG_ARCHIVE_DEST_n 
 parameter matches the DB_UNIQUE_NAME parameter defined at the 
 destination. 

But the DB_UNIQUE_NAME was correct in the Primary's LOG_ARCHIVE_DEST_2 parameter.

Next I looked at the Standby DBs Alert.log file, especially around the timestamp of the ORA-16047 error in the Primary DBs Alert.log. It seems that the Broker was not happy and decided to deconfigure the LOG_ARCHIVE_CONFIG parameter!

Fri Sep 14 13:54:23 2018

ALTER SYSTEM SET log_archive_config='nodg_config' SCOPE=BOTH;

...

Completed: Data Guard Broker shutdown

Fri Sep 14 13:54:59 2018

ALTER SYSTEM SET dg_broker_start=FALSE SCOPE=BOTH;

ALTER SYSTEM SET dg_broker_start=TRUE SCOPE=BOTH;

3.) Primary and Standby DG Alert log files

Lets look at the DG Alert.log files around the same timestamp.

The Standby DG Alert.log had hundreds of repeating ORA-16501 error messages until the timestamp in question when we got:

...

Failed to send message to site pc3dfmw2tc. Error code is ORA-16501.

...

09/14/2018 13:54:06

REMOVE CONFIGURATION [PRESEVERE DESTINATIONS]

So I was correct, the Broker was not happy (as can be seen by the repeated ORA-16501 errors) and eventually deconfigured the LOG_ARCHIVE_CONFIG parameter!

Error:  ORA-16501 the Data Guard broker operation failed

---------------------------------------------------------------------------
Cause:  the Data Guard broker operation failed
Action: See accompanying messages for details.

Not a lot of info for the ORA-16501 error, it seems to be a generic error. Investigating further back in the Standby's DG Alert.log file I found that the switchover completed with errors. The DBA was satisfied that the switchover worked, but did not do due diligence in investigating the accompanied error, and a few hours later DG stopped shipping Archivelogs altogether.




The solution was to correct the log_archive_config setting to what it was before the switchover, then to re-enable the Standby database in the DG Broker config. That fixed the lag, archives are now transported and applied to the Standby DB. That also corrected the Apply Lag reported in v$dataguard_stats.The Standby DB is now in sync and is usable in case of a DR, but further troubleshooting is necessary to determine why the Broker configuration was not 100% happy in the first place. 

Recover after a failed switchover

A failed swithcover attempt left both databases with a DATABASE_ROLE=PHYSICAL_STANDBY

Steps I followed to recover from the failure and to change the old PRIMARY back to PRIMARY was as follows:

SQL>shutdown immediate

ORA-01092: ORACLE instance terminated. Disconnection forced

Login to sqlplus again as sysdba and do a startup mount

SQL>startup mount

ORACLE instance started.

Total System Global Area 6.8947E+10 bytes

Fixed Size                  2189520 bytes

Variable Size            2.0670E+10 bytes

Database Buffers         4.8050E+10 bytes

Redo Buffers              225488896 bytes

Database mounted.

SQL>SELECT DATABASE_ROLE, status,OPEN_MODE,DB_UNIQUE_NAME, PROTECTION_MODE, PROTECTION_LEVEL, SWITCHOVER_STATUS

FROM V$DATABASE, V$INSTANCE

/

DATABASE_ROLE    STATUS       OPEN_MODE            DB_UNIQUE PROTECTION_MODE      PROTECTION_LEVEL     SWITCHOVER_STATUS

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

PHYSICAL STANDBY MOUNTED      MOUNTED              casprd    MAXIMUM PERFORMANCE  MAXIMUM PERFORMANCE  RECOVERY NEEDED

Cancel the MRP process. You may receive “ORA-16136: Managed Standby Recovery not active” if the MRP process is not running.

                                              0

SQL>alter database recover managed standby database cancel;

alter database recover managed standby database cancel

*

ERROR at line 1:

ORA-16136: Managed Standby Recovery not active

Terminate the current switchover to Standby that never completed fully.  

SQL>alter database recover managed standby database finish;

Now switchover to Primary.

SQL>alter database commit to switchover to primary with session shutdown;

Open the database.

SQL>alter database open;

 Confirm DATABASE_ROLE

SQL>SELECT DATABASE_ROLE, status,OPEN_MODE,DB_UNIQUE_NAME, PROTECTION_MODE, PROTECTION_LEVEL, SWITCHOVER_STATUs

FROM V$DATABASE, V$INSTANCE

/

DATABASE_ROLE    STATUS       OPEN_MODE            DB_UNIQUE PROTECTION_MODE      PROTECTION_LEVEL     SWITCHOVER_STATUS

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

PRIMARY          OPEN         READ WRITE           casprd    MAXIMUM PERFORMANCE  MAXIMUM PERFORMANCE  TO STANDBY

Drop Primary logfiles on Physical Standby Database

So we migrated a Physical Standby Database from RAW devices to ASM, after the move I still had to move the Online Redolog files:

SQL>select * from v$logfile;

    GROUP# STATUS  TYPE    MEMBER                             IS_

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

         1         ONLINE  /dev/vx/rdsk/redovmdg/casprd_REDO1  NO
         1         ONLINE  /dev/vx/rdsk/redovmdg/casprd_REDO1b NO
         2         ONLINE  /dev/vx/rdsk/redovmdg/casprd_REDO3  NO
         2         ONLINE  /dev/vx/rdsk/redovmdg/casprd_REDO3b NO
         3         ONLINE  /dev/vx/rdsk/redovmdg/casprd_REDO5  NO
         3         ONLINE  /dev/vx/rdsk/redovmdg/casprd_REDO5b NO

First step was to change STANDBY_FILE_MANAGEMENT from AUTO to MANUAL:

SQL>alter system set standby_file_management='MANUAL';

System altered.

But simply dropping a  logfile group was not so straight forward:

SQL>ALTER DATABASE DROP logfile group 1;

ALTER DATABASE DROP logfile group 1

*

ERROR at line 1:

ORA-01624: log 1 needed for crash recovery of instance castc (thread 1)

ORA-00312: online log 1 thread 1: '/dev/vx/rdsk/redovmdg/casprd_REDO1'

ORA-00312: online log 1 thread 1: '/dev/vx/rdsk/redovmdg/casprd_REDO1b'

Check the STATUS of the Online Redo log Group:

SQL>SELECT GROUP#, STATUS FROM V$LOG;

    GROUP# STATUS

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

         1 CLEARING
         2 CLEARING
         3 CURRENT

If Status is CLEARING or CURRENT then you cannot drop Online Redo log Group.The STATUS need to be CLEARED, UNUSED or INACTIVE

SQL>ALTER DATABASE CLEAR LOGFILE GROUP 1;

Database altered.

SQL>SELECT GROUP#, STATUS FROM V$LOG;

    GROUP# STATUS

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

         1 UNUSED
         2 CLEARING
         3 CURRENT

SQL>ALTER DATABASE DROP LOGFILE GROUP 1; 

.

SQL>alter database add logfile group 1 ('+PCASDG1','+PCASDG1');

Repeat for all groups and check:

SQL>select * from v$logfile;

    GROUP# STATUS  TYPE    MEMBER                                IS_

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

         1         ONLINE  +PCASDG1/castc/onlinelog/group_1.1148.826447293 NO
         1         ONLINE  +PCASDG1/castc/onlinelog/group_1.1149.826447293 NO
         2         ONLINE  +PCASDG1/castc/onlinelog/group_2.1153.826447427 NO
         2         ONLINE  +PCASDG1/castc/onlinelog/group_2.1152.826447431 NO
         3         ONLINE  +PCASDG1/castc/onlinelog/group_3.1180.826447635 NO
         3         ONLINE  +PCASDG1/castc/onlinelog/group_3.1181.826447641 NO

ORA-16714 in a RAC environment

I had to setup a physical standby in a RAC environment. The primary database is a two node RAC cluster but the standby environment is a single instance database.

During setup and configuration of the dataguard broker, we had the following error . ” ORA-16608: one or more sites have warnings”.

In DGMGRL, the command line interface of the broker you check the configuration status using “show configuration”, the broker would give you the current setup at the end of the show configuration output, the broker tries to query the current status from all servers involved, this includes all instances in the RAC configuration on the primary and also the physical standby.

DGMGRL> show configuration;

Configuration - ssodg

  Protection Mode: MaxPerformance

  Databases:

    ssoprd - Primary database

      Warning: ORA-16792: configurable property value is inconsistent with database setting

    ssodrp - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:

WARNING

2. So the problem is for a init.ora parameter on one (or both) RAC nodes. We need to drill down, so “show database ssoprd” would tell us which database has this error and also show which property (or init.ora parameter) it is complaining about.

DGMGRL> show database ssoprd;

Database - ssoprd

  Role:            PRIMARY

  Intended State:  TRANSPORT-ON

  Instance(s):

    ssoprd1

    ssoprd2

      Warning: ORA-16714: the value of property StandbyFileManagement is inconsistent with the database setting

      Warning: ORA-16714: the value of property ArchiveLagTarget is inconsistent with the database setting

      Warning: ORA-16714: the value of property LogArchiveMaxProcesses is inconsistent with the database setting

      Warning: ORA-16714: the value of property LogArchiveMinSucceedDest is inconsistent with the database setting

      Warning: ORA-16714: the value of property LogArchiveTrace is inconsistent with the database setting

      Warning: ORA-16714: the value of property LogArchiveFormat is inconsistent with the database setting

Database Status:

WARNING

3. So just one node in the RAC cluster has a problem and that is ssoprd2. I logged into that node and did a “show parameter standby_file_management” and it showed a value of AUTO. Back in DGMGRL I did “show database verbose ssoprd”. The verbose option shows you DG configured properties for a db. The StandbyFileManagement property was also set to AUTO, so what is the problem. The command “SHOW DATABASE ssoprd 'InconsistentProperties';” gave me more info.

It showed me the 3 different places where a property/parameter can be set MEMORY_VALUE,   SPFILE_VALUE and BROKER_VALUE. As confirmed earlier the database MEMORY_VALUE had and standby_file_management =AUTO and the BROKER_VALUE had StandbyFileManagement=AUTO, the problem was that the SPFILE_VALUE parameter for node ssoprd2 had a value of NULL.

4. Now why would one node in a RAC cluster have a different SPFILE value when the SPFILE is kept in a shared location on ASM? I looked in the $ORACLE_HOME/dbs directory of node ssoprd2 and found a spfilessoprd2.ora file! Even though the contents was ‘*.SPFILE='+DG_DATA/ssoprd/spfilessoprd.ora' which is the shared location it is still a non-shared spfile in the local $ORACLE_HOME! Just to confirm I looked into $ORACLE_HOME/dbs on the other node did not find a SPFILE there. So the solution was simply to shutdown node 2, remove the spfile from $ORACLE_HOME/dbs and then to start the database on node 2. Note that each node had a initssoprd?.ora file in the $ORACLE_HOME with the contents *.SPFILE='+DG_DATA/ssoprd/spfilessoprd.ora'

5. This fixed the issue, it was the DGB not able to synchronize the value of these various parameters/properties between the various instances in the cluster. In a RAC environment its a best practice to maintain the SPFILE in a shared location such as ASM storage.

The SHOW CONFIGURATION command from the DGMGRL returned error free.

DGMGRL> show configuration;Configuration - ssodg  Protection Mode: MaxPerformance  Databases:    ssoprd - Primary database    ssodrp - Physical standby database Fast-Start Failover: DISABLED Configuration Status:SUCCESS DGMGRL> show database ssoprd;Database - ssoprd  Role:            PRIMARY  Intended State:  TRANSPORT-ON  Instance(s):    ssoprd1    ssoprd2 Database Status:SUCCESS