Monitor I/O performance on Solaris with DTrace script and Oracle Database 12c with pluggable database

July 8, 2013 by · Leave a Comment 

Well, like all of you out there fellow Oracle DBAs, I am super excited about playing around with newest release of Oracle Database 12c. Since I am home alone in the next few weeks, besides painting the flat and similar house activities, guess what else I will be doing? :) Of course, try to throttle as much CPU and IO possible from my home server running virtual machines.

What to do you need?

  • Dtrace iopattern script written by the genius Brendan Gregg which comes along with DTraceToolkit version 0.99.
  • Oracle Database
  • SunOS 5.10 to run the script

Since 12c release come out recently, I have decided to create one pluggable database, create one external table and fetch the results from iopattern script. Before running the iopattern script, we will modify it in such a way that it will not print the column header names on every 20 lines and we will also comma separate the output and enclose it with quotes. This way we will easily fetch the output using an external table.

Open the script and go to the line# 156 and make sure LINES=1.

/*
  * Program start
  */
 dtrace:::BEGIN
 {
        /* starting values */
	diskcnt = 0;
	diskmin = 0;
	diskmax = 0;
	diskran = 0;
	diskr = 0;
	diskw = 0;
        counts = COUNTER;
        secs = INTERVAL;
	LINES = 1;
	line = 0;
	last_event[""] = 0;
 }

Then immediately bellow at line# 165 you need to make the second change to line=0.

/*
* Print header
*/
profile:::tick-1sec
/line = 0 /
{
/* print optional headers */
OPT_time ? printf("%-20s ", "TIME") : 1;
OPT_device ? printf("%-9s ", "DEVICE") : 1;
OPT_mount ? printf("%-12s ", "MOUNT") : 1;
OPT_file ? printf("%-12s ", "FILE") : 1;

/* print header */
printf("%4s %4s %6s %6s %6s %6s %6s %6s\n",
"%RAN", "%SEQ", "COUNT", "MIN", "MAX", "AVG", "KR", "KW");

line = LINES;
}

Third and last change is on lines#246,252,253 and 254 by adding double quote and comma to optional fields (OPT_time) and in the print data section.

	/* print optional fields */
	OPT_time   ? printf("\"%-20Y\",", walltimestamp) : 1;
	OPT_device ? printf("%-9s ", DEVICE) : 1;
	OPT_mount  ? printf("%-12s ", MOUNT) : 1;
	OPT_file   ? printf("%-12s ", FILENAME) : 1;

	/* print data */
	printf("\"%d\",\"%d\",\"%d\",\"%d\",\"%d\",\"%d\",\"%d\",\"%d\"\n",
            diskran, diskseq, diskcnt, diskmin, diskmax, diskavg,
            diskr, diskw);

Run the modified iopattern script with -v option to add the timestamp output and save the output to a file.

nohup ./iopattern -v 10 43200 > iopattern_hostname.dat &

If you have done the changes above, than after a few minutes the iopattern_hostname.dat should be populated with I/O performance information from your hostname.

"2013 Jul  5 15:22:10","53","47","5004","512","524288","326212","1535696","58415"
"2013 Jul  5 15:22:20","64","36","8585","512","524288","217093","1670752","149314"
"2013 Jul  5 15:22:30","59","41","5557","512","524288","241380","1188360","121555"
"2013 Jul  5 15:22:40","64","36","10825","512","524288","186383","1647872","322440"
"2013 Jul  5 15:22:50","66","34","10282","512","524288","190390","1666832","244877"
"2013 Jul  5 15:23:00","71","29","11472","512","524288","170426","1638032","271272"

Next we will create/clone a new pluggable database from an existing PDB.


column name format a10
select DBID, name, CDB, CON_ID, CON_DBID
from gv$database;

      DBID NAME       CDB     CON_ID   CON_DBID
---------- ---------- --- ---------- ----------
1274083969 DB12C      YES          0 1274083969
1274083969 DB12C      YES          0 1274083969

-- Check the existing PDBs
SQL> select inst_id, name, con_id
from gv$active_services
where con_id > 2 --Exclude ROOT and SEED
order by 2,1;

Ok, we do have an existing PDB called pdb12c and we will clone this one into a new pluggable database called pdbmon.

   INST_ID NAME           CON_ID
---------- ---------- ----------
         1 pdb12c              3
         2 pdb12c              3

-- Datafiles for existing PDB
column name format a80
select name, con_id, plugged_in
from v$datafile
where con_id > 2
order by 2;

NAME                                                                                 CON_ID PLUGGED_IN
-------------------------------------------------------------------------------- ---------- ----------
+DATA/DB12C/E0D4B3F29C873F47E0436538A8C09AF4/DATAFILE/system.278.820060571                3          0
+DATA/DB12C/E0D4B3F29C873F47E0436538A8C09AF4/DATAFILE/users.281.820060717                 3          0
+DATA/DB12C/E0D4B3F29C873F47E0436538A8C09AF4/DATAFILE/sysaux.279.820060571                3          0

