Update 4.3.2015: See also Undocumented Application Engine Parameter: EnableAEMonitoring
I have written and spoken often about the huge importance of instrumentation in an application. PeopleSoft introduced internal instrumentation to PeopleTools 8.44 for its own Performance Monitor that works on any platform. Since PeopleTools 7.53, when running on an Oracle database, PeopleTools also calls the Oracle supplied package dbms_application_info package to set the module and action for the session. The values set were not particularly useful, so I wrote a PL/SQL package (psftapi) and trigger to set the module and action attributes when a process started.
In PeopleTools 8.50 this instrumentation was enhanced to set module and action to the component and page name in the PIA. These values appear in Oracle Enterprise Manager and Active Session History (ASH). They can be used to profile components.
Now, in PeopleTools 8.52 Application Engine has been enhanced to set the action to the full Application Engine step name.
To illustrate what happens, I have produced an Oracle Extended SQL Trace for the process, but I have shown only the lines in a SQL Trace file with 3 asterisks. So you can see MODULE and ACTION being set (and some other timestamp information). The lines in italic were emitted when module and action were set by my psftapi package, in which I simply set the MODULE to the Application Engine program name.
Application Engine also sets the MODULE attribute. In the above example it was set to
Unfortunately, this change to MODULE also means that it is no longer possible to enable trace by setting a watchpoint (as I blogged previously). It no longer works with Application Engine because it is not possible to predict the value of the SESSIONIDNUM in MODULE.
I am testing with 8.52.12 and have found a significant problem. Application Engine doesn't set the action on DO SELECT statements. The first statement in the trace extract below does come from
However, MAIN.SELECT.D duly appears in the AE batch timings report.
This is a serious problem If you profile the top SQL statements in an Application Engine (using either ASH as I have done above, or by profiling a trace file and looking for the top SQL statement by searching through the raw trace file) it will lead you to the wrong conclusion! Time spent in
Nevertheless, this instrumentation is a very welcome and significant improvement for Application Engine. It will help to localise performance problems. However, until the omissions are fixed, you will need to be aware of their implications and avoid falling into the traps.
My thanks to Wolfgang Breitling for telling me about the feature.
I have written and spoken often about the huge importance of instrumentation in an application. PeopleSoft introduced internal instrumentation to PeopleTools 8.44 for its own Performance Monitor that works on any platform. Since PeopleTools 7.53, when running on an Oracle database, PeopleTools also calls the Oracle supplied package dbms_application_info package to set the module and action for the session. The values set were not particularly useful, so I wrote a PL/SQL package (psftapi) and trigger to set the module and action attributes when a process started.
In PeopleTools 8.50 this instrumentation was enhanced to set module and action to the component and page name in the PIA. These values appear in Oracle Enterprise Manager and Active Session History (ASH). They can be used to profile components.
Now, in PeopleTools 8.52 Application Engine has been enhanced to set the action to the full Application Engine step name.
To illustrate what happens, I have produced an Oracle Extended SQL Trace for the process, but I have shown only the lines in a SQL Trace file with 3 asterisks. So you can see MODULE and ACTION being set (and some other timestamp information). The lines in italic were emitted when module and action were set by my psftapi package, in which I simply set the MODULE to the Application Engine program name.
*** 2012-11-22 21:47:38.282
*** SESSION ID:(7.2237) 2012-11-22 21:47:38.282
*** CLIENT ID:(PS) 2012-11-22 21:47:38.282
*** SERVICE NAME:(HCM91) 2012-11-22 21:47:38.282
*** MODULE NAME:(PSPMCSOSUM) 2012-11-22 21:47:38.282
*** ACTION NAME:(PI=867:Processing) 2012-11-22 21:47:38.282
*** MODULE NAME:(PSAE.PSPMCSOSUM.1448) 2012-11-22 21:47:38.419
*** ACTION NAME:(PSPMCSOSUM) 2012-11-22 21:47:38.419
*** ACTION NAME:(PSPMCSOSUM.MAIN.STATS.S) 2012-11-22 21:47:38.420
*** 2012-11-22 21:47:38.588
*** ACTION NAME:(PSPMCSOSUM.MAIN.CTL.P) 2012-11-22 21:47:38.919
*** ACTION NAME:(PSPMCSOSUM.MAIN.SELECT.C) 2012-11-22 21:47:38.937
*** ACTION NAME:(PSPMCSOSUM.GETCNT.CNT.P) 2012-11-22 21:47:38.963
…
*** ACTION NAME:(PSPMCSOSUM.MAIN.SELECT.C) 2012-11-22 21:48:15.168
*** ACTION NAME:(PSPMCSOSUM.GETCNT.CNT.P) 2012-11-22 21:48:15.168
*** ACTION NAME:(PSPMCSOSUM.MAIN.Close.P) 2012-11-22 21:48:15.197
*** ACTION NAME:(PI=867:Success) 2012-11-22 21:48:15.201
Application Engine also sets the MODULE attribute. In the above example it was set to
PSAE.PSPMCSOSUM.1448. The string is composed of three parts.- PSAE indicates that it was running Application Engine. It sets the same value for both stand-alone and Tuxedo server Application Engine processes.
- PSPMCSOSUM was the name of the Application Engine Program
- 1448 was the operating system process ID of the Application Engine process. This value is recorded in the column SESSIONIDNUM on the table PSPRCSQUE.
SELECT r.prcsinstance, h.module, h.action, sum(1) ash_secs
FROM v$active_Session_history h
, psprcsque q
, psprcsrqst r
WHERE r.prcsinstance = q.prcsinstance
AND h.module = 'PSAE.'||q.prcsname||'.'||q.sessionidnum
AND h.sample_time BETWEEN r.begindttm AND NVL(r.enddttm,SYSDATE)
and r.prcsinstance = 867
GROUP BY r.prcsinstance, h.module, h.action
ORDER BY ash_secs DESC
/
PRCSINSTANCE MODULE ACTION ASH_SECS
------------ -------------------- ------------------------- --------
867 PSAE.PSPMCSOSUM.1448 PSPMCSOSUM.GETCNT.CNT.P 7
867 PSAE.PSPMCSOSUM.1448 PSPMCSOSUM.MAIN.STATS.S 1
Unfortunately, this change to MODULE also means that it is no longer possible to enable trace by setting a watchpoint (as I blogged previously). It no longer works with Application Engine because it is not possible to predict the value of the SESSIONIDNUM in MODULE.
I am testing with 8.52.12 and have found a significant problem. Application Engine doesn't set the action on DO SELECT statements. The first statement in the trace extract below does come from
PSPMCSOSUM.MAIN.CTL PeopleCode, however, the second SQL statement actually comes from PSPMCSOSUM.MAIN.SELECT.D, but the absence of another action line would lead you to believe the statement came from the preceding PeopleCode step.
*** ACTION NAME:(PSPMCSOSUM.MAIN.CTL.P) 2012-11-22 21:47:38.919
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220814597
WAIT #0: nam='SQL*Net message from client' ela= 740 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220815371
CLOSE #348647416:c=0,e=33,dep=0,type=1,tim=257220815447
=====================
PARSING IN CURSOR #348528704 len=98 dep=0 uid=45 oct=3 lid=45 tim=257220815496 hv=1424819941 ad='7ff2559e550' sqlid='98af7ppafu1r5'
END OF STMT
PARSE #348528704:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1148792852,tim=257220815496
EXEC #348528704:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1148792852,tim=257220815572
WAIT #348528704: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220815612
FETCH #348528704:c=0,e=2824,p=0,cr=16,cu=0,mis=0,r=1,dep=0,og=1,plh=1148792852,tim=257220818462
STAT #348528704 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=16 pr=0 pw=0 time=2828 us)'
STAT #348528704 id=2 cnt=3075 pid=1 pos=1 obj=228740 op='INDEX FULL SCAN PS_PSPMCSO_CHART (cr=16 pr=0 pw=0 time=333 us cost=0 size=13 card=1)'
WAIT #348528704: nam='SQL*Net message from client' ela= 123 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220818671
FETCH #348528704:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1148792852,tim=257220818696
WAIT #348528704: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220818714
WAIT #348528704: nam='SQL*Net message from client' ela= 702 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220819434
CLOSE #349389936:c=0,e=16,dep=0,type=1,tim=257220819496
=====================
PARSING IN CURSOR #349702624 len=555 dep=0 uid=45 oct=3 lid=45 tim=257220819548 hv=1888777338 ad='7ff2559ce90' sqlid='5phgqq9s98x3u'
SELECT DISTINCT OPRID , TO_CHAR(CAST((LOGINDTTM) AS TIMESTAMP),'YYYY-MM-DD-HH24.MI.SS.FF') , TO_CHAR(CAST((LOGOUTDTTM) AS TIMESTAMP),'YYYY-MM-DD-HH24.MI.SS.FF') , PM_SIGNON_TYPE , PM_SIGNOFF_TYPE FROM PSPMCSOLOG_VW WHERE '1' <> '2' AND TO_DATE(TO_CHAR(LOGINDTTM,'YYYY-MM-DD'),'YYYY-MM-DD') >= TO_DATE('2005-07-06','YYYY-MM-DD') AND TO_DATE(TO_CHAR(LOGOUTDTTM,'YYYY-MM-DD'),'YYYY-MM-DD') >= TO_DATE('2005-07-06','YYYY-MM-DD') AND OPRID NOT IN ( SELECT OPRID FROM PSPMCSOCHRTXOP) AND LOGIPADDRESS NOT IN ( SELECT LOGIPADDRESS FROM PSPMCSOCHRTXIP) ORDER BY 2
END OF STMT
PARSE #349702624:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4226533831,tim=257220819547
EXEC #349702624:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4226533831,tim=257220819669
WAIT #349702624: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220819723
WAIT #349702624: nam='SQL*Net more data to client' ela= 76 driver id=1413697536 #bytes=8145 p3=0 obj#=-40016373 tim=257220831271
FETCH #349702624:c=15600,e=11621,p=0,cr=214,cu=0,mis=0,r=201,dep=0,og=1,plh=4226533831,tim=257220831375
WAIT #349702624: nam='SQL*Net message from client' ela= 988 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220832412
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220832481
WAIT #0: nam='SQL*Net message from client' ela= 40 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220832541
*** ACTION NAME:(PSPMCSOSUM.MAIN.SELECT.C) 2012-11-22 21:47:38.937
However, MAIN.SELECT.D duly appears in the AE batch timings report.
C o m p i l e E x e c u t e F e t c h Total
SQL Statement Count Time Count Time Count Time Time
------------------------------ ------- -------- ------- -------- ------- -------- --------
…
AE Program: PSPMCSOSUM
MAIN.CTL.D 1 0.0 1 0.0 2 0.0 0.0
MAIN.SELECT.D 1 0.0 1 0.0 556 0.0 0.0
MAIN.STATS.S 1 0.0 1 0.5 0 0.0 0.5
…
This is a serious problem If you profile the top SQL statements in an Application Engine (using either ASH as I have done above, or by profiling a trace file and looking for the top SQL statement by searching through the raw trace file) it will lead you to the wrong conclusion! Time spent in
PSPMCSOSUM.MAIN.SELECT.D will be accounted as having been spent in PSPMCSOSUM.GETCNT.CNT.P. It is not until you look for the specific SQL statement in Application Designer that you realise that the source code doesn't match the instrumentation.
My thanks to Wolfgang Breitling for telling me about the feature.
@go-faster.co.uk on BlueSky
Posts
4 comments :
Can you please define ASH_SECS in your script. Thank you
I think the above comment really relates to a different posting about Active Session History. ASH_SECS is the column alias I use in my scripts for the amount DB Time. So when working with ASH data you could 10 seconds of DB time for each row on DBA_HIST_ACTIVE_SESS_HISTORY. This is set out in my paper Practical Use of ASH - http://www.go-faster.co.uk/docs.htm#Practical_ASH.pdf
This module information is not showing up my v$active_session_history. What do i need to
set in peoplesoft for the app engine job module info to start showing up in the v$active_session_history in tools 8.5* thank you in advance.
There is a new parameter in PeopleTools 8.54, which was backported to PT8.52.23 and PT8.53.13 in the Database Options section of the process scheduler configuration file (psprcs.cfg). EnableAEMonitor controls whether Application Engine calls DBMS_APPLICATION_INFO. The default value for this parameter is 0. If the parameter is not present add it and set it to 1. See a more recent blog postingUndocumented Application Engine Parameter: EnableAEMonitoring, http://blog.psftdba.com/2015/03/undocumented-application-engine.html).
Post a Comment