Pages

Monday, May 21, 2018

Oracle Golden Gate Extract is failing with: ERROR OGG-00868 Error code 1291, error message: ORA-01291: missing logfile.

=======================
General
=======================
The archive folder was 100% full.
As an SOS operation, all archive files were deleted.
Now, several Extract process are in Abended state.
When checking  with info extract EXT_I_01 DETAIL, the error is:

2018-05-21 06:33:43  ERROR   OGG-00868  Error code 1291, error message: ORA-01291: missing logfile
 (Missing Log File /oracle_db/db2/db_igt/arch/arch0001_136774_827755274.arc. Read Position SCN -976006635).

2018-05-21 06:33:43  ERROR   OGG-01668  PROCESS ABENDING.

How to resolve this situation?

=======================
Evidences
=======================
via ggsci

info all 
EXTRACT     ABENDED     EXT_I_01    00:06:36      118:28:15   
EXTRACT     ABENDED     EXT_I_02    00:06:31      118:28:14   
EXTRACT     ABENDED     EXT_I_04    00:06:28      118:28:20   
EXTRACT     ABENDED     EXT_I_05    00:00:06      263:13:17   
EXTRACT     ABENDED     EXT_I_06    00:06:29      118:28:20   
EXTRACT     ABENDED     EXT_I_07    00:06:28      118:28:18   
EXTRACT     ABENDED     EXT_I_09    00:06:30      118:28:22   
EXTRACT     ABENDED     EXT_I_10    00:06:27      118:28:20   
EXTRACT     ABENDED     EXT_I_11    00:06:26      118:28:21   
EXTRACT     ABENDED     EXT_I_13    00:06:36      118:28:15   
EXTRACT     ABENDED     EXT_I_14    00:06:33      118:28:19   
EXTRACT     ABENDED     EXT_I_15    00:06:31      118:28:19   
EXTRACT     ABENDED     EXT_I_17    00:06:30      118:28:20   
EXTRACT     ABENDED     EXT_P_01    00:06:32      118:28:20   
EXTRACT     ABENDED     EXT_P_02    00:06:32      118:28:15   
EXTRACT     ABENDED     EXT_P_04    00:06:30      118:28:21   
EXTRACT     ABENDED     EXT_P_05    00:00:05      263:13:12   
EXTRACT     ABENDED     EXT_P_06    00:06:25      118:28:26   
EXTRACT     ABENDED     EXT_P_07    00:06:28      118:28:18   
EXTRACT     ABENDED     EXT_P_09    00:06:30      118:28:20   
EXTRACT     ABENDED     EXT_P_10    00:06:27      118:28:21   
EXTRACT     ABENDED     EXT_P_11    00:06:30      118:28:22   
EXTRACT     ABENDED     EXT_P_13    00:06:35      118:28:16   
EXTRACT     ABENDED     EXT_P_14    00:06:28      118:28:19   
EXTRACT     ABENDED     EXT_P_15    00:06:28      118:28:18   
EXTRACT     ABENDED     EXT_P_17    00:06:33      118:28:20   
EXTRACT     ABENDED     EXT_S_13    00:06:29      118:28:19   
EXTRACT     ABENDED     EXT_S_14    00:06:32      118:28:21   
EXTRACT     ABENDED     EXT_S_15    00:06:28      118:28:19   
EXTRACT     ABENDED     EXT_S_17    00:06:34      118:28:18  


GGSCI (my_server) 19> VIEW PARAM EXT_I_01 
Will display extact parameter files


GGSCI (my_server) 19> info extract EXT_I_01 DETAIL

EXTRACT    EXT_I_01  Last Started 2018-01-29 06:48   Status ABENDED
Checkpoint Lag       00:06:36 (updated 118:35:46 ago)
Log Read Checkpoint  Oracle Integrated Redo Logs
                     2018-05-16 07:52:30
                     SCN 3.3318960661 (16203862549)

  Target Extract Trails:

  Trail Name                                       Seqno        RBA     Max MB Trail Type

  /software/ogg/1212/dirdat/01/out/ei                 12     458809        100 EXTTRAIL  