Before we clone the existing PDB, let's check the state of the database

column name format a10
select name, inst_id, open_mode, con_id
from gv$pdbs
order by 1,2,4;

NAME          INST_ID OPEN_MODE      CON_ID
---------- ---------- ---------- ----------
PDB$SEED            1 READ ONLY           2
PDB$SEED            2 READ ONLY           2
PDB12C              1 MOUNTED             3
PDB12C              2 MOUNTED             3

Why CON_ID column is important? Well as per Oracle documentation

  • 0 – The data pertains to the entire CDB
  • 1 – The data pertains to the root
  • 2 – The data pertains to the seed
  • 3 – 254 – The data pertains to a PDB. Each PDB has its own container ID.

which means that each new pluggable database will have CON_ID > 2 and in my case the cloned PDB will have CON_ID=4 since I already have existing PDB with CON_ID=3. Now let’s clone existing PDB12C into PDBMON.

SQL> CREATE PLUGGABLE DATABASE pdbmon FROM PDB12C
STORAGE (MAXSIZE 1G MAX_SHARED_TEMP_SIZE 100M);

ERROR at line 1:
ORA-65040: operation not allowed from within a pluggable database

Cause: An operation was attempted that can only be performed in the root container.
Action: Switch to the root container to perform the operation.

Ok, we need to switch to the root container and than clone the existing PDB.

SQL> alter session set container=CDB$ROOT;

Session altered.

SQL> CREATE PLUGGABLE DATABASE pdbmon FROM PDB12C
STORAGE (MAXSIZE 1G MAX_SHARED_TEMP_SIZE 100M);   2

Pluggable database created.

Let’s check if the datafiles are created as well as metadata about PDBMON.

SQL> select inst_id, name, con_id
from gv$active_services
where con_id > 2 --Exclude ROOT and SEED
order by 2,1;

   INST_ID NAME           CON_ID
---------- ---------- ----------
         1 pdb12c              3
         2 pdb12c              3
         1 pdbmon              4
         2 pdbmon              4

SQL> column name format a80
select name, con_id, plugged_in
from v$datafile
where con_id > 2
order by 2;

NAME                                                                                 CON_ID PLUGGED_IN
-------------------------------------------------------------------------------- ---------- ----------
+DATA/DB12C/E0D4B3F29C873F47E0436538A8C09AF4/DATAFILE/system.278.820060571                3          0
+DATA/DB12C/E0D4B3F29C873F47E0436538A8C09AF4/DATAFILE/sysaux.279.820060571                3          0
+DATA/DB12C/E0D4B3F29C873F47E0436538A8C09AF4/DATAFILE/users.281.820060717                 3          0
+DATA/DB12C/E0DFB405AB58276FE0436638A8C0096D/DATAFILE/system.286.820109577                4          0
+DATA/DB12C/E0DFB405AB58276FE0436638A8C0096D/DATAFILE/sysaux.284.820109577                4          0
+DATA/DB12C/E0DFB405AB58276FE0436638A8C0096D/DATAFILE/users.285.820109577                 4          0

Create one user and check the state of newly cloned PDB.

alter session set container=CDB$ROOT;

column name format a10
select name, inst_id, open_mode, con_id
from gv$pdbs
order by 1,2,4;

NAME          INST_ID OPEN_MODE      CON_ID
---------- ---------- ---------- ----------
PDB$SEED            1 READ ONLY           2
PDB$SEED            2 READ ONLY           2
PDB12C              1 MOUNTED             3
PDB12C              2 MOUNTED             3
PDBMON              1 MOUNTED             4
PDBMON              2 MOUNTED             4

-- Switch to the root container
alter session set container=CDB$ROOT;

-- Create the user "C##MON" and grant privileges
create user c##mon identified by oracle;
grant create session to C##MON container=ALL;
grant dba to C##MON container=ALL;

-- Open the PDBMON database. Note: In my case I am using RAC DB, so I have to open the DB on both nodes.
alter session set container=PDBMON;

NAME          INST_ID OPEN_MODE      CON_ID
---------- ---------- ---------- ----------
PDBMON              1 MOUNTED             4
PDBMON              2 MOUNTED             4

-- From both nodes
SQL> alter database open;

Database altered.

NAME          INST_ID OPEN_MODE      CON_ID
---------- ---------- ---------- ----------
PDBMON              1 READ WRITE          4
PDBMON              2 READ WRITE          4

Next edit your tnsnames.ora files and add entry for PDMON database.

vi $ORACLE_HOME/network/admin/tnsnames.ora

