Enhancements to Oracle trace file conversion and replay

[sm-shaw]

Is your feature request related to a problem? Please describe. HammerDB includes as a long-standing feature the option to convert and replay Oracle trace files. Recently there has been interest in this feature e.g. https://github.com/TPC-Council/HammerDB/discussions/695, however we know there is an opportunity to improve it.

Describe the solution you'd like Where there is interest there is the potential to enhance and improve HammerDB Oracle trace conversion and replay to re-run workloads captured from Oracle on Oracle and other databases.

Describe alternatives you've considered Oracle has the licensed option of RAT (real application testing) although this does not allow replay against other databases and is not open source.

Additional context This work has been done in the past and there is the opportunity for an interested party to pick it up. In particular, this issue serves to note that there are known issues in the current implementation and highlight these to prevent the assumption that this feature is fully complete and give the opportunity for further discussion and effort to complete it.

As an example the following shows Oracle trace file output as described in the documentation https://www.hammerdb.com/docs/ch14.html.

Trace file /u01/diag/rdbms/razcdb1/RAZCDB1/trace/RAZCDB1_ora_7642.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.10.0.0.0
Build label:    RDBMS_19.10.0.0.0DBRU_LINUX.X64_201227
ORACLE_HOME:    /home/oracle
System name:    Linux
Node name:  razorbill.home
Release:    4.18.0-348.12.2.el8_5.x86_64
Version:    #1 SMP Thu Jan 20 12:59:31 PST 2022
Machine:    x86_64
Instance name: RAZCDB1
Redo thread mounted by this instance: 1
Oracle process number: 46
Unix process pid: 7642, image: oracle@razorbill.home
...
*** 2024-07-03T10:12:29.031141-04:00 (RAZPDB1(3))
*** SESSION ID:(287.63997) 2024-07-03T10:12:29.031190-04:00
*** CLIENT ID:() 2024-07-03T10:12:29.031202-04:00
*** SERVICE NAME:(razpdb1) 2024-07-03T10:12:29.031212-04:00
*** MODULE NAME:(wish8.6@razorbill.home (TNS V1-V3)) 2024-07-03T10:12:29.031224-04:00
*** ACTION NAME:() 2024-07-03T10:12:29.031235-04:00
*** CLIENT DRIVER:(Oratcl) 2024-07-03T10:12:29.031245-04:00
*** CONTAINER ID:(3) 2024-07-03T10:12:29.031257-04:00

CLOSE #140104750723472:c=1,e=1,dep=2,type=0,tim=1513246068
=====================
PARSING IN CURSOR #140104750370288 len=134 dep=1 uid=0 oct=47 lid=0 tim=1513246664 hv=1934114635 ad=
'7cb42048' sqlid='829z4wttnhgub'
begin
if (user = 'TPCC') then
execute immediate
'alter session set events ''10046 trace name context forever, level 4''';
end if;
end;
END OF STMT
EXEC #140104750370288:c=2298,e=1806,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,plh=0,tim=1513246662
CLOSE #140104750370288:c=10,e=10,dep=1,type=1,tim=1513246902
=====================
--More--(0%)
...
PARSING IN CURSOR #140104749872736 len=186 dep=0 uid=188 oct=47 lid=188 tim=1513
430863 hv=849606409 ad='74273600' sqlid='16dhat4ta7xs9'
begin neword(:no_w_id,:no_max_w_id,:no_d_id,:no_c_id,:no_o_ol_cnt,:no_c_discount
,:no_c_last,:no_c_credit,:no_d_tax,:no_w_tax,:no_d_next_o_id,TO_DATE(:timestamp,
'YYYYMMDDHH24MISS')); END;
END OF STMT
PARSE #140104749872736:c=100,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=
1513430862
BINDS #140104749872736:

 Bind#0
  oacdty=01 mxl=16386(12000) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=873 siz=16392 off=0
  kxsbbbfp=7f6cadcf6438  bln=16386  avl=01  flg=05
  value="9"
 Bind#1
  oacdty=01 mxl=16386(12000) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=873 siz=16392 off=0
  kxsbbbfp=7f6cadcf23f0  bln=16386  avl=02  flg=05
  value="10"
