Data Guard
Using Logminer to troubleshoot logical standby database issues
User Rating:   / 4
- Details
-
Parent Category: Articles
-
Created on Thursday, 13 October 2011 13:01
-
Last Updated on Monday, 12 March 2012 13:54
-
Published on Thursday, 13 October 2011 13:01
-
Written by Guy Lambregts
-
Hits: 6388
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
2 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301809.arc');
3 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301810.arc');
4 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301811.arc');
5 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301812.arc');
6 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301813.arc');
7 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301814.arc');
8 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301815.arc');
2 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301816.arc');
3 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301817.arc');
4 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301818.arc');
5 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301819.arc');
6 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301820.arc');
7 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301821.arc');
8 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301822.arc');
6 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301823.arc');
7 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301824.arc');
8 dbms_logmnr.add_logfile('/prim_db/oracle/oradata/prim_db/archive/prim_db0000301825.arc');
9 end;
10 /
PL/SQL procedure successfully completed.
SQL> begin
2 dbms_logmnr.start_logmnr(options => dbms_logmnr.dict_from_online_catalog);
3 end;
4 /
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.
|