Integrated Extract outbound server first scn: Unavailable.Need DBLOGIN.

  Extract Source          Begin             End        
  Not Available           2018-01-17 10:36  2018-05-16 07:52
  Not Available           2018-01-17 10:36  2018-01-29 06:47
  Not Available           2018-01-17 10:36  2018-01-28 06:47
  Not Available           2018-01-17 10:36  2018-01-27 06:47
  Not Available           2018-01-17 10:36  2018-01-26 06:47
  Not Available           2018-01-17 10:36  2018-01-25 06:47
  Not Available           2018-01-17 10:36  2018-01-24 06:47
  Not Available           2018-01-17 10:36  2018-01-23 06:47
  Not Available           2018-01-17 10:36  2018-01-22 06:47
  Not Available           2018-01-17 10:36  2018-01-21 06:47
  Not Available           2018-01-17 10:36  2018-01-20 06:47
  Not Available           2018-01-17 10:36  2018-01-19 06:47
  Not Available           2018-01-17 10:36  2018-01-18 06:47
  Not Available           * Initialized *   2018-01-17 10:36



Current directory    /software/ogg/1212
Report file          /software/ogg/1212/dirrpt/EXT_I_01.rpt
Parameter file       /software/ogg/1212/dirprm/ext_i_01.prm
Checkpoint file      /software/ogg/1212/dirchk/EXT_I_01.cpe
Process file         /software/ogg/1212/dirpcs/EXT_I_01.pce
Error log            /software/ogg/1212/ggserr.log


 less  /software/ogg/1212/dirrpt/EXT_I_01.rpt
Source Context :
  SourceModule            : [er.redo.oraxo]
  SourceID                : [/scratch/aime1/adestore/views/aime1_adc4150472/oggcore/OpenSys/src/app/er/redo/oracle/redooraix.c]
  SourceFunction          : [REDOORAIX_abend_if_missing_logfile]
  SourceLine              : [8206]
  ThreadBacktrace         : [15] elements
                          : [/software/ogg/1212/libgglog.so(CMessageContext::AddThreadContext()+0x1e) [0x7fd7c02e5dee]]
                          : [/software/ogg/1212/libgglog.so(CMessageFactory::CreateMessage(CSourceContext*, unsigned int, ...)+0x31c) [0x7fd7c02e2c2c]]
                          : [/software/ogg/1212/libgglog.so(_MSG_ERR_DB_GENERIC_FAILURE(CSourceContext*, char const*, CMessageFactory::MessageDisposition)+0x31) [0x7fd7c02c81d1]]
                          : [/software/ogg/1212/extract(REDOORAIX_abend_if_missing_logfile(char*)+0x1b9) [0x7b9a57]]
                          : [/software/ogg/1212/extract(REDOORAIX_attach(ggs::gglib::ggunicode::UString&, int, char (&) [2048])+0x274) [0x7ae574]]
                          : [/software/ogg/1212/extract(REDOORAIX_validate_config()+0x4e9) [0x7b21f9]]
                          : [/software/ogg/1212/extract(REDO_validate_config(int, unsigned int*, int*)+0xfab) [0x71f07b]]
                          : [/software/ogg/1212/extract(redo_log_setup()+0x36) [0x5ad3c6]]
                          : [/software/ogg/1212/extract(extract_main(int, char**)+0x29e) [0x5b096e]]
                          : [/software/ogg/1212/extract(ggs::gglib::MultiThreading::MainThread::ExecMain()+0x4f) [0x68743f]]
                          : [/software/ogg/1212/extract(ggs::gglib::MultiThreading::Thread::RunThread(ggs::gglib::MultiThreading::Thread::ThreadArgs*)+0x104) [0x687694]]
                          : [/software/ogg/1212/extract(ggs::gglib::MultiThreading::MainThread::Run(int, char**)+0x8b) [0x68785b]]
                          : [/software/ogg/1212/extract(main+0x3f) [0x5b047f]]
                          : [/lib64/libc.so.6(__libc_start_main+0xfd) [0x3998c1ed1d]]
                          : [/software/ogg/1212/extract() [0x51dc59]]

2018-05-21 06:33:43  ERROR   OGG-00868  Error code 1291, error message: ORA-01291: missing logfile
 (Missing Log File /oracle_db/db2/db_igt/arch/arch0001_136774_827755274.arc. Read Position SCN -976006635).

2018-05-21 06:33:43  ERROR   OGG-01668  PROCESS ABENDING.

======================================================
Solution
======================================================
The solution would be to unregister and register the extract process, causing it to reset to currect SCN value.

GGSCI (my_server) 2> DBLOGIN USERID OGG  PASSWORD <password>
Successfully logged into database.