....

In the HammerDB GUI in the side menu there is the button "Convert Trace to Oratcl" that is active when Oracle is selected. When a trace file is loaded then pressing this button will convert it into a format that can replayed against the database. The following is an example of tracing the HammerDB TPROC-C workload.

Note that it should be obvious that in many cases simply re-running the same trace against the database will result in errrors. For example if the TPROC-H insert refresh function is traced then replaying the inserts will result in constraint violations. Tracing and converting is intended as a template for building a bespoke test workload.

#!/usr/local/bin/tclsh8.6
package require Oratcl
####UPDATE THE CONNECT STRING BELOW###
set connect tpcc/tpcc@RAZPDB1
set lda [oralogon $connect]
set curn140104749290880 [oraopen $lda ]
set sql140104749290880 "alter session set NLS_LANGUAGE = AMERICAN "
orasql $curn140104749290880 $sql140104749290880
set curn140104749289240 [oraopen $lda ]
set sql140104749289240 "alter session set NLS_TERRITORY = AMERICA "
orasql $curn140104749289240 $sql140104749289240
set curn140104749287600 [oraopen $lda ]
set sql140104749287600 "select max(w_id) from warehouse "
orasql $curn140104749287600 $sql140104749287600
set row [orafetch $curn140104749287600 -datavariable output ]
while { [ oramsg  $curn140104749287600 ] == 0 } {
puts $output
set row [orafetch  $curn140104749287600 -datavariable output ]
}
set curn140104749285960 [oraopen $lda ]
set sql140104749285960 "select max(d_id) from district "
orasql $curn140104749285960 $sql140104749285960
set row [orafetch $curn140104749285960 -datavariable output ]
while { [ oramsg  $curn140104749285960 ] == 0 } {
puts $output
set row [orafetch  $curn140104749285960 -datavariable output ]
}
set curn140104749284320 [oraopen $lda ]
set sql140104749284320 "BEGIN DBMS_RANDOM.initialize (val => TO_NUMBER(TO_CHAR(SYSDATE,'MMSS')) * (USERENV('SESSIONID') - TRUNC(USERENV('SESSIONID'),-5))); END; "
oraparse $curn140104749284320 $sql140104749284320
oraplexec $curn140104749284320 $sql140104749284320
set curn140104749282680 [oraopen $lda ]
set sql140104749282680 "BEGIN payment(:p_w_id,:p_d_id,:p_c_w_id,:p_c_d_id,:p_c_id,:byname,:p_h_amount,:p_c_last,:p_w_street_1,:p_w_street_2,:p_w_city,:p_w_state,:p_w_zip,:p_d_street_1,:p_d_street_2,:p_d_city,:p_d_state,:p_d_zip,:p_c_first,:p_c_middle,:p_c_street_1,:p_c_street_2,:p_c_city,:p_c_state,:p_c_zip,:p_c_phone,:p_c_since,:p_c_credit,:p_c_credit_lim,:p_c_discount,:p_c_balance,:p_c_data,TO_DATE(:timestamp,'YYYYMMDDHH24MISS')); END; "
oraparse $curn140104749282680 $sql140104749282680
oraplexec $curn140104749282680 $sql140104749282680 :p_c_middle {} :p_w_zip {} :p_d_street_1 {} :p_c_d_id {8} :p_c_discount {} :p_c_state {} :p_d_street_2 {} :p_w_id {9} :p_c_data {} :p_c_since {} :p_d_state {} :p_d_city {} :byname {1} :p_c_last {ABLEPRESATION} :p_w_state {} :p_d_id {8} :p_c_street_1 {} :p_c_street_2 {} :p_c_first {} :p_c_city {} :p_h_amount {1668} :p_c_phone {} :timestamp {20240703101229} :p_c_credit {0} :p_c_zip {} :p_c_w_id {9} :p_w_street_1 {} :p_c_credit_lim {} :p_d_zip {} :p_w_street_2 {} :p_c_id {511} :p_w_city {} :p_c_balance {0} 
oraplexec $curn140104749282680 $sql140104749282680 :p_c_middle {} :p_w_zip {} :p_d_street_1 {} :p_c_d_id {4} :p_c_discount {} :p_c_state {} :p_d_street_2 {} :p_w_id {9} :p_c_data {} :p_c_since {} :p_d_state {} :p_d_city {} :byname {1} :p_c_last {ANTIABLEANTI} :p_w_state {} :p_d_id {4} :p_c_street_1 {} :p_c_street_2 {} :p_c_first {} :p_c_city {} :p_h_amount {3763} :p_c_phone {} :timestamp {20240703101229} :p_c_credit {0} :p_c_zip {} :p_c_w_id {9} :p_w_street_1 {} :p_c_credit_lim {} :p_d_zip {} :p_w_street_2 {} :p_c_id {2134} :p_w_city {} :p_c_balance {0} 
set curn140104749872736 [oraopen $lda ]
set sql140104749872736 "begin neword(:no_w_id,:no_max_w_id,:no_d_id,:no_c_id,:no_o_ol_cnt,:no_c_discount,:no_c_last,:no_c_credit,:no_d_tax,:no_w_tax,:no_d_next_o_id,TO_DATE(:timestamp,'YYYYMMDDHH24MISS')); END; "
oraparse $curn140104749872736 $sql140104749872736
oraplexec $curn140104749872736 $sql140104749872736 :no_d_next_o_id {0} :no_c_credit {} :no_c_id {2390} :no_max_w_id {10} :no_d_tax {} :no_w_id {9} :no_c_discount {} :no_w_tax {} :no_o_ol_cnt {10} :no_c_last {} :no_d_id {5} :timestamp {20240703101229} 
oraplexec $curn140104749872736 $sql140104749872736 :no_d_next_o_id {} :no_c_credit {} :no_c_id {2507} :no_max_w_id {10} :no_d_tax {} :no_w_id {9} :no_c_discount {} :no_w_tax {} :no_o_ol_cnt {6} :no_c_last {} :no_d_id {1} :timestamp {20240703101229} 
set curn140104749805856 [oraopen $lda ]
set sql140104749805856 "BEGIN ostat(:os_w_id,:os_d_id,:os_c_id,:byname,:os_c_last,:os_c_first,:os_c_middle,:os_c_balance,:os_o_id,:os_entdate,:os_o_carrier_id); END; "
oraparse $curn140104749805856 $sql140104749805856
oraplexec $curn140104749805856 $sql140104749805856 :os_o_id {} :byname {0} :os_c_id {1473} :os_w_id {9} :os_c_balance {0} :os_d_id {8} :os_entdate {} :os_c_middle {} :os_o_carrier_id {} :os_c_first {} :os_c_last {} 
oraplexec $curn140104749805856 $sql140104749805856 :os_o_id {} :byname {1} :os_c_id {148} :os_w_id {9} :os_c_balance {} :os_d_id {10} :os_entdate {} :os_c_middle {} :os_o_carrier_id {} :os_c_first {} :os_c_last {ESEATIONANTI} 
oraplexec $curn140104749282680 $sql140104749282680 :p_c_middle {} :p_w_zip {} :p_d_street_1 {} :p_c_d_id {2} :p_c_discount {} :p_c_state {} :p_d_street_2 {} :p_w_id {9} :p_c_data {} :p_c_since {} :p_d_state {} :p_d_city {} :byname {1} :p_c_last {OUGHTPRIESE} :p_w_state {} :p_d_id {2} :p_c_street_1 {} :p_c_street_2 {} :p_c_first {} :p_c_city {} :p_h_amount {3892} :p_c_phone {} :timestamp {20240703101229} :p_c_credit {0} :p_c_zip {} :p_c_w_id {9} :p_w_street_1 {} :p_c_credit_lim {} :p_d_zip {} :p_w_street_2 {} :p_c_id {1549} :p_w_city {} :p_c_balance {0} 
oraplexec $curn140104749282680 $sql140104749282680 :p_c_middle {} :p_w_zip {} :p_d_street_1 {} :p_c_d_id {6} :p_c_discount {} :p_c_state {} :p_d_street_2 {} :p_w_id {9} :p_c_data {} :p_c_since {} :p_d_state {} :p_d_city {} :byname {1} :p_c_last {PRICALLYCALLY} :p_w_state {} :p_d_id {6} :p_c_street_1 {} :p_c_street_2 {} :p_c_first {} :p_c_city {} :p_h_amount {522} :p_c_phone {} :timestamp {20240703101229} :p_c_credit {0} :p_c_zip {} :p_c_w_id {9} :p_w_street_1 {} :p_c_credit_lim {} :p_d_zip {} :p_w_street_2 {} :p_c_id {1577} :p_w_city {} :p_c_balance {0} 
oraplexec $curn140104749282680 $sql140104749282680 :p_c_middle {} :p_w_zip {} :p_d_street_1 {} :p_c_d_id {10} :p_c_discount {} :p_c_state {} :p_d_street_2 {} :p_w_id {9} :p_c_data {} :p_c_since {} :p_d_state {} :p_d_city {} :byname {1} :p_c_last {OUGHTPRESABLE} :p_w_state {} :p_d_id {10} :p_c_street_1 {} :p_c_street_2 {} :p_c_first {} :p_c_city {} :p_h_amount {1830} :p_c_phone {} :timestamp {20240703101229} :p_c_credit {0} :p_c_zip {} :p_c_w_id {9} :p_w_street_1 {} :p_c_credit_lim {} :p_d_zip {} :p_w_street_2 {} :p_c_id {2401} :p_w_city {} :p_c_balance {0} 
oraplexec $curn140104749872736 $sql140104749872736 :no_d_next_o_id {} :no_c_credit {} :no_c_id {753} :no_max_w_id {10} :no_d_tax {} :no_w_id {9} :no_c_discount {} :no_w_tax {} :no_o_ol_cnt {12} :no_c_last {} :no_d_id {3} :timestamp {20240703101229} 
oraclose $curn140104749805856
oralogoff $lda

