Friday, June 8, 2012

Accurately predicting the redo log sequence needed for a Golden Gate Restart

Bounded Recovery is set to 20 Minutes.

1. Started an active transaction which runs for 5 hours at 8.11AM.
The log sequence at the start of transaction is 16230 (please see below logfile).

jupiter<oracle>/tmp> cat test.sh
#!/bin/ksh
. /usr/local/bin/sid athenadv
sqlplus ops\$gchandra/test123 << EOF >test.log

select max(sequence#) from v\$log;
select to_char(sysdate,'dd-mon-yyyy hh24:mi:ss') from dual;
drop table testtab;
create table testtab (col1 number);
insert into testtab values(1);
execute dbms_lock.sleep(18000);
commit;
exit
EOF

Run the above script(in the background)
nohup ./test.sh &

Now check the spool file created.....

jupiter<oracle>/tmp> cat test.log

SQL*Plus: Release 11.2.0.3.0 Production on Fri Jun 8 08:11:22 2012

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


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Data Mining
and Real Application Testing options

SQL> SQL>
MAX(SEQUENCE#)
--------------
         16230

SQL>
TO_CHAR(SYSDATE,'DD-MON-YYYYH
-----------------------------
08-jun-2012 08:11:22

SQL>
Table dropped.

SQL>
Table created.

SQL>
1 row created.


2.

At around 10am, I stop the extract process.
GGSCI (jupiter) 2> stop ext xtathdv

Sending STOP request to EXTRACT XTATHDV ...
Request processed.

3. Check the BR checkpoint from ggserr.log and also from BR directory.
It hapenned at around 9.42am.

2012-06-08 09:42:24  INFO    OGG-01738  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: CHECKPOINT: for object pool 1: p28822_extr: start=SeqNo: 16293, RBA: 75422736, SCN: 1932.1174983728 (8299051799600), Timestamp: 2012-06-08 09:42:23.000000, end=SeqNo: 16293, RBA: 75423744, SCN: 1932.1174983728 (8299051799600), Timestamp: 2012-06-08 09:42:23.000000.

jupiter<oracle>/oracle/software/goldengate/11.1.1.1.2/BR/XTATHDV> ls -lt
total 88
-rw-rw----   1 oracle     dba          65536 Jun  8 09:42 CP.XTATHDV.000000039
-rw-rw----   1 oracle     dba          65536 Jun  8 09:22 PO.XTATHDV.0000007.0000000
-rw-rw----   1 oracle     dba          65536 Jun  8 08:42 PO.XTATHDV.0000006.0000000
drwxrwxr-x   2 oracle     dba             96 Jun  7 15:54 stale


4.Check the archive log sequence at around 9.42am.

select sequence# from v$archived_log
  where to_date('08-jun-2012 09:42:00','dd-mon-yyyy hh24:mi:ss') between first_time and next_time;

SQL> select sequence# from v$archived_log
  2    where to_date('08-jun-2012 09:42:00','dd-mon-yyyy hh24:mi:ss') between first_time and next_time;

 SEQUENCE#
----------
     16293
    
This means I need only archive log from sequence 16293 when I restart GG extract process.
I should not need from sequence 16230(log sequence # from start of transaction).


5.Perform a few log switches and delete all archive files from RMAN.
SQL> alter system switch logfile;

System altered.

SQL> /

System altered.

SQL> /

System altered.

Run the following from rman -

run {
allocate channel c1 type 'sbt_tape' parms 'ENV=(TDPO_OPTFILE=/oracle/admin/backup/config/jupiter_tdpo.opt)';
backup
filesperset = 4
format 'al_%d%s%t_%U'
archivelog until time 'SYSDATE'
delete all input;
sql 'alter system archive log current';
release channel c1;
}


6.Kill the test.sh script.

jupiter<oracle>/oracle/arch/athenadv/arch> ps -ef|grep test.sh
  oracle  5072     1  0 08:11:22 ?         0:00 /bin/ksh ./test.sh
  oracle 15014 26448  0 10:16:01 pts/6     0:00 grep test.sh
jupiter<oracle>/oracle/arch/athenadv/arch> ps -ef|grep sqlplus
  oracle  5077  5072  0 08:11:22 ?         0:00 sqlplus ops$gchandra/test123
  oracle 15018 26448  1 10:16:08 pts/6     0:00 grep sqlplus
jupiter<oracle>/oracle/arch/athenadv/arch> kill -9 5077
jupiter<oracle>/oracle/arch/athenadv/arch>
jupiter<oracle>/oracle/arch/athenadv/arch> ps -ef|grep test.sh
  oracle 16879 26448  1 10:16:27 pts/6     0:00 grep test.sh
jupiter<oracle>/oracle/arch/athenadv/arch>


7.

GGSCI (jupiter) 2> start ext xtathdv

Sending START request to MANAGER ...
EXTRACT XTATHDV starting


2012-06-08 10:44:42  INFO    OGG-00987  Oracle GoldenGate Command Interpreter for Oracle:  GGSCI command (oracle): start ext xtathdv.
2012-06-08 10:44:42  INFO    OGG-00963  Oracle GoldenGate Manager for Oracle, mgr.prm:  Command received from GGSCI on host 10.64.17.19 (START EXTRACT XTATHDV ).
2012-06-08 10:44:42  INFO    OGG-00975  Oracle GoldenGate Manager for Oracle, mgr.prm:  EXTRACT XTATHDV starting.
2012-06-08 10:44:42  INFO    OGG-00992  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  EXTRACT XTATHDV starting.
2012-06-08 10:44:43  INFO    OGG-01639  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY:  ACTIVE: for object pool 1: p28822_extr.
2012-06-08 10:44:43  INFO    OGG-01640  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: recovery start XID: 0.0.0.
2012-06-08 10:44:43  INFO    OGG-01641  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: recovery start position: SeqNo: 16293, RBA: 75422736, SCN: 1932.1174983728 (8299051799600), Timestamp: 2012-06-08 09:42:23.000000.
2012-06-08 10:44:43  INFO    OGG-01642  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: recovery end position: SeqNo: 16293, RBA: 75423744, SCN: 1932.1174983728 (8299051799600), Timestamp: 2012-06-08 09:42:23.000000.
2012-06-08 10:44:43  INFO    OGG-01579  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: VALID BCP: CP.XTATHDV.000000039.
2012-06-08 10:44:43  INFO    OGG-01629  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: PERSISTED OBJECTS RECOVERED: 2.
2012-06-08 10:44:45  INFO    OGG-01513  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Positioning to Sequence 16293, RBA 75422736.
2012-06-08 10:46:12  ERROR   OGG-00446  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Could not find archived log for sequence 16293 thread 1 under default destinations SQL <SELECT  name    FROM v$archived_log   WHERE sequence# = :ora_seq_no AND         thread# = :ora_thread AND         resetlogs_id = :ora_resetlog_id AND         archived = 'YES' AND         deleted = 'NO>, error retrieving redo file name for sequence 16293, archived = 1, use_alternate = 0Not able to establish initial position for sequence 16293, rba 75422736.
2012-06-08 10:46:12  ERROR   OGG-01668  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  PROCESS ABENDING.


The above log extract says that it reads from 16293. That is as per my expectation.

Since 16293 is not present in archive destination, the GG process abends as expected.



8.Restore the archive log from rman

RMAN> RESTORE ARCHIVELOG FROM SEQUENCE 16293;

Starting restore at 08-Jun-2012
allocated channel: ORA_SBT_TAPE_1
channel ORA_SBT_TAPE_1: SID=112 device type=SBT_TAPE
channel ORA_SBT_TAPE_1: Data Protection for Oracle: version 5.5.2.0
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=594 device type=DISK

archived log for thread 1 with sequence 16348 is already on disk as file /oracle/arch/athenadv/arch/1_16348_783838261.dbf
archived log for thread 1 with sequence 16349 is already on disk as file /oracle/arch/athenadv/arch/1_16349_783838261.dbf
..
..
..

9. Restart the GG extract process and observe the logfile

GGSCI (jupiter) 3> start ext xtathdv

Sending START request to MANAGER ...
EXTRACT XTATHDV starting


Observe the logfile

2012-06-08 10:51:46  INFO    OGG-00975  Oracle GoldenGate Manager for Oracle, mgr.prm:  EXTRACT XTATHDV starting.
2012-06-08 10:51:46  INFO    OGG-00992  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  EXTRACT XTATHDV starting.
2012-06-08 10:51:46  INFO    OGG-01639  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY:  ACTIVE: for object pool 1: p28822_extr.
2012-06-08 10:51:46  INFO    OGG-01640  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: recovery start XID: 0.0.0.
2012-06-08 10:51:46  INFO    OGG-01641  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: recovery start position: SeqNo: 16293, RBA: 75422736, SCN: 1932.1174983728 (8299051799600), Timestamp: 2012-06-08 09:42:23.000000.
2012-06-08 10:51:46  INFO    OGG-01642  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: recovery end position: SeqNo: 16293, RBA: 75423744, SCN: 1932.1174983728 (8299051799600), Timestamp: 2012-06-08 09:42:23.000000.
2012-06-08 10:51:46  INFO    OGG-01579  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: VALID BCP: CP.XTATHDV.000000039.
2012-06-08 10:51:46  INFO    OGG-01629  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: PERSISTED OBJECTS RECOVERED: 2.
2012-06-08 10:51:49  INFO    OGG-01513  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Positioning to Sequence 16293, RBA 75422736.
2012-06-08 10:51:49  INFO    OGG-01516  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Positioned to Sequence 16293, RBA 75422736, Jun 8, 2012 9:42:23 AM.
2012-06-08 10:51:49  INFO    OGG-00993  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  EXTRACT XTATHDV started.
2012-06-08 10:51:49  INFO    OGG-01055  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Recovery initialization completed for target file /oracle/goldengatedata/dirdat/at000011, at RBA 32117725.
2012-06-08 10:51:49  INFO    OGG-01478  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Output file /oracle/goldengatedata/dirdat/at is using format RELEASE 10.4/11.1.
2012-06-08 10:51:49  INFO    OGG-01026  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Rolling over remote file /oracle/goldengatedata/dirdat/at000011.
2012-06-08 10:51:49  INFO    OGG-01053  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Recovery completed for target file /oracle/goldengatedata/dirdat/at000012, at RBA 1032.
2012-06-08 10:51:49  INFO    OGG-01057  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Recovery completed for all targets.
2012-06-08 10:51:50  INFO    OGG-01517  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  Position of first record processed Sequence 16293, RBA 75422736, SCN 1932.1174983725, Jun 8, 2012 9:42:23 AM.
2012-06-08 10:51:50  INFO    OGG-01644  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  BOUNDED RECOVERY: COMPLETE: for object pool 1: p28822_extr at SeqNo: 16293, RBA: 75423760, SCN: 1932.1174983729 (8299051799601).
2012-06-08 10:52:37  WARNING OGG-00869  Oracle GoldenGate Capture for Oracle, xtathdv.prm:  No unique key is defined for table DV3_STATUS. All viable columns will be used to represent the key, but may not guarantee uniqueness.  KEYCOLS may be used to define the key.


Looks like GG extract is chuggling along.

Hope you find this useful.

No comments:

Post a Comment