GGSCI (my_server) 15> STOP EXTRACT EXT_I_02
EXTRACT EXT_I_02 is already stopped.

If extract cannot be stopped do:
ALTER EXTRACT EXT_P_02, BEGIN NOW

GGSCI (my_server) 16> UNREGISTER EXTRACT EXT_I_02 DATABASE   
Successfully unregistered EXTRACT EXT_I_02 from database.
This might take several minutes

GGSCI (my_server) 17> REGISTER EXTRACT EXT_I_02 DATABASE
Extract EXT_I_02 successfully registered with database at SCN 16308342873.
This might take several minutes

GGSCI (my_server) 18> START EXTRACT EXT_I_02

Sending START request to MANAGER ...
EXTRACT EXT_I_02 starting


GGSCI (my_server) 13> INFO EXTRACT EXT_I_02

EXTRACT    EXT_I_01  Last Started 2018-05-21 08:20   Status RUNNING
Checkpoint Lag       00:00:00 (updated 00:00:00 ago)
Process ID           36729
Log Read Checkpoint  Oracle Integrated Redo Logs
                     First Record       
                     SCN 3.3405189667 (16290091555)


===============================
Additional Information
===============================
Checking the SCN with INFO EXTRACT XXX SHOWCH command one can see that the SCN in extract is pointing to a deleted archive file

Get data from Database
oracle@my_server:/oracle_db/db2/db_igt/arch>% ls -ltr | head -10
total 59342928
-rw-r----- 1 oracle dba 372660224 May 20 15:44 arch0001_137783_827755274.arc
-rw-r----- 1 oracle dba 371138560 May 20 15:44 arch0001_137784_827755274.arc
-rw-r----- 1 oracle dba 393000960 May 20 15:44 arch0001_137785_827755274.arc
-rw-r----- 1 oracle dba 372824064 May 20 15:45 arch0001_137786_827755274.arc
-rw-r----- 1 oracle dba 384171008 May 20 15:46 arch0001_137787_827755274.arc
-rw-r----- 1 oracle dba 491667968 May 20 15:49 arch0001_137788_827755274.arc
-rw-r----- 1 oracle dba 489092608 May 20 15:51 arch0001_137789_827755274.arc
-rw-r----- 1 oracle dba 377072128 May 20 15:53 arch0001_137790_827755274.arc
-rw-r----- 1 oracle dba 379522048 May 20 15:55 arch0001_137791_827755274.arc

SELECT recid, 
       name, 
       first_change#, 
       next_change#,  
       TO_CHAR(first_time, 'YYYYMMDD hh24:mi:ss') AS first_time 
  FROM V$ARCHIVED_LOG 
 WHERE name LIKE '%arch0001_137783_827755274%';

recid  name
------- --------------------------------------------------------
137782 /oracle_db/db2/db_igt/arch/arch0001_137783_827755274.arc

first_change# next_change#  first_time
------------- ------------ -----------------
16290091555 16290177738 20180520 13:23:04


SELECT dbid, current_scn  FROM V$DATABASE;
dbid current_scn
----------- -----------
1066039690 16307173674


Get data from Extract

GGSCI (my_server) 27> INFO EXTRACT EXT_I_05 SHOWCH

EXTRACT    EXT_I_05  Last Started 2018-05-16 07:53   Status ABENDED
Checkpoint Lag       00:00:06 (updated 265:36:17 ago)
Log Read Checkpoint  Oracle Integrated Redo Logs
                     2018-05-10 07:13:58
                     SCN 3.3213072676 (16097974564)


Current Checkpoint Detail:

Read Checkpoint #1

  Oracle Integrated Redo Log

  Startup Checkpoint (starting position in the data source):
    Timestamp: 2015-08-09 08:42:51.000000
    SCN: Not available

  Recovery Checkpoint (position of oldest unprocessed transaction in the data source):
    Timestamp: 2018-05-10 07:13:58.000000
    SCN: 3.3213072615 (16097974503)

  Current Checkpoint (position of last record read in the data source):
    Timestamp: 2018-05-10 07:13:58.000000
    SCN: 3.3213072676 (16097974564)

  BR Previous Recovery Checkpoint:
    Timestamp: 2018-01-29 06:48:22.685278
    SCN: Not available

  BR Begin Recovery Checkpoint:
    Timestamp: 2018-05-10 05:21:30.000000
    SCN: 3.3212132747 (16097034635)

  BR End Recovery Checkpoint:
    Timestamp: 2018-05-10 05:21:30.000000
    SCN: 3.3212132747 (16097034635)