PDBMON =
  (DESCRIPTION =
    (ADDRESS = (PROTOCOL = TCP)(HOST = ol6-121-scan)(PORT = 1521))
    (CONNECT_DATA =
      (SERVER = DEDICATED)
      (SERVICE_NAME = PDBMON)
    )
  )

Connect to the PDMON and create the external table in order to fetch the output from iopattern script.

$ sqlplus c##mon/oracle@pdbmon

SQL*Plus: Release 12.1.0.1.0 Production on Sun Jul 7 00:36:52 2013

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

Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application Testing options

-- Create the directory which holds the output on iopattern. 
-- In my case I use ACFS so the file is available from both RAC nodes.
SQL> create directory dir_monitoring
as
'/u01/app/oracle/nakinov';

Directory created.

-- Create the external table
SQL> create table iopattern_hostname
    (
       sample_time          date,
      pct_random        number(3),
      pct_sequential    number(3),
      io_count          number(38),
       io_min           number(38),
       io_max           number(38),
       io_avg           number(38),
       io_kr            number(38),
       io_kw            number(38)
    )
    organization external
    ( default directory dir_monitoring
      access parameters
      ( records delimited BY newline fields terminated by "," optionally enclosed by '"'
        LDRTRIM
        MISSING FIELD VALUES ARE NULL
        REJECT ROWS WITH ALL NULL FIELDS
        (
         sample_time        CHAR(22) date_format DATE mask "YYYY MON  DD HH24:MI:SS",    
         pct_random         CHAR(3),
         pct_sequential     CHAR(3),
         io_count           CHAR(255),
         io_min             CHAR(255),
         io_max             CHAR(255),
         io_avg             CHAR(255),
         io_kr              CHAR(255),
         io_kw              CHAR(255)
        )
      )
      location ('iopattern_hostname.dat')
  );


Table created.

-- Check if all is working
SQL> set autotrace on
SQL> set lines 300
SQL> column st format a21
column io_count format 999999
select to_char(sample_time,'dd.mm.yyyy hh24:mi:ss') st, io_count
from iopattern_hostname
order by sample_time
FETCH FIRST 10 ROWS ONLY;

ST                    IO_COUNT
--------------------- --------
05.07.2013 15:22:10       5004
05.07.2013 15:22:20       8585
05.07.2013 15:22:30       5557
05.07.2013 15:22:40      10825
05.07.2013 15:22:50      10282
05.07.2013 15:23:00      11472
05.07.2013 15:23:10      12389
05.07.2013 15:23:20      17184
05.07.2013 15:23:30      15731
05.07.2013 15:23:40       7404

10 rows selected.


Execution Plan
----------------------------------------------------------
Plan hash value: 3575133555

---------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                    |  8168 |   366K|    29   (0)| 00:00:01 |
|*  1 |  VIEW                        |                    |  8168 |   366K|    29   (0)| 00:00:01 |
|*  2 |   WINDOW SORT PUSHED RANK    |                    |  8168 |   175K|    29   (0)| 00:00:01 |
|   3 |    EXTERNAL TABLE ACCESS FULL| IOPATTERN_HOSTNAME |  8168 |   175K|    29   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("from$_subquery$_002"."rowlimit_$$_rownumber"<=10)
   2 - filter(ROW_NUMBER() OVER ( ORDER BY "SAMPLE_TIME")<=10)


Statistics
----------------------------------------------------------
         20  recursive calls
          0  db block gets
         42  consistent gets
          0  physical reads
          0  redo size
        940  bytes sent via SQL*Net to client
        543  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
         10  rows processed

Since “FETCH FIRST 10 ROWS ONLY” is also a new 12c feature for top-n queries, I wonder if analytical function can be avoided (2 – filter(ROW_NUMBER() OVER ( ORDER BY “SAMPLE_TIME”)<=10)).

Download both original and modified iopattern script as well as sample output data.

More about managing multitenant environments on the official Oracle documentation about 12c..

Oracle Golden Gate Logdump parser

October 23, 2012 by · 2 Comments 

Logdump is a utility from OGG used to troubleshoot OGG. The purpose of this post is not to explain how to use Logdump, but to rather use Logdump over some trail files and extract information about the transactions in the trail file.

The bash script bellow simply calls Logdump, opens the trail file and issues “count” command. As a result, the output show basic information about the trail file such as number of rows inside, number of delete/insert operations, average bytes per transactions etc.

./logdump
Logdump 1 >open /u05/nakinov/gg_trails/test/aa000100
Logdump 2 >count
Logdump 3 >LogTrail /u05/nakinov/gg_trails/test/aa000100 has 408545 records
Total Data Bytes          55703897
  Avg Bytes/Record             136
Delete                        2146
Insert                      209403
FieldComp                   196995
Others                           1
Before Images                 2146
After Images                406398

Average of 74443 Transactions
    Bytes/Trans .....        263
    Records/Trans ...          5
    Files/Trans .....          1

Call the bash script like this:

nohup time ./logdump_parser.sh /u05/nakinov/gg_trails/aa /u01/nakinov/04.monitoring/logdump_parsed.log &

where first argument (/u05/nakinov/gg_trails/aa) is the location with the prefix of OGG trail files to process, while the second argument (/u01/nakinov/04.monitoring/logdump_parsed.log) is the file name which will contain the parsed output.

#!/usr/bin/bash
#====================================================================================
#title           : ./logdump_parser.sh
#description     : This script will parse the output from ./logdump utility
#author          : Lazar Nakinov, http://database.com.mk
#date            : 23.12.2012
#version         : 0.1
#usage           : ./logdump_parser.sh </location/of/trail_files/prefix> </output/file.log>
#notes           : Tested on OGGCORE_11.1.1_PLATFORMS_110421.2040 
#				   SunOS billdb1 5.10 Generic_144488-17 sun4v sparc SUNW,T5440
#				   	
#====================================================================================

# Setup environment variables
NLS_LANG=AMERICAN_AMERICA.WE8ISO8859P15; export NLS_LANG
ORACLE_HOSTNAME=billdb1.wataniyaalgerie.com ; export ORACLE_HOSTNAME
ORACLE_UNQNAME=RAC; export ORACLE_UNQNAME
ORACLE_BASE=/u01/app/oracle; export ORACLE_BASE
ORACLE_HOME=$ORACLE_BASE/product/11.2.0/dbhome_1; export ORACLE_HOME
ORACLE_SID=BSCSP1; export ORACLE_SID
ORACLE_TERM=xterm; export ORACLE_TERM
TNS_ADMIN=$ORACLE_HOME/network/admin; export TNS_ADMIN;
export GGHOME=/u01/ggs
LD_LIBRARY_PATH=$ORACLE_HOME/lib:$GGHOME; export LD_LIBRARY_PATH
PATH=$PATH:/usr/local/bin:/usr/ccs/bin:$GGHOME:/usr/sfw/bin:$ORACLE_HOME/bin:/u01/11.2.0/grid/;
BASE_PATH=/usr/bin:$PATH; export BASE_PATH
PATH=$ORACLE_HOME/bin:$BASE_PATH:/u01/11.2.0/grid/; export PATH

print_usage () {
    echo " "
    echo "Oracle Golden Gate replication throughput"
    echo " "
    echo "Error in $0 - Invalid Argument Count"
    echo " "
    echo "Example: $0 /u05/nakinov/gg_trails/aa /u01/nakinov/04.monitoring/logdump_parsed.log"
    echo " "
    exit
}