The following are a list of known enhancements that can do done to improve the conversion of Oracle trace files for replay:

1. Add Convert Trace to Oratcl option to the CLI - very easy as existing functionality is there.

2. Run the trace conversion in a separate thread. Do a pre-pass to extract dep=0 and remove recursive SQL.

3. Convert timestamps from memory dumps dty=180. Note memory dump ordering depends on the machine type and you can get this from the header e.g. x8_64 is little endian. There is a question on the Oracle AskTom site that shows exactly how to do this. For a timestamp you identify the variable as a TIMESTAMP (dty=180), and convert a dump of three memory locations:

bind 2: dty=180 mx1=11(11) mal=00 sc1=00 pre=00 oacflg=01 oacf12=0 
size=0 offset=48
bfp=Obbeea10 bln=11 av1=11 flg=01
value=
Dump of memory from OxOBBEEA10 to OxOBBEEA1B
BBEEA10 1F0CA977 00010111 0040420F [w B@.]
bind 3: dty=180 mx1=11(11) mal=00 sc1=00 pre=00 oacflg=01 oacf12=0 
size=0 offset=60
bfp=Obbeea1c bln=11 av1=11 flg=01
value=
Dump of memory from OxOBBEEA1C to OxOBBEEA27
BBEEA10 13096A78 [xj..]
BBEEA20 070D0112 0000D454 [....T...]