Write Checkpoint #1

  GGS Log Trail

  Current Checkpoint (current write position):
    Sequence #: 363
    RBA: 1495
    Timestamp: 2018-05-10 07:14:04.547894
    Extract Trail: /software/ogg/1212/dirdat/05/out/ei
    Trail Type: EXTTRAIL

Header:
  Version = 2
  Record Source = A
  Type = 13
  # Input Checkpoints = 1
  # Output Checkpoints = 1

File Information:
  Block Size = 2048
  Max Blocks = 100
  Record Length = 2048
  Current Offset = 0

Configuration:
  Data Source = 3
  Transaction Integrity = 1
  Task Type = 0

Status:
  Start Time = 2018-05-16 07:53:24
  Last Update Time = 2018-05-10 07:14:04
  Stop Status = A
  Last Result = 0
  

So in archive logs, the first available SCN is 16290091555 starting at 20180520 13:23:04
But the extract is expecting to process SCN 16097974503 from 2018-05-10 07:13:58.

The latest available archive file start with first_change# 16290091555 but extract expect to process SCN starting from 16097974503.

Since the archive files were deleted, the only option is to reset the extract, by register and register it again to the database.

Once that was done, the SCN in Golden Gate extract was in sync with SCN in database.

Sunday, May 13, 2018

SQL Server. Top Segments and shrink datafile

=======================
To see top Segments
=======================
SELECT CAST(object_name(id) as varchar(50)) AS object_name, 
       SUM(CASE WHEN indid<2 THEN rows END) AS rows,
       ROUND(SUM(reserved)*8/1024,0) AS reserved_Mb, 
       ROUND(SUM(dpages)*8/1024,0) AS Size_Mb, 
       ROUND(SUM(used-dpages)*8/1024,0) AS Used_Mb, 
       ROUND(SUM(reserved-used)*8/1024,0) AS Unused_Mb
  FROM sysindexes with (nolock) 
 WHERE indid in(0,1,255) and id>100 
 GROUP BY id with rollup
 ORDER BY sum(dpages)*8 desc;


object_name            rows reserved_Mb Size_Mb Used_Mb Unused_Mb
------------------ -------- ----------- ------- ------- ---------
NULL 34550143      120475    7626   82027     30822
email_contact       9439214        3094    3084      10         0
email_user_details  3845153        1008     987      13         7
email_message       1236052      112406     587   81804     30014
USER_CompanyStatus 11786380 466     460       0         5
email_association   1445918 355     350       3         2
IncidentAuditLog     682479 390     345      43         1
UserActivityLog     2194807 390     296       0        94
IncidentWorkNote     306004         291     278      12         0
EmailsLOG            265786         237     236       0         0


=======================
To free up unused space:
=======================
DBCC SHRINKFILE('cdb_Data',125000)

cdb_Data is the file logical name.

The output:
(1 row(s) affected)
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Dbid Field CurrentSize MinimumSize UsedPages  EstimatedPagaed
   7     1    16000000         128  15760728         15760728

15760728*8=126085824 Kb = 123130 Mb
So in theory we can shrink data file only to 123,130Mb
Lets try to shrink to 120,000Mb
DBCC SHRINKFILE('Starhome_Data',120000) 
This should not work...
After long long time, several hours, the command was still running...
I had to kill it.



Sunday, April 29, 2018

PL/SQ and sqlplus batch by example. Delete from Table in Three Steps

=======================
General
=======================
Generic delete from  a table using Business Logic.
Several million of records are being deleted.
The flow is a three steps process:


Step1.
pre_run_steps.sh
This create backup table for SOURCE_DATA_SUBSCRIBER (SOURCE_DATA_SUBSCRIBER_BAK) 
Creates additional temporary tables which are to be used during actual delete step.


Step2.
main_delete.sh 
The actual DELETE. 
Create the PL/SQL Package, which handles the business logic.
Call the PL/SQL package.
Progress is logged into SGA_W_LOG Table.

Step3.

post_run_steps.sh
This drop the SOURCE_DATA_SUBSCRIBER_BAK and drop additional temporary tables created in pre_run_steps.sh

=======================
Code
=======================
Step 0.
set_vipuser.sql

