Ignore previous. Here is same with SQL statements expanded.
* - TRCPGM2 command
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-TRCPGM2command>-
Library List
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-LibraryList>-
Some important notes
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-Someimportantnotes>-
Analyzing Output
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-AnalyzingOutput>-
Statement Processed Count
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-StatementProcessedCount>-
Statement Processing Time
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-StatementProcessingTime>-
Detail build information
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-Detailbuildinformation>-
Source
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-Source>-
Output File
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-OutputFile>-
Change Output File attributes
<
http://confluence.corp.pvt:8180/pages/viewpage.action?pageId=31524754#TraceProgramPerformance(TRCPGM2command)-ChangeOutputFileattributes>**TRCPGM2
command*
The TRCPGM2 command will perform a setup and call the TRCPGM program.
TRCPGM is a C program that uses the IBM debugging API's to retrieve debug
and source information and logs each program statement that is executed
into a source physical file. This allows analysis to see how many times a
particular program statement is invoked.
*Trace a program*
*Library List*
TRCPGM2 requires the following libraries. The command will added them to
the library list *LAST. .
- QUSRTOOL
- TRCRPG2
*Running the Trace*
The following commands will start a trace on a program.
The STRDBG command is used in conjunction with TRCPGM2. Debug will be
stopped, if currently active. TRCPGM2 will start debug with UPDPROD(*YES).
1. TRCRPG2/TRCPGM2 SET(*ON) PGM(LIBRARY/PROGRAM)
OUTFILE(TRCRPG2/OUTPUTxxx)
1. Be sure to put the library and program that you want to debug.
2. Be sure to specify the output file that you created in the above
step under Output File.
2. CALL LIBRARY/PROGRAM
3. TRCRPG2/TRCPGM2 SET(*OFF)
*Some important notes*
- It works best to set the program to start debugging at a callable
program. So not a service program with no main specified. The trace
process will step into the procedure and still log the desired information.
- You can use STRSRVJOB before issuing the STRDBG command and the trace
process will trace the other job.
- The trace process will add a lot of time to the processing.
- This is because for each program statement that is executed it has
to write a row into your output file.
- The timestamp values between statements includes the time that the
TRCPGM took to retrieve the statement number and write the row to the
outfile.
- AKA the difference in time between one statement to the next should
be used for trending, not as definitive.
*Analyzing Output*
The output that is placed in the specified output file will be a statement
by statement run down of exactly what was executed. This information can
be very informative from two very important perspectives.
1. The number of times a particular statement was invoked.
2. The general length of time a statement took to process
*Statement Processed Count*
The reason the number of times a particular statement is processed is
important is because it allows us to focus on areas of the code where we
might be able to focus and improve the code to reduce the number of
invocations.
The following SQL statement can be used to pull the data sorted by the
number of times a particular statement was invoked.
select statement, count(*)
From (select substr(srcdta,1,90) statement
from trcrpg2/OUTPUTxxx) statements
group by statement
order by count(*) desc
Be sure to replace your file with the trcrpg2/OUTPUTxxx in the above
statement.
By using this technique the API team was able to determine that an
excessive amount of CPU Cycles was being consumed in initializing large
arrays. This in turn allowed us to change the code to more efficiently
initialize the arrays and in turn saved well over 800,000 processed
statements and CPU cycles per API call. We were able to reduce the 800,000
to less than 1,200 CPU cycles. This wasn't something that showed upon
anyones reports as a problem because the CPU was able to accomplish the
task very quickly, but by resolving this we were able to return 798,800 CPU
cycles back to the system to be used for something else.
Please note that if the count equates to a SQL statement that the lines of
code that are created by the SQL precompiler all count toward this number.
So for example, if there are 3 fields selected, the count needs to include
the following.
Select 1, 2, 3
into :field1, :field2, :field3
From myTable
Where a = :a and b = :b;
EVAL SQL_00005 = where_host_variable_1
EVAL SQL_00006 = where_host_variable_2
Z-ADD -4 SQLER6
CALL SQLROUTE
PARM SQLCA
PARM SQL_00000
SQL_00003 IFEQ '1'
EVAL field1 = SQL_00008
EVAL field2 = SQL_00009
EVAL field3 = SQL_00010
END
So in this case there are actually 11 lines of code that equate to the same
line number. So if the count was 88 then it means that line of code was
actually invoked 10 times, not 88 times.
*Statement Processing Time*
The reason this is important is because it allows us to quickly see which
lines of code are taking more time than expected to run. (Often times SQL
statements that do not have indexes or were poorly constructed)
The following SQL statement can be used to pull the data sorted by the
longest run time in a descending order.
Be sure to replace your file with the trcrpg2/OUTPUTxxx in the above
statement.
*Base analysis * Collapse source
with mydata as
(
SELECT rrn(a) seq, srcdta
FROM trcrpg2.OUTPUTxxx a)
select statement, processing_time
from (
Select c.statement, c.start, c.end,
dec(timestampdiff(1,char(c.end-c.start)), 15, 0)/1000000
processing_time
from (
select substr(b.srcdta,1,91) statement,
timestamp(substr(a.srcdta,92,26)) start,
timestamp(substr(b.srcdta,92,26)) end
from mydata a
join mydata b on a.seq+1 = b.seq) c
) d
order by d.processing_time desc
*Statement, count and time* Collapse source
with mydata as (
SELECT rrn(a) seq, srcdta, substr(a.srcdta,11,80) SrcDta2
FROM trcrpg2.OUTPUTxxx a)
, myData2 as (
select b.SrcDta2,
timestamp(substr(a.srcdta,92,26)) start,
timestamp(substr(b.srcdta,92,26)) end,
dec(timestampdiff(1,char(
timestamp(substr(b.srcdta,92,26)) -
timestamp(substr(a.srcdta,92,26))))
, 15, 0)/1000000 DurTime
from mydata a
join mydata b on a.seq+1 = b.seq)
select a.SrcDta2, Int(count(*)) StmCnt, Sum(DurTime) SumTime
From MyData2 a
group by SrcDta2
order by 3 desc
*Program, Module, Procedure Summary analysis* Collapse source
with mydata as (
SELECT rrn(a) seq,
substr(srcdta,1,10) as ConstStmt, Char(
substr(srcdta, 11, posStr(substr(srcdta,11,90),' ')-1)
,10) StmtNum ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+14, 10) ObjTyp ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+25, 10) ObjLib ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+36, 10) ObjNam ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+47, 10) ModNam ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+58, 23) ProcNam ,
SRCDAT, SRCDTA,
timestamp(substr(srcdta,92,26)) as TimStamp
FROM trcrpg2.OUTPUTxxx a)
, myData2 as (
select b.ConstStmt, b.StmtNum, b.ObjTyp, b.ObjLib, b.ObjNam,
b.ModNam, b.ProcNam, b.SEQ, b.SRCDAT, b.SRCDTA,
a.TimStamp Start, b.TimStamp End,
dec(timestampdiff(1,char(b.TimStamp - a.TimStamp)
) , 15, 0)/1000000 DurTime
from mydata a
join mydata b on a.seq+1 = b.seq)
select Int(count(*)) StmCnt, Sum(DurTime) SumTime,
a.ConstStmt, a.ObjTyp, a.ObjLib, a.ObjNam,
a.ModNam, a.ProcNam
From MyData2 a
group by a.ConstStmt, a.ObjTyp, a.ObjLib, a.ObjNam,
a.ModNam, a.ProcNam
order by 2 desc
;
*Linking results back to the source* Collapse source
-- The alias is used to access the member.
create alias myLibrary.myMember for myLibrary.comsrc(myMember);
with mydata as (
SELECT rrn(a) seq,
substr(srcdta,1,10) as ConstStmt, Char(
substr(srcdta, 11, posStr(substr(srcdta,11,90),' ')-1)
,10) StmtNum ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+14, 10) ObjTyp ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+25, 10) ObjLib ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+36, 10) ObjNam ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+47, 10) ModNam ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+58, 23) ProcNam ,
SRCDAT, SRCDTA,
timestamp(substr(srcdta,92,26)) as TimStamp
FROM trcrpg2.OUTPUTxxx a)
, myData2 as (
select b.ConstStmt, b.StmtNum, b.ObjTyp, b.ObjLib, b.ObjNam,
b.ModNam, b.ProcNam, b.SEQ, b.SRCDAT, b.SRCDTA,
a.TimStamp Start, b.TimStamp End,
dec(timestampdiff(1,char(b.TimStamp - a.TimStamp)
) , 15, 0)/1000000 DurTime
from mydata a
join mydata b on a.seq+1 = b.seq)
, mySource as (
select Int(count(*)) StmCnt, Sum(DurTime) SumTime,
a.ConstStmt, a.StmtNum, a.ObjTyp, a.ObjLib, a.ObjNam,
a.ModNam, a.ProcNam, a.SRCDAT
From MyData2 a
group by a.ConstStmt, a.StmtNum, a.ObjTyp, a.ObjLib, a.ObjNam,
a.ModNam, a.ProcNam,
a.SRCDAT
order by 2 desc)
Select a.StmCnt, a.SumTime, a.ProcNam, b.SrcDta
from mySource a
Join myLibrary.OAHandlrM3 b -- REPLACE myLibrary with the library of the
alias to the source member
on INT(digits(b.srcseq)) = INT(a.StmtNum)
Where a.ModNam = 'OAHANDLRM3'
Order by 2 desc
;
*Detail analysis linked to source statements * Collapse source
-- The alias is used to access the member.
create alias myLibrary.myMember for myLibrary.comsrc(myMember);
with mydata as (
SELECT rrn(a) seq,
substr(srcdta,1,10) as ConstStmt, Char(
substr(srcdta, 11, posStr(substr(srcdta,11,90),' ')-1)
,10) StmtNum ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+14, 10) ObjTyp ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+25, 10) ObjLib ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+36, 10) ObjNam ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+47, 10) ModNam ,
substr(srcdta, posStr(substr(srcdta,11,90),' ')+58, 23) ProcNam ,
SRCDAT, SRCDTA,
timestamp(substr(srcdta,92,26)) as TimStamp
FROM trcrpg2.OUTPUTxxx a)
, myData2 as (
select b.ConstStmt, b.StmtNum, b.ObjTyp, b.ObjLib, b.ObjNam,
b.ModNam, b.ProcNam, b.SEQ, b.SRCDAT, b.SRCDTA,
a.TimStamp Start, b.TimStamp End,
dec(timestampdiff(1,char(b.TimStamp - a.TimStamp)
) , 15, 0)/1000000 DurTime
from mydata a
join mydata b on a.seq+1 = b.seq)
Select a.Seq, a.ProcNam, b.SrcSeq, b.SrcDta, a.DurTime,
a.Start, a.End
from myData2 a
Join devrpgoa6.OAHandlrM3 b
on INT(digits(b.srcseq)) = INT(a.StmtNum)
Where a.ModNam = 'OAHANDLRM3'
Order by 1
;
The timestampdiff result is returning microseconds. So in order to turn
this into seconds and milliseconds it needs to be divided by 1,000,000.
Detail build information*Source*
*Source* Collapse source
File . . . . . .
COMSRC
Library . . . . TRCRPG2
Opt Member Type
Text
TRCPGM C CMD PROCESSING PGM FOR ZTRCPGM COMMAND
(TTETRCP)
TRCPGMC CLLE CMD PROCESSING PGM FOR ZTRCPGM CL
PGM
TRCPGM2 CMD COMMAND SOURCE FOR ZTRCPGM TOOL
(TRCPGM)
*Output File*
The TRCPGM2 command requires an out file, with a trigger to populate the
timestamps. The out file will be created by TRCPGM2, by duplicating the
OUTPUT file. The new OUTPUTxxx file will be created with the same trigger
to populate the timestamps.
CRTDUPOBJ OBJ(OUTPUT)
FROMLIB(TRCRPG2)
OBJTYPE(*FILE)
TOLIB(TRCRPG2)
NEWOBJ(OUTPUTxxx)
DATA(*NO)
CST(*NO)
TRG(*YES)
*Change Output File attributes*
The TRCPGM2 will change the OUTPUTxxx out file to allow more data to be
written to your output file.
- CHGPF FILE(TRCRPG2/OUTPUTTIM) SIZE(100000 10000 32767)
On Wed, Jul 25, 2018 at 10:02 AM Alan Campin <alan0307d@xxxxxxxxx> wrote:
Found this on our wiki.
*TRCPGM2 command*
The TRCPGM2 command will perform a setup and call the TRCPGM program.
TRCPGM is a C program that uses the IBM debugging API's to retrieve debug
and source information and logs each program statement that is executed
into a source physical file. This allows analysis to see how many times a
particular program statement is invoked.
*Trace a program*
*Library List*
TRCPGM2 requires the following libraries. The command will added them to
the library list *LAST. .
- QUSRTOOL
- TRCRPG2
*Running the Trace*
The following commands will start a trace on a program.
The STRDBG command is used in conjunction with TRCPGM2. Debug will be
stopped, if currently active. TRCPGM2 will start debug with UPDPROD(*YES).
1. TRCRPG2/TRCPGM2 SET(*ON) PGM(LIBRARY/PROGRAM)
OUTFILE(TRCRPG2/OUTPUTxxx)
1. Be sure to put the library and program that you want to debug.
2. Be sure to specify the output file that you created in the above
step under Output File.
2. CALL LIBRARY/PROGRAM
3. TRCRPG2/TRCPGM2 SET(*OFF)
*Some important notes*
- It works best to set the program to start debugging at a callable
program. So not a service program with no main specified. The trace
process will step into the procedure and still log the desired information.
- You can use STRSRVJOB before issuing the STRDBG command and the
trace process will trace the other job.
- The trace process will add a lot of time to the processing.
- This is because for each program statement that is executed it
has to write a row into your output file.
- The timestamp values between statements includes the time that the
TRCPGM took to retrieve the statement number and write the row to the
outfile.
- AKA the difference in time between one statement to the next
should be used for trending, not as definitive.
*Analyzing Output*
The output that is placed in the specified output file will be a statement
by statement run down of exactly what was executed. This information can
be very informative from two very important perspectives.
1. The number of times a particular statement was invoked.
2. The general length of time a statement took to process
*Statement Processed Count*
The reason the number of times a particular statement is processed is
important is because it allows us to focus on areas of the code where we
might be able to focus and improve the code to reduce the number of
invocations.
The following SQL statement can be used to pull the data sorted by the
number of times a particular statement was invoked.
select statement, count(*)
From (select substr(srcdta,1,90) statement
from trcrpg2/OUTPUTxxx) statements
group by statement
order by count(*) desc
Be sure to replace your file with the trcrpg2/OUTPUTxxx in the above
statement.
By using this technique the API team was able to determine that an
excessive amount of CPU Cycles was being consumed in initializing large
arrays. This in turn allowed us to change the code to more efficiently
initialize the arrays and in turn saved well over 800,000 processed
statements and CPU cycles per API call. We were able to reduce the 800,000
to less than 1,200 CPU cycles. This wasn't something that showed upon
anyones reports as a problem because the CPU was able to accomplish the
task very quickly, but by resolving this we were able to return 798,800 CPU
cycles back to the system to be used for something else.
Please note that if the count equates to a SQL statement that the lines of
code that are created by the SQL precompiler all count toward this number.
So for example, if there are 3 fields selected, the count needs to include
the following.
Select 1, 2, 3
into :field1, :field2, :field3
From myTable
Where a = :a and b = :b;
EVAL SQL_00005 = where_host_variable_1
EVAL SQL_00006 = where_host_variable_2
Z-ADD -4 SQLER6
CALL SQLROUTE
PARM SQLCA
PARM SQL_00000
SQL_00003 IFEQ '1'
EVAL field1 = SQL_00008
EVAL field2 = SQL_00009
EVAL field3 = SQL_00010
END
So in this case there are actually 11 lines of code that equate to the
same line number. So if the count was 88 then it means that line of code
was actually invoked 10 times, not 88 times.
*Statement Processing Time*
The reason this is important is because it allows us to quickly see which
lines of code are taking more time than expected to run. (Often times SQL
statements that do not have indexes or were poorly constructed)
The following SQL statement can be used to pull the data sorted by the
longest run time in a descending order.
Be sure to replace your file with the trcrpg2/OUTPUTxxx in the above
statement.
*Base analysis * Expand source
*Statement, count and time* Expand source
*Program, Module, Procedure Summary analysis* Expand source
*Linking results back to the source* Expand source
*Detail analysis linked to source statements * Expand source
The timestampdiff result is returning microseconds. So in order to turn
this into seconds and milliseconds it needs to be divided by 1,000,000.
Detail build information*Source*
*Source* Expand source
*Output File*
The TRCPGM2 command requires an out file, with a trigger to populate the
timestamps. The out file will be created by TRCPGM2, by duplicating the
OUTPUT file. The new OUTPUTxxx file will be created with the same trigger
to populate the timestamps.
CRTDUPOBJ OBJ(OUTPUT)
FROMLIB(TRCRPG2)
OBJTYPE(*FILE)
TOLIB(TRCRPG2)
NEWOBJ(OUTPUTxxx)
DATA(*NO)
CST(*NO)
TRG(*YES)
*Change Output File attributes*
The TRCPGM2 will change the OUTPUTxxx out file to allow more data to be
written to your output file.
- CHGPF FILE(TRCRPG2/OUTPUTTIM) SIZE(100000 10000 32767)
On Wed, Jul 25, 2018 at 9:07 AM Dan <dan27649@xxxxxxxxx> wrote:
+1!!!
On Wed, Jul 25, 2018 at 11:57 AM, Jon Paris <jon.paris@xxxxxxxxxxxxxx>
wrote:
As I intimated in an earlier post, there are debug APIs that can
facilitate this.
Maybe I just found my next project!
--
This is the RPG programming on the IBM i (AS/400 and iSeries) (RPG400-L)
mailing list
To post a message email: RPG400-L@xxxxxxxxxxxx
To subscribe, unsubscribe, or change list options,
visit: https://lists.midrange.com/mailman/listinfo/rpg400-l
or email: RPG400-L-request@xxxxxxxxxxxx
Before posting, please take a moment to review the archives
at https://archive.midrange.com/rpg400-l.
Please contact support@xxxxxxxxxxxx for any subscription related
questions.
Help support midrange.com by shopping at amazon.com with our affiliate
link: http://amzn.to/2dEadiD
midrange.com