if [ $# -ne 2 ]
then
    print_usage
    exit
fi

TMPLOGTRAIL=logdump_output.tmp
NOW=$(date +"%D %T")
ARG1=`echo -n $1*`
LOGFINAL=$2
#echo $ARG1

delete_old_logs () {

if [ -f $TMPLOGTRAIL ]
then
		rm $TMPLOGTRAIL
fi

}

if [ -f $LOGFINAL ]
then
		rm $LOGFINAL
fi

delete_old_logs

echo " " >> $LOGFINAL
echo "##########################################################################################################################################################" >> $LOGFINAL
echo "Date: $NOW" >> $LOGFINAL
echo "LOGDUMP Parser" >> $LOGFINAL
echo "##########################################################################################################################################################" >> $LOGFINAL
echo "----------------------------------------------------------------------------------------------------------------------------------------------------------" >> $LOGFINAL
echo "LOG_OPENED|TF_OPENED|TF_NUMRECORDS|TF_TOTAL_DATA_BYTES|TF_AVG_DATA_BYTES|TF_DELETE|TF_INSERT|TF_FIELDCOMP|TF_GGSPKUPD|TF_OTHERS|TF_BEFORE_IMG|TF_AFTER_IMG|TF_AVG_OF|TF_BYTES_TRANS|TF_REC_TRANS|TF_FILES_TRANS|LOG_CLOSED"  >> $LOGFINAL
echo "----------------------------------------------------------------------------------------------------------------------------------------------------------" >> $LOGFINAL


for i in $( ls -ltr $ARG1 | awk '{print $9}' )
do

delete_old_logs

echo $i
$GGHOME/logdump <<EOF
log to $TMPLOGTRAIL
open $i
count 
exit
EOF

# Get the log date opened	
LOG_OPENED=`cat $TMPLOGTRAIL | egrep -i "opened" | sed 's/  */ /g' | cut -d" " -f7`
# Get the log trail opened
TF_OPENED=`cat $TMPLOGTRAIL | egrep -i "LogTrail is" | cut -d" " -f4`
# Get the number of records in the trail file
TF_NUMRECORDS=`cat $TMPLOGTRAIL | egrep -i "has" | cut -d" " -f4`
# Get the "Total Data Bytes"
TF_TOTAL_DATA_BYTES=`cat $TMPLOGTRAIL | egrep -i "Total Data Bytes" | sed 's/  */ /g' | cut -d" " -f4`
# Get the "Avg Bytes/Record"
TF_AVG_DATA_BYTES=`cat $TMPLOGTRAIL | egrep -i "Avg Bytes/Record" | sed 's/  */ /g' | cut -d" " -f4`
# Get the "Delete"
TF_DELETE=`cat $TMPLOGTRAIL | egrep -i "Delete" | sed 's/  */ /g' | cut -d" " -f2`
# Get the "Insert"
TF_INSERT=`cat $TMPLOGTRAIL | egrep -i "Insert" | sed 's/  */ /g' | cut -d" " -f2` 	
# Get the "FieldComp"
TF_FIELDCOMP=`cat $TMPLOGTRAIL | egrep -i "FieldComp" | sed 's/  */ /g' | cut -d" " -f2` 	
# Get the "GGSPKUpdate"
TF_GGSPKUPD=`cat $TMPLOGTRAIL | egrep -i "GGSPKUpdate" | sed 's/  */ /g' | cut -d" " -f2`
# Get the "Others"
TF_OTHERS=`cat $TMPLOGTRAIL | egrep -i "Others" | sed 's/  */ /g' | cut -d" " -f2`
# Get the "Before Images"
TF_BEFORE_IMG=`cat $TMPLOGTRAIL | egrep -i "Before Images" | sed 's/  */ /g' | cut -d" " -f3` 	 
# Get the "After Images"
TF_AFTER_IMG=`cat $TMPLOGTRAIL | egrep -i "After Images" | sed 's/  */ /g' | cut -d" " -f3`
# Get the "Average of"
TF_AVG_OF=`cat $TMPLOGTRAIL | egrep -i "Average of" | sed 's/  */ /g' | cut -d" " -f3`
# Get the "Bytes/Trans"
TF_BYTES_TRANS=`cat $TMPLOGTRAIL | egrep -i "Bytes/Trans" | sed 's/  */ /g' | cut -d" " -f4`
# Get the "Records/Trans"
TF_REC_TRANS=`cat $TMPLOGTRAIL | egrep -i "Records/Trans" | sed 's/  */ /g' | cut -d" " -f4`
# Get the "Files/Trans"
TF_FILES_TRANS=`cat $TMPLOGTRAIL | egrep -i "Files/Trans" | sed 's/  */ /g' | cut -d" " -f4` 
#Get the log date closed
LOG_CLOSED=`cat $TMPLOGTRAIL | egrep -i "closed" | sed 's/  */ /g' | cut -d" " -f7 | tail -1`

LINE=`echo -n "$LOG_OPENED"; echo -n "|$TF_OPENED|"; echo -n "$TF_NUMRECORDS|"; echo -n "$TF_TOTAL_DATA_BYTES|"; echo -n "$TF_AVG_DATA_BYTES|"; echo -n "$TF_DELETE|"; echo -n "$TF_INSERT|"; echo -n "$TF_FIELDCOMP|"; echo -n "$TF_GGSPKUPD|"; echo -n "$TF_OTHERS|"; echo -n "$TF_BEFORE_IMG|"; echo -n "$TF_AFTER_IMG|"; echo -n "$TF_AVG_OF|"; echo -n "$TF_BYTES_TRANS|"; echo -n "$TF_REC_TRANS|"; echo -n "$TF_FILES_TRANS|"; echo -n "$LOG_CLOSED|"; echo`
echo $LINE >> $LOGFINAL
	
done

In my test case it took 1h and 10m to parse 733 files each 100MB. That is not so bad since you probably going to parse the files only once. Parsed output looks like:

##########################################################################################################################################################
Date: 10/23/12 14:09:40
LOGDUMP Parser
##########################################################################################################################################################
----------------------------------------------------------------------------------------------------------------------------------------------------------
LOG_OPENED|TF_OPENED|TF_NUMRECORDS|TF_TOTAL_DATA_BYTES|TF_AVG_DATA_BYTES|TF_DELETE|TF_INSERT|TF_FIELDCOMP|TF_GGSPKUPD|TF_OTHERS|TF_BEFORE_IMG|TF_AFTER_IMG|
TF_AVG_OF|TF_BYTES_TRANS|TF_REC_TRANS|TF_FILES_TRANS|LOG_CLOSED
----------------------------------------------------------------------------------------------------------------------------------------------------------
14:09:41.092.323|/u05/nakinov/gg_trails/aa000002|564668|41681228|73|79|544095|20471|21|1|79|564588|15789|1716|35|1|14:09:47.733.210|
14:09:48.127.917|/u05/nakinov/gg_trails/aa000003|522733|46571038|89|6|497360|25364|2|1|6|522726|7033|3567|74|1|14:09:54.403.133|
14:09:54.818.453|/u05/nakinov/gg_trails/aa000004|323874|65527053|202|26|244510|79331|6|1|26|323847|53917|288|6|1|14:09:59.147.767|
14:09:59.561.782|/u05/nakinov/gg_trails/aa000005|332036|64861161|195|40|243377|88610|8|1|40|331995|41312|385|8|1|14:10:04.104.768|
14:10:04.514.325|/u05/nakinov/gg_trails/aa000006|301767|68265877|226|33|222079|79635|19|1|33|301733|37798|383|7|1|14:10:08.660.982|

Now let us create the external table and fetch the parsed file into Oracle.

-- Create the Oracle directory that points to the location of the parsed file
create directory GG_LOG_DIR 
as '/u01/nakinov/04.monitoring'
/ 

DROP TABLE gg_log_dump;

-- Create the external table using SQL*Loader API
create table gg_log_dump 
( 
          LOG_OPENED VARCHAR2(50),
          TF_OPENED VARCHAR2(500),
          TF_NUMRECORDS NUMBER(20),
          TF_TOTAL_DATA_BYTES NUMBER(20),
          TF_AVG_DATA_BYTES NUMBER(20),
          TF_DELETE NUMBER(20),
          TF_INSERT NUMBER(20),
          TF_FIELDCOMP NUMBER(20),
          TF_GGSPKUPD NUMBER(20),
          TF_OTHERS NUMBER(20),
          TF_BEFORE_IMG NUMBER(20),
          TF_AFTER_IMG NUMBER(20),
          TF_AVG_OF NUMBER(20),
          TF_BYTES_TRANS NUMBER(20),
          TF_REC_TRANS NUMBER(20),
          TF_FILES_TRANS NUMBER(20),
          LOG_CLOSED VARCHAR2(50)
                      
) 
organization external ( 
   type oracle_loader 
   default directory GG_LOG_DIR 
   access parameters 
   ( 
      records delimited by newline   
      nologfile 
      nobadfile      
      nodiscardfile 
      fields terminated by "|" lrtrim 
      missing field values are NULL
      ( 
          LOG_OPENED,
          TF_OPENED,
          TF_NUMRECORDS,
          TF_TOTAL_DATA_BYTES,
          TF_AVG_DATA_BYTES,
          TF_DELETE,
          TF_INSERT,
          TF_FIELDCOMP,
          TF_GGSPKUPD,
          TF_OTHERS,
          TF_BEFORE_IMG,
          TF_AFTER_IMG,
          TF_AVG_OF,
          TF_BYTES_TRANS,
          TF_REC_TRANS,
          TF_FILES_TRANS,
          LOG_CLOSED
      ) 
   ) 
   location ('logdump_parsed.log') 
) 
reject limit unlimited 
/ 

-- Test it
SELECT *
FROM gg_log_dump
WHERE tf_opened IS NOT NULL
ORDER BY 2;

-- Output
LOG_OPENED	TF_OPENED	TF_NUMRECORDS	TF_TOTAL_DATA_BYTES	TF_AVG_DATA_BYTES	TF_DELETE	TF_INSERT	TF_FIELDCOMP	TF_GGSPKUPD	TF_OTHERS	TF_BEFORE_IMG	TF_AFTER_IMG	TF_AVG_OF	TF_BYTES_TRANS	TF_REC_TRANS	TF_FILES_TRANS	LOG_CLOSED
14:09:40.652.673	/u05/nakinov/gg_trails/aa000000	2	954	477		1			1		1	2	48	1	1	14:09:40.661.047
14:09:40.249.245	/u05/nakinov/gg_trails/aa000001	2	862	431					1		1	2	48	1	1	14:09:40.257.976
14:09:41.092.323	/u05/nakinov/gg_trails/aa000002	564668	41681228	73	79	544095	20471	21	1	79	564588	15789	1716	35	1	14:09:47.733.210
14:09:48.127.917	/u05/nakinov/gg_trails/aa000003	522733	46571038	89	6	497360	25364	2	1	6	522726	7033	3567	74	1	14:09:54.403.133
14:09:54.818.453	/u05/nakinov/gg_trails/aa000004	323874	65527053	202	26	244510	79331	6	1	26	323847	53917	288	6	1	14:09:59.147.767
14:09:59.561.782	/u05/nakinov/gg_trails/aa000005	332036	64861161	195	40	243377	88610	8	1	40	331995	41312	385	8	1	14:10:04.104.768
14:10:04.514.325	/u05/nakinov/gg_trails/aa000006	301767	68265877	226	33	222079	79635	19	1	33	301733	37798	383	7	1	14:10:08.660.982
14:10:09.075.735	/u05/nakinov/gg_trails/aa000007	378745	58983931	155	2637	185895	190210	2	1	2637	376107	77034	235	4	1	14:10:14.058.163
14:10:14.487.763	/u05/nakinov/gg_trails/aa000008	369429	60029187	162	3079	190194	176149	6	1	3079	366349	78101	227	4	1	14:10:19.262.802
14:10:19.664.548	/u05/nakinov/gg_trails/aa000009	418743	55262000	131	3724	171066	243950	2	1	3724	415018	62129	323	6	1	14:10:25.179.657

Extract rate/delta from an extract or replicat Oracle Golden Gate process

October 22, 2012 by · Leave a Comment 

For the past few days I really got hooked on OGG. Since there are nice reporting commands and I am lazy to calculate them manually, in the past few days I wrote several scripts. This is the latest one. I am using rather intensive reporting on every 1 min intervals since the configuration I am testing on is not so critical, but for a production extract|replicat perhaps would be smart to report the rate/delta on a 5-10 min intervals.

Use the REPORTCOUNT parameter to have the extract or replicat process automatically add a count of the records OGG has processed since its startup.

-- My replicat parameter has the following reporting parameters
STATOPTIONS, RESETREPORTSTATS
REPORTCOUNT EVERY 1 MINUTES, rate
REPORT AT 01:00
REPORT AT 02:00
REPORT AT 03:00
REPORT AT 04:00
REPORT AT 05:00
REPORT AT 06:00
REPORT AT 07:00
REPORT AT 08:00
REPORT AT 09:00
REPORT AT 10:00
REPORT AT 11:00
REPORT AT 12:00
REPORT AT 13:00
REPORT AT 14:00
REPORT AT 15:00
REPORT AT 16:00
REPORT AT 17:00
REPORT AT 18:00
REPORT AT 19:00
REPORT AT 20:00
REPORT AT 21:00
REPORT AT 22:00
REPORT AT 23:00
REPORT AT 00:00
REPORTROLLOVER ON FRIDAY

OGG uses the following calculations for rate/delta:

Rate = number of records processed since startup / total time since startup
Delta = number of records since last report / time since last report

Use the shell script bellow to parse the report file for a particular extract|replicat process, which redirects the output into a file. Latter on this file is being access from an Oracle external table.

#!/usr/bin/bash
#====================================================================================
#title           : ./gg_extract_delta.sh
#description     : This script will grep output from extract|replicat process
#author          : Lazar Nakinov, http://database.com.mk
#date            : 22.12.2012
#version         : 0.1
#usage           : ./gg_extract_delta.sh </read/report_file.rpt> </write/gg_rate_delta.log> <sleep time> <interval>
#notes           : Extract/Replicat process must have reporting enabled
#				    STATOPTIONS, RESETREPORTSTATS
#					REPORTCOUNT EVERY 1 MINUTES, rate
#					Rate = # of records processed since startup / total time since startup
#					Delta = # of records since last report / time since last report
#====================================================================================

# Report to parse
ARG1=$1
# File name to write
ARG2=$2
# Sleep time in seconds
ARG3=$3
# Interval to exit
ARG4=$4

print_usage () {
    echo " "
    echo "OGG extract|replicat rate/delta report parser"
    echo " "
    echo "Error in $0 - Invalid Argument Count"
    echo "Syntax: $0 ./gg_extract_delta.sh </read/report_file.rpt> </write/parsed_report_file.log> <sleep time> <interval>"
    echo " "
    echo "Example: $0 /u01/ggs/dirrpt/RPROD01.rpt /u01/nakinov/04.monitoring/gg_rate_delta.log 60 120"
    echo " "
    exit
}

if [ $# -ne 4 ]
then
    print_usage
    exit
fi

x=1
while [ $x -le $ARG4 ]
do
  if [ -f $ARG2 ]
  then
		rm $ARG2
   fi

  cat $ARG1 | egrep -i "records processed as of" > $ARG2
  sed 's/,/ /g' $ARG2 > tmp.log ; mv tmp.log $ARG2
  sed 's/  */ /gp' $ARG2 > tmp.log ; mv tmp.log $ARG2
  x=$(( $x + 1 ))
  sleep $ARG3
done

Call the script using

nohup time ./gg_extract_delta.sh </read/report_file.rpt> </write/gg_rate_delta.log> <sleep time> <interval>

The file containing parsed output should look like this:

 20886 records processed as of 2012-10-22 09:13:16 (rate 348 delta 348)
 20886 records processed as of 2012-10-22 09:13:16 (rate 348 delta 348)
 56121 records processed as of 2012-10-22 09:14:16 (rate 467 delta 587)
 56121 records processed as of 2012-10-22 09:14:16 (rate 467 delta 587)
 106536 records processed as of 2012-10-22 09:15:16 (rate 591 delta 840)
 106536 records processed as of 2012-10-22 09:15:16 (rate 591 delta 840)
 158030 records processed as of 2012-10-22 09:16:16 (rate 658 delta 858)
 158030 records processed as of 2012-10-22 09:16:16 (rate 658 delta 858)
 207354 records processed as of 2012-10-22 09:17:16 (rate 691 delta 822)
 207354 records processed as of 2012-10-22 09:17:16 (rate 691 delta 822)
 261782 records processed as of 2012-10-22 09:18:16 (rate 727 delta 907)
 261782 records processed as of 2012-10-22 09:18:16 (rate 727 delta 907)
 316151 records processed as of 2012-10-22 09:19:16 (rate 752 delta 906)
 316151 records processed as of 2012-10-22 09:19:16 (rate 752 delta 906)
 367998 records processed as of 2012-10-22 09:20:16 (rate 766 delta 864)
 367998 records processed as of 2012-10-22 09:20:16 (rate 766 delta 864)
 424899 records processed as of 2012-10-22 09:21:16 (rate 786 delta 948)
 424899 records processed as of 2012-10-22 09:21:16 (rate 786 delta 948)
 479451 records processed as of 2012-10-22 09:22:16 (rate 799 delta 909)
 479451 records processed as of 2012-10-22 09:22:16 (rate 799 delta 909)
 539010 records processed as of 2012-10-22 09:23:16 (rate 816 delta 992)
 539010 records processed as of 2012-10-22 09:23:16 (rate 816 delta 992)
 595752 records processed as of 2012-10-22 09:24:16 (rate 827 delta 945)
 595752 records processed as of 2012-10-22 09:24:16 (rate 827 delta 945)
 --- Output truncated ---

Next create the directory and the external table:

create directory GG_LOG_DIR
as '/u01/nakinov/04.monitoring'
/

create table gg_measure_rate_delta_full
(
  mygglog varchar2(4000)
)
organization external (
  type oracle_loader
  default directory GG_LOG_DIR
  access parameters (
     records delimited by newline
     nobadfile
     nologfile
     nodiscardfile
  )
  location ('gg_rate_delta.log')
)
reject limit unlimited
/

Or if you want to do it more precise, create another external table with all the columns from the parsed file.

create table gg_measure_rate_delta
(
          txt0 VARCHAR2(50),
          rows_processed NUMBER(15),
          txt1 VARCHAR2(50),
          txt2 VARCHAR2(50),
          txt3 VARCHAR2(50),
          txt4 VARCHAR2(50),
          log_date DATE,
          txt5 VARCHAR2(50),
          txt6 VARCHAR2(50),
          txt7 VARCHAR2(50),
          txt8 VARCHAR2(50),
          txt9 VARCHAR2(50),
          txt10 VARCHAR2(50)

)
organization external (
   type oracle_loader
   default directory GG_LOG_DIR
   access parameters
   (
      records delimited by newline
      nologfile
      nobadfile
      nodiscardfile
      fields terminated by " " lrtrim
      missing field values are NULL
      (
          txt0,
          rows_processed,
          txt1,
          txt2,
          txt3,
          txt4,
          log_date char(30) date_format date mask "YYYY-MM-DD",
          txt5,
          txt6,
          txt7,
          txt8,
          txt9,
          txt10
      )
   )
   location ('gg_rate_delta.log')
)
reject limit unlimited
/

SELECT To_Date(SubStr(log_date,1,10) || ' ' || txt5, 'DD-MM-YY HH24:MI:SS') log_date
       , rows_processed
       , To_Number(trim(txt7)) rate
       , To_Number(SubStr(trim(txt9),1,Length(txt9)-1)) delta
FROM gg_measure_rate_delta ;

-- Output
LOG_DATE	ROWS_PROCESSED	RATE	DELTA
22.10.2012 09:13:16	20886	348	348
22.10.2012 09:13:16	20886	348	348
22.10.2012 09:14:16	56121	467	587
22.10.2012 09:14:16	56121	467	587
22.10.2012 09:15:16	106536	591	840
22.10.2012 09:15:16	106536	591	840
22.10.2012 09:16:16	158030	658	858
22.10.2012 09:16:16	158030	658	858
22.10.2012 09:17:16	207354	691	822
22.10.2012 09:17:16	207354	691	822

Once you have the data, you can export it in csv format and using Tableau you can generate useful charts about how fast/slow your extract|replicat process is doing.

If the delta is increasing, this means that you are processing more rows, thus your process is getting faster. Graph above is splitted into 3 parts (Delta/Rate/Rows Processed) and shows that my replicat process at the beginning (9h,10h and 11h) was having rather constant delta, then in the next 3 hours (12h, 13h and 14h) it went slower, while processing was fastest at 15h with delta over 2000. The “rows processed” graph has always an increasing tendency and this is normal since the rows processed are a cumulative sum and if the extract|process is running, than this graph should always display as increasing.

Tableau besides many useful features has an option to chart the trend line (black line displayed in every hour) which really helps for a better understanding of the rate/delta.

Next Page »