Step1.
pre_run_steps.sh
pre_run_steps.batpre_run_steps.sql


Step2.
main_delete.shmain_delete.bat
main_delete.sql
MULTI_DELETE.sql

Step3.
post_run_steps.shpost_run_steps.batpost_run_steps.sql

Step 0.
set_vipuser.sql
--Set the connection detailsdefine vipuser=my_userdefine vippass=my_passdefine connectStr=MY_INSTANCE
Step 1.
pre_run_steps.sh
sqlplus /nolog @pre_run_steps.sql

pre_run_steps.bat
sqlplus /nolog @pre_run_steps.sql

pre_run_steps.sql
@../set_vipuser.sql

SET SERVEROUT ON
SET HEADING OFF
SET LINESIZE 400
SET PAGESIZE 0
SET FEEDBACK OFF
SET VERIFY OFF

PROMPT conn &&vipuser/&&vippass@&&connectStr
conn &&vipuser/&&vippass@&&connectStr

EXEC DBMS_OUTPUT.ENABLE(100000);

PROMPT CREATE TABLE SOURCE_DATA_SUBSCRIBER_BAK AS SELECT * FROM SOURCE_USER.SOURCE_DATA_SUBSCRIBER WHERE 1=2;
DECLARE
  v_sql_str    VARCHAR2(2000);
  v_counter    NUMBER;
BEGIN
  SELECT COUNT(*) INTO v_counter FROM USER_TABLES WHERE table_name = 'SOURCE_DATA_SUBSCRIBER_BAK'; 
  IF v_counter = 0 THEN
    v_sql_str := 'CREATE TABLE SOURCE_DATA_SUBSCRIBER_BAK AS SELECT * FROM SOURCE_USER.SOURCE_DATA_SUBSCRIBER WHERE 1=2';
  ELSE
    v_sql_str := 'TRUNCATE TABLE SOURCE_DATA_SUBSCRIBER_BAK';
  END IF;
  EXECUTE IMMEDIATE v_sql_str;
END;
/

PROMPT ALTER TABLE SOURCE_DATA_SUBSCRIBER_BAK MOVE TABLESPACE IGT_TEMP_TABLE;
ALTER TABLE SOURCE_DATA_SUBSCRIBER_BAK MOVE TABLESPACE IGT_TEMP_TABLE;

PROMPT INSERT /*+ APPEND */ INTO SOURCE_DATA_SUBSCRIBER_BAK SELECT * FROM SOURCE_USER.SOURCE_DATA_SUBSCRIBER;
INSERT /*+ APPEND */ INTO SOURCE_DATA_SUBSCRIBER_BAK SELECT * FROM SOURCE_USER.SOURCE_DATA_SUBSCRIBER;
COMMIT;

PROMPT CREATE TABLE   SGA_LOC_GRP_OUTBACK_NETWORKS
DECLARE
  v_sql_str    VARCHAR2(2000);
  v_counter    NUMBER;
BEGIN
  SELECT COUNT(*) INTO v_counter FROM USER_TABLES WHERE table_name = 'SGA_LOC_GRP_OUTBACK_NETWORKS'; 
  IF v_counter = 0 THEN
    v_sql_str := 'CREATE TABLE   SGA_LOC_GRP_OUTBACK_NETWORKS (network_id        NUMBER(10) ) TABLESPACE IGT_TEMP_TABLE;';
  ELSE
    v_sql_str := 'TRUNCATE TABLE SGA_LOC_GRP_OUTBACK_NETWORKS';
  END IF;
  EXECUTE IMMEDIATE v_sql_str;
END;
/


PROMPT CREATE TABLE   MSISDN_PROFILE_NOT_PRE
DECLARE
  v_sql_str    VARCHAR2(2000);
  v_counter    NUMBER;
BEGIN
  SELECT COUNT(*) INTO v_counter FROM USER_TABLES WHERE table_name = 'MSISDN_PROFILE_NOT_PRE'; 
  IF v_counter = 0 THEN
    v_sql_str := 'CREATE TABLE   MSISDN_PROFILE_NOT_PRE (msisdn VARCHAR2(30) NOT NULL) TABLESPACE IGT_TEMP_TABLE;';
  ELSE
    v_sql_str := 'TRUNCATE TABLE MSISDN_PROFILE_NOT_PRE';
  END IF;
  EXECUTE IMMEDIATE v_sql_str;
END;
/

