17 | 08 | 2017
Latest Articles
Popular Articles

Data Guard

Using Logminer to troubleshoot logical standby database issues

User Rating:  / 1
PoorBest 

Using Logminer to troubleshoot logical standby database issues ( used for Oracle 9i ).

 


At standby database level I found a rather huge "gap" between dba_logstdby_progress.applied_time and dba_logstdby_progress.read_time


12:22:28 Lprim_db_DBA_USER_05/10/2011 23:36>select * from dba_logstdby_progress;

APPLIED_SCN APPLIED_TIME             READ_SCN READ_TIME              NEWEST_SCN NEWEST_TIME
---------------- ---------------- ---------------- ---------------- ---------------- ----------------
8854985832685 06/10/2011 12:47    8854933477078 05/10/2011 12:31    8854985832685 06/10/2011 12:47


 

Whenever we stop and restart the standby logical apply the reader, preparer and builder process takes a huge time to scan the redo prior to the (re) start of the real transaction apply. Why is that why there is such a big gap between dba_logstdby_progress.applied_time and dba_logstdby_progress.read_time ?

Answer. There are huge open transactions whch are not committed nor rolled back


At primary database level I found the archived log which containes the latest dba_logstdby_progress.read_time, dba_logstdby_progress.read_scn with

 

SQL > select sequence#,name from v$archived_log where 8854933477078 between first_change# and next_change#;

301809
Lprim_db

301809
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301809.arc



At primary database level I start a logminer session with a few archived redo logs.

 

 

SQL> begin
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301809.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301810.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301811.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301812.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301813.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301814.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301815.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301816.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301817.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301818.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301819.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301820.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301821.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301822.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301823.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301824.arc');
dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301825.arc');
end;
10  /

PL/SQL procedure successfully completed.

SQL> begin
dbms_logmnr.start_logmnr(options => dbms_logmnr.dict_from_online_catalog);
end;
/
PL/SQL procedure successfully completed.


At primary database level I verify the logminer logfiles

 


SQL> select filename from v$logmnr_logfile;

FILENAME
--------------------------------------------------------------------------------
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301809.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301810.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301811.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301812.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301813.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301814.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301815.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301816.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301817.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301818.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301819.arc

FILENAME
--------------------------------------------------------------------------------
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301820.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301821.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301822.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301823.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301824.arc
/prim_db/oracle/oradata/prim_db/archive/prim_db0000301825.arc

17 rows selected.


SQL> select scn,commit_timestamp,sql_redo,xidusn, xidslt, xidsqn from v$logmnr_contents where scn = 8854933477078 and rownum < 11;


SCN COMMIT_TIMESTAMP
---------------- ----------------
SQL_REDO
--------------------------------------------------------------------------------
XIDUSN           XIDSLT           XIDSQN
---------------- ---------------- ----------------
8854933477078
set transaction read write;
15               64            13476

8854933477078
update "SYS"."SEQ$" set "INCREMENT$" = '100', "MINVALUE" = '1', "MAXVALUE" = '99
99999999', "CYCLE#" = '0', "ORDER$" = '0', "CACHE" = '20', "HIGHWATER" = '636873
617', "AUDIT$" = '--------------------------------', "FLAGS" = '0' where "OBJ#"
= '29746' and "INCREMENT$" = '100' and "MINVALUE" = '1' and "MAXVALUE" = '999999
9999' and "CYCLE#" = '0' and "ORDER$" = '0' and "CACHE" = '20' and "HIGHWATER" =
'636871617' and "AUDIT$" = '--------------------------------' and "FLAGS" = '0'
and ROWID = 'AAAABDAABAAAAECABw';
15               64            13476



SQL> select scn,commit_timestamp,sql_redo,xidusn, xidslt, xidsqn from v$logmnr_contents where scn = 8854933477078 + 1 and rownum < 11;

SCN COMMIT_TIMESTAMP
---------------- ----------------
SQL_REDO
--------------------------------------------------------------------------------
XIDUSN           XIDSLT           XIDSQN
---------------- ---------------- ----------------
8854933477079 05/10/2011 12:31
commit;
15               64            13476

8854933477079
insert into "OWNER"."T1"("DISCREPANCY_ENTRY_ID","PROC_VAR
IABLE_NAME","COL1_ID","COL1_ENTRY_TS","VALUE_TEXT","DCF_INCLUDE") values
('636871617','MEDI.CMMODIFY','4405620617',TO_DATE('17/06/2011 08:43', 'DD/MM/YY
YY HH24:Mi'),'PADMARDS0812345678901234567890123456789012345678901234567890123456
78901234567890123456879012345678901234567890123456789012345678901234567890123456
789012345678901234567890123456879012345678901234567890','Y');
15               41            13461

8854933477079

15               41            13461

8854933477079

15               41            13461

8854933477079
insert into "OWNER"."T1"("DISCREPANCY_ENTRY_ID","PROC_VAR
IABLE_NAME","COL1_ID","COL1_ENTRY_TS","VALUE_TEXT","DCF_INCLUDE") values
('636871617','MEDI.RDSC_S',NULL,NULL,NULL,'Y');
15               41            13461

8854933477079

15               41            13461

8854933477079
insert into "OWNER"."T1"("DISCREPANCY_ENTRY_ID","PROC_VAR
IABLE_NAME","COL1_ID","COL1_ENTRY_TS","VALUE_TEXT","DCF_INCLUDE") values
('636871617','ROW',NULL,NULL,'8','Y');
15               41            13461

8854933477079

15               41            13461



SQL> select count(*) from v$logmnr_contents where xidusn = 15 and xidslt = 41 and xidsqn = 13461;

COUNT(*)
----------
556983


10 rows selected.

 

 

We see that the transaction with xidusn = 15 and xidslt = 41 and xidsqn = 13461 is still open, indeed the user did not commit nor rolled back, we thus can list the transaction in v$transaction.



SQL> select XIDUSN,XIDSLOT,XIDSQN,s.username,s.sid,s.serial#,s.osuser from v$transaction t,v$session s
13:37:58   2  where t.ses_addr = s.saddr
13:38:00   3  order by s.sid;

XIDUSN XIDSLOT  XIDSQN USERNAME                          SID          SERIAL# OSUSER                     
------ ------- ------- ------------------------------ ------ ---------------- ------------------------------
1       69       55534 OPS$USER1                       52            31376    sa_user1   
19      39        8151 OPS$USER3                       79            19134    sa_user2
15      41       13461 OPS$USER2                      128            17884    sa_user3





Note that you can run into this issue : A huge "gap" between dba_logstdby_progress.applied_time and dba_logstdby_progress.read_time when the transaction has recently been committed either rolled back. You thus find no entries in v$transaction anymore.