Example Perl program that does this:

if (@ARGV-0) {die "Usage: mem2ts.pl <HEX
doubleword> \n"} 
@months=("Jan","Feb","Mar","Apr","May","Jun","Jul","Aug","Sep","Oct","Nov","Dec"); 
&check_args;
my($dy,$mo,$yr,$cy)=map{hex$_}$ARGV[0]=–/(..)(..)(..)(..)/;
my($fs0,$ss,$mi,$hr)=map{hex$_}$ARGV[1]=—/(..)(..)(..)(..)/; 
my($blah,$fs3,$fs2,$fs1)=map{hex$_}$ARGV[2]=—/(..)(..)(..)(..)/; 
$tsfrac=hex(substr(SARGV[1],0,2).substr(SARGV[2],6,2).substr($ARGV[2],4,2).substr($ARGV[2],2,2)); 
printf "\nTimestamp is: %02d %s %4d %02d:°/002d:°/002d.%s\n\n",$dy,$months[$mo-1],(100*($cy-100)+($yr-100)),($hr-1),($mi-1),($ss-1),$tsfrac;
sub check_args{
if (@ARGV != 3)
{die "Number of arguments must be 3";}
foreach $1 (0..@ARGV-1){
if (length($ARGV[$1])!=8) {die "Incorrect length for argument
",$i+1,": got ",length($ARGV[$i]),", should be 8";}
} 
}
exit;

4. Convert raw datatypes. Raw = dty 23 these are shown as memory dumps but can be converted:

   bind 34: dty=23 mx1=32(08) mal=00 sc1=00 pre=00 oacflg=03 oacfl2=0 size=0 offset=1088 
   bfp=0191fbe4 bln=32 av1=08 flg=01
   value=
   Dump of memory from Ox191FBE4 to Ox191FBEC
   191FBE0 2A008000 00000000 [* ]

   the actual value which is being inserted is available and is highlighted on the second line after the "value=" line.

so would be converted if formatted as follows:

bind 34: dty=23 mx1=32(08) mal=OO sc1=00 pre=00 oacflg=03 oacfl2=0 size=0 offset-1088 
 bfp=0191fbe4 b1n=32 av1=08 fig=01
 value="2A00800000000000"

• The string "dty=23" indicates that the value is a RAW datatype. • The "Dump of memory" line must be discarded. • The value is a hex value which will get implicitly converted to the RAW value by Oracle. • The space between the first and last 8 characters must be removed. • The value must be placed in " " and included after the "value=" string.

5. Ref Cursors Dump Memory dty-102 i.e. if {[string match {\ bind\ [0-9]:\ dty=102} $line]} Ref-cursor variables returned by oraplexec must be specified as a currently open statement handle from the same logon connection:

                               set lda [oralogon scott/tiger]
                               set exec_cur [oraopen $lda]
                               set fetch_cur [oraopen $lda]
                               set plsql { begin
                                           open :fetchcur for select empno, ename 
                                           from emp where job = :job ;
                                           end;
                                       }
                               oraplexec $exec_cur $plsql :job ANALYST :fetchcur $fetch_cur
                               orafetch $fetch_cur -arrayvariable dbres -indexbyname 
                               while {[oramsg $fetch_cur rc] == 0} {
                                       puts "$dbres(EMPNO) $dbres(ENAME)"
                                       orafetch $fetch_cur -arrayvariable dbres - indexbyname
                               }

6. Use timestamps to order transactions similar to SCN based scheduling e.g. order by the tim= value for replay with multiple virtual users:

EXEC#140104750370288:c=2298,e=1806,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,plh=0,tim=1513246662

7. http://www.juliandyke.com/Presentations/Presentations.html#IsRATWorthCatching

8. Improve special character handling. $ "" i.e. empty bind variable and NULL to {} were examples:

9. Enable option to convert trace format to other databases.