PROMPT INSERT /*+ APPEND */ INTO SGA_LOC_GRP_OUTBACK_NETWORKS
INSERT /*+ APPEND */ INTO SGA_LOC_GRP_OUTBACK_NETWORKS
SELECT DISTINCT network_id 
    FROM SOURCE_USER.SGA_LOCATION_GROUP_ENTRIES 
   WHERE location_group_id IN 
         (SELECT location_group_id 
    FROM SOURCE_USER.SGA_LOCATION_GROUPS 
WHERE LOCATION_GROUP_NAME='Outback');
commit;

PROMPT INSERT /*+ APPEND */ INTO MSISDN_PROFILE_NOT_PRE(msisdn)
INSERT /*+ APPEND */ INTO MSISDN_PROFILE_NOT_PRE(msisdn)
SELECT KEY1 FROM SOURCE_USER.SFI_CUSTOMER_PROFILE WHERE ATTR1 NOT IN ('RogEngPre','RogFrPre','FidoEngPre','FidoFrPre');
commit;


PROMPT CREATE INDEX SFI_CST_PROF_IX
DECLARE
  v_sql_str    VARCHAR2(2000);
  v_counter    NUMBER;
BEGIN
  SELECT COUNT(*) INTO v_counter FROM USER_INDEXES WHERE index_name = 'SFI_CST_PROF_IX'; 
  IF v_counter > 0 THEN
    v_sql_str := 'DROP INDEX SFI_CST_PROF_IX';
  END IF;
  EXECUTE IMMEDIATE v_sql_str;
END;
/

PROMPT CREATE INDEX SFI_CST_PROF_IX ON MSISDN_PROFILE_NOT_PRE(msisdn) TABLESPACE IGT_TEMP_INDEX;
CREATE INDEX SFI_CST_PROF_IX ON MSISDN_PROFILE_NOT_PRE(msisdn) TABLESPACE IGT_TEMP_INDEX;

BEGIN
  DBMS_STATS.gather_table_stats('&&vipuser','MSISDN_PROFILE_NOT_PRE');
END;
/

PROMPT Finished Pre Run step
EXIT;



Step 2.
main_delete.sh
sqlplus /nolog @main_delete.sql

main_delete.bat
sqlplus /nolog @main_delete.sql

main_delete.sql
@../set_vipuser.sql

SET SERVEROUT ON
SET HEADING OFF
SET LINESIZE 400
SET PAGESIZE 0
SET FEEDBACK OFF

PROMPT conn &&vipuser/&&vippass@&&connectStr
conn &&vipuser/&&vippass@&&connectStr

EXEC DBMS_OUTPUT.ENABLE(100000);

PROMPT CREATE PROCEDURE MULTI_DELETE
@MULTI_DELETE.sql

PROMPT EXECUTE PROCEDURE MULTI_DELETE
PROMPT .............................
PROMPT Running DELETE....
PROMPT Follow Up on process Progress by: SELECT * FROM SGA_W_LOG ORDER BY TS_LAST_MODIFIED;
PROMPT .............................

BEGIN
  MULTI_DELETE;
END;
/

PROMPT Finished Run step  
EXIT;


