It was only a matter of time before I posted an article about my TDF_LAP() function - which is literally a "matter of time". I created this useful function to measure the timings of routines and SQL statements in SQR batch processes. It's actually a set of timing entries that can be nested - levels 0 thru 20. In general, a simple BEG and END call will calculate the elapsed time in between and print the results on a log.
Above: LEGO Guy returns - he's going to replicate the TDF_LAP function in Asssembler. Stay tuned...
Flashback: LEGO Guy loves Assembler
Sample Log Output - AP Vendor/Sourcing Extract
Process_Main uses timing set number 1 and contains all the other routines which use the stand-alone level of zero. The nested levels end and appear first followed by the high level Process_Main routine which displays the total BEG/END information.
Below are the usage notes & parameter descriptions for the TDF_LAP() function. The LOG Y/N option is useful if a routine or SQL statement is executed multiple times - say 1000 or more. The calculated lapsed time (#O_sec) can then be aggregated & printed after all instances have executed instead of printing 1000+ log entries.
!**********************************************************************
!* LAPSE Between Begin/End Times *
!**********************************************************************
!* *
!* INPUT: $I_oper - Operation Type (BEG/END) *
!* #I_idx - Lapse Index Set (0 thru 20) *
!* $I_log - Display Log Output? (Y/N) *
!* $I_msg - Message Text *
!* OUTPUT: #O_sec - Lapsed in seconds *
!* $O_hms - Lapsed in HH:MI:SS Format *
!* *
!**********************************************************************
!* *
!* EXAMPLE: do TDF_LAP('BEG', 0, 'N','', #O_sec, $O_hms) *
!* ... *
!* do TDF_LAP('END', 0, 'Y', 'Lapsed', #O_sec, $O_hms) *
!* *
!* RESULTS: Displays Duration between BEG/END times. *
!* Returns Duration in both seconds and HH:MI:SS. *
!* Resets BEG time to END time for next lapse message. *
!* Index Set 0 used for timings (0 thru 20 available) - *
!* use different sets for nested timings (otherwise 0). *
!* *
!**********************************************************************
Sample - Nested Timings
The routine below is part of a much larger process - a custom Voucher Edit/Build module. The routine NSS_Edit_AP_Invoice_Dup will use timing levels 7, 8 and 9 to track each nested component of the routine.
!**********************************************************************
!* NSS Edit AP Invoice Duplicate *
!**********************************************************************
begin-procedure NSS_Edit_AP_Invoice_Dup
do TDF_LAP('BEG', 7, 'N', '', #O_sec, $O_hms)
let $DUP_VNDR = ' and a.vendor_setid = ~<SETID>~ ' ||
' and a.vendor_id = u.vendor_id '
let $DUP_VNDR = replace($DUP_VNDR, '<SETID>', $NSS_setid_vendor)
let $DUP_VNDR = replace($DUP_VNDR, '~', chr(39))
create-array name=DUPmtx size=5 field=DUPsql:char
let DUPmtx.DUPsql (0) = ' and a.business_unit = u.business_unit '
let DUPmtx.DUPsql (1) = $DUP_vndr
let DUPmtx.DUPsql (2) = ' and a.invoice_id = u.invoice_id '
let DUPmtx.DUPsql (3) = ' and a.invoice_dt = u.invoice_dt '
let DUPmtx.DUPsql (4) = ' and a.gross_amt = u.invoice_amount '
! Initialize Defaults at Origin/BU Levels
let #DUPdef = #OPT_dup_inv_comb_code
! Update Staging Detail with Specified/Default Combination Options
let $SQL_proc = 'NSS_Edit_AP_Invoice_Dup (Options)'
let $SQL_action = 'Update'
let $SQL_table = 'XX_API_STG_DTL'
do TDF_LAP('BEG', 8, 'N', '', #O_sec, $O_hms)
begin-sql On-Error=Error-Routine
update ps_xx_api_stg_dtl u
set (u.dup_invoice_ind,
u.dup_inv_comb_code) =
(select a.dup_invoice_ind,
decode(a.dup_invoice_ind,
'D', #DUPdef,
decode(a.dup_invoice_action,
'K',a.dup_inv_comb_code,0))
from ps_vendor_invoice a
where a.setid = $NSS_setid_vendor
and a.vendor_id = u.vendor_id
and a.effdt =
(select max(a2.effdt)
from ps_vendor_invoice a2
where a2.setid = a.setid
and a2.vendor_id = a.vendor_id
and a2.effdt <= sysdate))
where u.business_unit = $NSS_business_unit
and u.xx_batch_type = $NSS_xx_batch_type
and u.xx_batch_id = #NSS_xx_batch_id
and u.xx_line_status = 'P'
and exists
(select 'X'
from ps_vendor_invoice a
where a.setid = $NSS_setid_vendor
and a.vendor_id = u.vendor_id
and a.effdt <= sysdate)
end-sql
do TDF_LAP('END', 8, 'Y', $SQL_proc, #O_sec, $O_hms)
! Cycle Thru Distinct Combinations (Dynamic SQL)
do TDF_LAP('BEG', 8, 'N', '', #O_sec, $O_hms)
begin-select
dup.dup_inv_comb_code
let $DUPwhere = ''
let #DUPcode = &dup.dup_inv_comb_code
let #DUPmap = &dup.dup_inv_comb_code
while #DUPmap > 0
do TDF_ERRBIT(#DUPmap, #DUPidx, #DUPval)
let $DUPsql = DUPmtx.DUPsql (#DUPidx)
let $DUPwhere = $DUPwhere || $DUPsql
end-while
do NSS_Edit_AP_Invoice_Dup_SQL
from ps_xx_api_stg_dtl dup
where dup.business_unit = $NSS_business_unit
and dup.xx_batch_type = $NSS_xx_batch_type
and dup.xx_batch_id = #NSS_xx_batch_id
and dup.xx_line_status = 'P'
and dup.dup_inv_comb_code > 0
group by dup.dup_inv_comb_code
end-select
let $SQL_proc = 'NSS_Edit_AP_Invoice_Dup [SQL Cycles]'
do TDF_LAP('END', 8, 'Y', $SQL_proc, #O_sec, $O_hms)
let $SQL_proc = 'NSS_Edit_AP_Invoice_Dup (Total)'
do TDF_LAP('END', 7, 'Y', $SQL_proc, #O_sec, $O_hms)
end-procedure
!**********************************************************************
!* NSS Edit AP Invoice Duplicates (per SQL Combination) *
!**********************************************************************
begin-procedure NSS_Edit_AP_Invoice_Dup_SQL
let $SQL_proc = 'NSS_Edit_AP_Invoice_Dup_SQL'
let $SQL_action = 'Update'
let $SQL_table = 'XX_API_STG_DTL'
do TDF_LAP('BEG', 9, 'N', '', #O_sec, $O_hms)
begin-sql On-Error=Error-Routine
update ps_xx_api_stg_dtl u
set u.xx_err_ap = u.xx_err_ap + {ERR_AP_duplicate},
u.xx_errors = u.xx_errors + 1
where u.business_unit = $NSS_business_unit
and u.xx_batch_type = $NSS_xx_batch_type
and u.xx_batch_id = #NSS_xx_batch_id
and u.xx_line_status = 'P'
and u.dup_inv_comb_code = #DUPcode
and exists
(select 'X'
from ps_voucher a
where 1 = 1
[$DUPwhere]
and a.business_unit in
(select z.setcntrlvalue
from ps_set_cntrl_rec z
where z.setid = $NSS_setid_vendor
and z.recname = 'VENDOR')
and a.invoice_id = u.invoice_id
and a.entry_status <> 'X'
and a.close_status <> 'C');
commit;
end-sql
let $SQL_proc = $SQL_proc || ' [' || to_char(#DUPcode) || ']'
do TDF_LAP('END', 9, 'Y', $SQL_proc, #O_sec, $O_hms)
end-procedure
!**********************************************************************
Portion of LOG Output:
The TDF_LAP() calls are highlighted in the code above. The 'nested' timings use levels 7, 8 and 9 in this example. The entire routine took .49 micro-seconds as shown by the last line (level 7 timing). The two nested level 8 entries show .32 and .17 microseconds - level 9 is a subset of the second level 8 entry at .06 microseconds.
The TDF_LAP() function is a staple in all my SQR processes.
Coming up - COBOL and Assembler/370 versions.
