Monitor I/O performance on Solaris with DTrace script and Oracle Database 12c with pluggable database
July 8, 2013 by Nakinov · 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 Nakinov · 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 Nakinov · 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.