MULTI_DELETE.sql
CREATE OR REPLACE PROCEDURE MULTI_DELETE IS

    v_effected_rows NUMBER;
    v_delete_rows NUMBER;
    v_row_counter NUMBER;
    v_table_name VARCHAR2(30);
    v_sql_str VARCHAR2(1000);
    v_module_name VARCHAR2(30);
    v_msg_text VARCHAR2(1000);

  BEGIN
    v_table_name :='SOURCE_DATA_SUBSCRIBER';
    v_effected_rows := 1;
    v_row_counter := 0;
    v_module_name := 'MULTI DELETE';

    v_sql_str := 'DELETE FROM SOURCE_DATA_SUBSCRIBER WHERE current_network_id NOT IN ( SELECT network_id FROM SGA_LOC_GRP_OUTBACK_NETWORKS ) AND msisdn IN( SELECT msisdn FROM MSISDN_PROFILE_NOT_PRE) AND ROWNUM < 100001';
    v_msg_text  := 'Running SQL: '||v_sql_str;

    INSERT INTO SGA_W_LOG (  procedure_name,  data,  ts_last_modified)
    VALUES(v_module_name,v_msg_text, SYSDATE);
    COMMIT;

    v_msg_text  := 'Starting at: '||TO_CHAR(SYSDATE,'YYYYMMDD hh24:mi:ss');
    INSERT INTO SGA_W_LOG (  procedure_name,  data,  ts_last_modified)
    VALUES(v_module_name,v_msg_text, SYSDATE);
    COMMIT;


    WHILE v_effected_rows > 0 LOOP

      DELETE FROM SOURCE_DATA_SUBSCRIBER
       WHERE current_network_id NOT IN ( SELECT network_id FROM SGA_LOC_GRP_OUTBACK_NETWORKS )
         AND msisdn IN( SELECT msisdn FROM MSISDN_PROFILE_NOT_PRE)
         AND ROWNUM < 100001;


      v_effected_rows := SQL%ROWCOUNT;
      v_row_counter := v_row_counter + v_effected_rows;
      COMMIT;
      
      v_msg_text := v_row_counter||' rows deleted from table '||v_table_name;      
      INSERT INTO SGA_W_LOG (  procedure_name,  data,  ts_last_modified)
      VALUES(v_module_name,v_msg_text, SYSDATE);
      COMMIT;
      
    END LOOP;
    
    COMMIT;
    
    v_msg_text := 'MANUAL_DELETE FROM '||v_table_name||' Finished Successfully';
    INSERT INTO SGA_W_LOG (  procedure_name,  data,  ts_last_modified)
    VALUES(v_module_name,v_msg_text, SYSDATE);
    COMMIT;


  EXCEPTION

    WHEN OTHERS THEN
      v_msg_text := 'Error in procedure '||v_module_name||'. Error Details: '|| SUBSTR(SQLERRM, 1, 900);
      INSERT INTO SGA_W_LOG (  procedure_name,  data,  ts_last_modified)
      VALUES(v_module_name,v_msg_text, SYSDATE);
      COMMIT;
  END MULTI_DELETE;
/


Step 3.
post_run_steps.shsqlplus /nolog @post_run_steps.sql
post_run_steps.bat
sqlplus /nolog @post_run_steps.sql

post_run_steps.sql
@../set_vipuser.sqlSET SERVEROUT ON
SET HEADING OFF
SET LINESIZE 400
SET PAGESIZE 0
SET FEEDBACK OFF
PROMPT conn &&vipuser/&&vippass@&&connectStr
conn &&vipuser/&&vippass@&&connectStr

EXEC DBMS_OUTPUT.ENABLE(100000);
PROMPT DROP TABLE 
SOURCE_DATA_SUBSCRIBER_BAK
DROP TABLE 
SOURCE_DATA_SUBSCRIBER_BAK;
PROMPT DROP TABLE SGA_LOC_GRP_OUTBACK_NETWORKS
DROP TABLE SGA_LOC_GRP_OUTBACK_NETWORKS;
PROMPT DROP TABLE MSISDN_PROFILE_NOT_PRE
DROP TABLE MSISDN_PROFILE_NOT_PRE;
PROMPT Finished Post Run step
EXIT;

Sunday, April 22, 2018

Golden Gate Lag at Chkpt is high. What does it mean?

==========================
General
==========================
The issue: One of the Oracle GG (Golden Gate) EXTRACT  processes was in ABENDED status. 
After fixing the underlying problem , the value for Lag at Chkpt is high.
What does it mean?


>%cd /software/ogg/1212
/software/ogg/1212/>% ./ggsci
info all

GGSCI (esp-tel-1-dbu-2) 26> info all

Program     Status      Group       Lag at Chkpt  Time Since Chkpt

MANAGER     RUNNING  
EXTRACT     RUNNING     EXT_I_01    00:00:06      00:00:06    
EXTRACT     RUNNING     EXT_I_02    00:00:05      00:00:02    
EXTRACT     RUNNING     EXT_I_04    00:00:06      00:00:04    
EXTRACT     RUNNING     EXT_I_05    00:00:06      00:00:02    
EXTRACT     RUNNING     EXT_I_06    00:00:07      00:00:10
EXTRACT     RUNNING     EXT_I_07    83:06:52      00:00:09
EXTRACT     RUNNING     EXT_S_02    00:00:05      00:00:07    
EXTRACT     RUNNING     EXT_S_04    00:00:05      00:00:02    
EXTRACT     RUNNING     EXT_S_05    00:00:05      00:00:03    
EXTRACT     RUNNING     EXT_S_06    00:00:05      00:00:03    
EXTRACT     RUNNING     EXT_S_07    96:46:27      00:00:01    


==========================
Explanation
==========================
Time Since Checkpoint and Lag at Checkpoint

Time Since Checkpoint
Each process has it's own checkpoint file. 
Whenever a process see's a commit in the transaction, a checkpoint is made in the checkpoint file. 

You can see the increase in the Time Since Checkpoint, when extract was stopped or when extract or replicat is processing a long running transaction

If you stop a Extract process at 10:00AM and restart it at 10:30 AM, upon restarting, the Extract process reads it's checkpoint file to know the last successful processed transaction. And it starts processing all the transactions after that checkpoint.

You can see the increase in the Time Since Checkpoint, when extract or replicat is processing a long running transaction. 
By using the SEND EXTRACT STATUS or SEND REPLICAT STATUS command you can know the exact status of the processes. 
The INFO command always fetches the information from the checkpoint file.
The SEND command communicates directly with the process and gets the current/latest status of it.


Lag at Checkpoint
For Extract, lag is the difference, in seconds, between the time that a record was processed by Extract (based on the system clock) and the timestamp of that record in the data source.

For Replicat, lag is the difference, in seconds, between the time that the last record was processed by Replicat (based on the system clock) and the timestamp of the record in the trail.

 ==========================
Resolution
==========================
Nothing to do, just wait.
The Extract was in Abended state for several hours, and it got a backlog of transactions to reprocess.
After ~10 minutes, the Lag at Checkpoint was reduced from ~90 minutes to ~70 minutes


GGSCI (my_server) 757> SEND REPLICAT REP_I_01 STATUS

Sending STATUS request to REPLICAT REP_I_01 ...
  Current status: Processing data
  Sequence #: 4,614
  RBA: 428,201,835
  275,562 records in current transaction.


GGSCI (my_server) 758> SEND REPLICAT REP_I_01 STATUS

Sending STATUS request to REPLICAT REP_I_01 ...
  Current status: Processing data
  Sequence #: 4,614
  RBA: 429,066,155
  277,022 records in current transaction.


The Transaction is not yet completed.

GGSCI (esp-tel-1-dbu-2) 26> info all

Program     Status      Group       Lag at Chkpt  Time Since Chkpt

MANAGER     RUNNING                    
EXTRACT     RUNNING     EXT_I_01    00:00:06      00:00:08    
EXTRACT     RUNNING     EXT_I_02    00:00:05      00:00:03    
EXTRACT     RUNNING     EXT_I_04    00:00:06      00:00:08    
EXTRACT     RUNNING     EXT_I_05    00:00:06      00:00:08    
EXTRACT     RUNNING     EXT_I_06    00:00:07      00:00:07    

EXTRACT     RUNNING     EXT_I_07    64:58:26      00:00:01 
EXTRACT     RUNNING     EXT_S_01    00:00:05      00:00:03    
EXTRACT     RUNNING     EXT_S_02    00:00:05      00:00:03    
EXTRACT     RUNNING     EXT_S_04    00:00:06      00:00:08    
EXTRACT     RUNNING     EXT_S_05    00:00:05      00:00:02    
EXTRACT     RUNNING     EXT_S_06    00:00:06      00:00:08    
EXTRACT     RUNNING     EXT_S_07    78:51:46      00:00:01    


After additional ~10 minutes, the Lag at Checkpoint was reduced further.
EXTRACT     RUNNING     EXT_I_01    00:00:06      00:00:07    
EXTRACT     RUNNING     EXT_I_02    00:00:06      00:00:07    
EXTRACT     RUNNING     EXT_I_04    00:00:06      00:00:07    
EXTRACT     RUNNING     EXT_I_05    00:00:06      00:00:07    
EXTRACT     RUNNING     EXT_I_06    00:00:05      00:00:03    
EXTRACT     RUNNING     EXT_I_07    54:01:19      00:00:08   
EXTRACT     RUNNING     EXT_S_01    00:00:06      00:00:07    
EXTRACT     RUNNING     EXT_S_02    00:00:06      00:00:06    
EXTRACT     RUNNING     EXT_S_04    00:00:06      00:00:07    
EXTRACT     RUNNING     EXT_S_05    00:00:06      00:00:07    
EXTRACT     RUNNING     EXT_S_06    00:00:06      00:00:07    
EXTRACT     RUNNING     EXT_S_07    66:03:33      00:00:07