Performance Metrics: What to Measure in the PeopleSoft 8 Environment

1
Performance MetricsWhat to Measure in the
PeopleSoft 8 Environment

• David Kurtz
• Go-Faster Consultancy Ltd.
• david.kurtz_at_go-faster.co.uk
• www.go-faster.co.uk

2
Agenda

• What is Performance Tuning?
• On-Line
• Batch
• What has been achieved?
• Questions?

3
Rules of Engagement

• If you cant hear me - say so now!
• Feel free to ask on-topic questions during the
  presentation.
• This presentation (with notes) will be available
  on the Tech SIG page on Customer Connection and
  on
• www.go-faster.co.uk

4
Who am I?

• DBA
• Independent consultant
• Performance tuning
• UK Oracle User Group
• Unix SIG Chair
• www.ukoug.org

5
Aphorism

• Performance is exactly what the user perceives it
  to be. No more, no less.

• Poor performance is when the users perception
  does not match their expectation.

6
Aphorism

• Performance Tuning is a search for lost time.

7
Aphorism

• When you have eliminated the impossible, whatever
  remains, however improbable, must be the truth.
• A Study in Scarlet, Arthur Conan-Doyle

• It is a capital mistake to theorise before one
  has data.
• The Memoirs of Sherlock Holmes, Arthur Conan-Doyle

8
Aphorism

• Detection is, or ought to be, an exact science.
  It should be be treated in the same cold and
  unemotional manner.
• The Sign of Four, Arthur Conan-Doyle

9
PIA (On-Line) Performance

• Architecture
• brief overview
• Sources of Metrics
• Graphical Techniques
• Tracing
• Techniques

10
It isnt always the database!

• Understand architecture
• Web front end
• Network
• Application server
• Database
• What can you measure?

11
PeopleSoft Internet Architecture

• PIA is 4-tier architecture
• Each component can contribute to response time
• Need to measure each component

12
Sources of Metrics (1)

• Browser
• Proxy Server
• 3rd Party software
• Local agent on PC
• Web Server
• Access Log

13
Sources of Metrics (2)

• BEA/Tuxedo
• Service Trace
• TMADMIN
• Oracle Database
• SQL_Trace
• PSFT Application Server Trace

14
Hint

• All the data collected on a time base.
• Therefore, make sure that the clocks on all
  machines are synchronised at least with each
  other.
• PC clocks are particularly liable to drift.

15
Sources of Metrics
Proxy Server Access Log
Webserver Access Log
16
Web/Proxy Access Log

• Standard format for access log
• www.w3.org/pub/WWW/TR/logfile.html
• Apache is different

17
Web/Proxy Access Log

• Fields
• Date, Time (finish not start)
• Time Taken
• accurate to OS time units (1/100ths or 1/1000ths)
• only 1s on Apache
• Message size bytes
• Client IP addresses DNS names
• URI stem Query

18
How to Enable WebLogic Trace

• weblogic.properties
• required
• weblogic.httpd.enableLogFiletrue
• weblogic.httpd.logFileNameaccess.log
• weblogic.httpd.logFileFormatextended
• recommended
• weblogic.httpd.logRotationTypedate
• weblogic.httpd.logRotationPeriodMins1440
• weblogic.httpd.logRotationBeginTime11-24-2000-00
  0000

19
Sample WebLogic Access Log

• Version 1.0
• Fields date time time-taken bytes c-ip c-dns
  cs-method sc-status cs-uri-stem cs-uri-query
• 2002-03-15 215103 0.981 8057 10.0.0.2 go-faster-
  1 GET 200 /servlets/iclientservlet/peoplesoft8/sig
  non.html -
• 2002-03-15 215103 0.11 2103 10.0.0.2 go-faster-1
  GET 200 /peoplesoft8/signin.css -
• 2002-03-15 215104 0.05 1186 10.0.0.2 go-faster-1
  GET 200 /peoplesoft8/images/secondaryPSFTLogo.gif
  -
• 2002-03-15 215110 3.414 8101 10.0.0.2 go-faster-
  1 POST 200 /servlets/iclientservlet/peoplesoft8/ I
  CTypePanelMenuADMINISTER_WORKFORCE_(GBL)Market
  GBLPanelGroupNamePERSONAL_DATARLtargetmain2

20
Apache Access Log

• httpd.conf
• LogFormat "Y.m.d HMStTBuhUse
  r-AgentigtsmUq" monitoring
• CustomLog logs/access.log monitoring

21
Sample Apache Access Log

• 2002.02.26 0957060275-127.0.0.1Mozilla/4.0
  (compatible MSIE 6.0 Windows NT 4.0
  Q312461)200GET/peoplesoft8/cache/PT_NEXTTAB_ENG
  _1.gif
• 2002.02.26 095717031847-127.0.0.1Mozilla/4.
  0 (compatible MSIE 6.0 Windows NT 4.0
  Q312461)200POST/servlets/iclientservlet?ICType
  PanelMenuADMINISTER_WORKFORCE_(GBL)MarketGBL
  PanelGroupNameJOB_DATA
• 2002.02.26 095726030959-127.0.0.1Mozilla/4.
  0 (compatible MSIE 6.0 Windows NT 4.0
  Q312461)200POST/servlets/iclientservlet?ICType
  PanelMenuADMINISTER_WORKFORCE_(GBL)MarketGBL
  PanelGroupNameJOB_DATA

22
What does the access log tell us?

• A date and time for every request
• Who made the request?
• How long did it take to serve?
• What was requested?
• Which component (panel group)?
• Indicate possible bandwidth problems.

23
Download Bandwidth

• version 1.0
• Fields date time time-taken bytes c-ip c-dns
  cs-method sc-status cs-uri-stem cs-uri-query
• 2002-09-10 112952 0.359 15832 141.93.249.74 141.
  93.249.74 GET 200 /XXXXXXXX/images/topPSFTLogo.gif
  -

24
Sources of Metrics
Tuxedo Service Trace
25
BEA/Tuxedo Service Trace

• Edit psappsrv.ubx file
• CLOPT-r -e APPQ.stderr
• -r enables trace to stderr file
• -e qualifies name of stderr file

26
Edit psappsrv.cfg

• Add a new variable to the trace section
• Thus service trace can be enabled/disabled from
  configuration file
• New variable will appear in the configuration
  dialogue
• Trace
• TuxedoServiceTrace-r

27
Edit psappsrv.ubx

• Change every CLOPT entry in psappsrv.ubx.
• File name is set manually.
• Same as queue name
• RQADDR"APPQ"
• CLOPT"Trace\TuxedoServiceTrace -e
  LOGDIRFSAPPQ.stderr PSAPPSRV\Spawn Server
  -s_at_..FSpsappsrv.lst -- -C CFGFILE -D Domain
  Settings\Domain ID -S PSAPPSRV"

28
Resultant psappsrv.ubb

• When domain is configured .ubb file is generated.
  All variables are fully resolved.
• CLOPT-r -e D\ps\hr8\appserv\hr8d\LOGS\APPQ.stde
  rr -p 1,6003,10 -s_at_..\psappsrv.lst
  -s_at_..\psqcksrv.lst -sICQuery -sSqlQuerySqlRequest
  -- -C psappsrv.cfg -D HR8D -S PSAPPSRV"

29
Sample Tuxedo Service Trace

• Each service called to domain is logged
• SERVICE PID SDATE STIME
  EDATE ETIME
• ------- --- ----- -----
  ----- -----
• _at_ICScript 390 1014717320 4586495
  1014717322 4588397
• _at_ICScript 390 1014717322 4588467
  1014717322 4588537
• _at_ICScript 390 1014717322 4588557
  1014717323 4589259
• _at_ICScript 390 1014717332 4598021
  1014717332 4598171
• _at_ICScript 390 1014717355 4621745
  1014717361 4627554
• _at_ICScript 390 1014717365 4631329
  1014717366 4632511
• _at_ICScript 390 1014717375 4641944
  1014717377 4643306
• _at_ICPanel 390 1014717380 4646761
  1014717381 4647783
• _at_ICPanel 390 1014717388 4654202
  1014717391 4657567
• _at_ICPanel 390 1014717396 4662614
  1014717401 4667271

30
Tuxedo Service Trace

• Service - Name of Service
• Pid - An OS PID of listener or handler
• Sdate/Edate - Start/End Date
• Seconds since 0000hrs GMT 1st January 1970.
• Stime/Etime
• Start/End Time in OS time units (1/ 100ths or
  1/1000ths)
• Hence calculate accurate service duration
• Time on Server - not queuing

31
Txrpt Utility

• SERVICE SUMMARY REPORT
• SVCNAME 9a-10a TOTALS
• Num/Avg Num/Avg
• --------------- -------- -------
• ICScript 8/1.43 8/1.43
• ICPanel 6/3.47 6/3.47
• JavaMgrGetObj 1/0.04 1/0.04
• GetCertificate 1/0.73 1/0.73
• --------------- ------- -------
• TOTALS 16/2.06 16/2.06

32
Sources of Metrics
Tuxedo tmadmin script
33
BEA/Tuxedo TMADMIN Utility

• BEA Interactive command line interface
• Can be included in scripts
• -r for read only in monitoring scripts
• pq (printqueue)
• psr (printserver)
• pclt (printclient)

34
PQ

• What queues in domain
• How many servers on queue
• How many requests queued
• (How much work on queue)
• Prog Name Queue Name Serve Wk Queued
  Queued Ave. Len Machine
• --------- ------------------- ---------
  -------- -------- -------
• JSL.exe 00095.00200 1 -
  0 - GO-FASTER
• JREPSVR.exe 00094.00250 1 -
  0 - GO-FASTER
• PSSAMSRV.exe SAMQ 1 -
  0 - GO-FASTER
• BBL.exe 54455 1 -
  0 - GO-FASTER
• WSL.exe 00001.00020 1 -
  0 - GO-FASTER
• PSAPPSRV.exe APPQ 1 -
  0 - GO-FASTER

35
PSR

• What servers exist?
• How many requests have they handled?
• What are they doing right now?
• Prog Name Queue Name Grp Name ID
  RqDone Load Done Current Service
• --------- ---------- -------- --
  ------ --------- ---------------
• BBL.exe 54455 GO-FAST 0
  3 150 ( IDLE )
• PSAPPSRV.exe APPQ APPSRV 1
  9 450 ICPanel
• PSSAMSRV.exe SAMQ APPSRV 100
  0 0 ( IDLE )
• WSL.exe 00001.00020 BASE 20
  0 0 ( IDLE )
• JSL.exe 00095.00200 JSLGRP 200
  0 0 ( IDLE )
• JREPSVR.exe 00094.00250 JREPGRP 250
  5 250 ( IDLE )

36
PCLT

• Who is connected?
• Are they doing something?
• When did they connect?
• LMID User Name Client Name
  Time Status Bgn/Cmmt/Abrt
• --------------- --------------- ---------------
  -------- ------- -------------
• GO-FASTER-1 NT WSH
  02114 IDLE 0/0/0
• GO-FASTER-1 NT JSH
  02113 IDLE 0/0/0
• GO-FASTER-1 NT tmadmin
  00000 IDLE 0/0/0
• GO-FASTER-1 PS JavaClient
  00230 BUSY/W 0/0/0

37
Sources of Metrics
Oracle SQLTrace
38
Oracle SQL Trace

• Tuning tool
• Session trace
• Format it with TKPROF
• Find long running SQL statements
• Total SQL Time for session
• call count cpu elapsed disk
  query current rows
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• Parse 72289 173.06 175.45 7
  14654 94 0
• Execute 77140 64.02 67.37 205495
  766343 170611 78630
• Fetch 50599 33.20 34.28 17302
  971624 80146 143218
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• total 200028 270.28 277.10 222804
  1752621 250851 221848

39
Small Application Servers

• Create small application with just a single
  handler process
• Enable trace on that process
• Trace sample transaction (only one user)
• sys.dbms_system.set_sql_trace_in_session(ltsidgt,ltse
  rialgt,TRUE)

40
Sources of Metrics
Proxy Server Access Log
Tuxedo Service Trace
Oracle SQLTrace
Tuxedo tmadmin script
Webserver Access Log
41
Graphical Analysis

• Dont drown in numbers
• Draw a picture
• Load Data into Database
• SQL_Loader (Oracle 9i External Table)
• Process Data
• Matching, Aggregation
• Oracle Analytic Function
• Load data into Excel
• Draw Graph

42
Sample SQLLoader File

• LOAD DATA
• INFILE 'APPQ.stderr'
• REPLACE
• INTO TABLE txrpt
• WHEN (1) '_at_'
• FIELDS TERMINATED BY WHITESPACE
• TRAILING NULLCOLS
• (service "substr(service,2)" -- remove leading _at_
• ,pid
• ,stimestamp "stimestamp/864002/24TO_DATE('01011
  970','DDMMYYYY')"
• ,stime "stime/100"
• ,queue APPQ"
• ,etime "etime/100")

43
Tips about Graphs

• Connect Excel directly to a database
• Aggregate data carefully
• Too little and excel draws it badly because it
  adds a black border around an area
• Too much and you lose details
• Pivot tables are useful
• but Excel97 buggy
• Scatters and Trendlines
• joining dots can obscure data
• Excel supports 32000 points per series

44
Example CPU Utilisation
45
Example Apache Servlet Times
46
Longest http conversations
47
Example Tuxedo Service Time
48
tmadmin - PCLT - Connect Client Sessions
49
tmadmin - PCLT - Busy/Wait Users
50
tmadmin - PQ - Queue Length
51
tmadmin - PSR - print server processes
52
Relating different metrics produces new
information
53
Batch Performance

• Sources of Metrics
• Graph

54
Sources of Metrics (1)

• Process Scheduler Request Table
• PSPRCSRQST
• need to archive this table
• maintain history in another table with on DELETE
  trigger

55
Graphical Analysis
56
Sources of Metrics(2)

• Application Engine Steps
• PS_BAT_ tables
• AE_TRACE1024128
• In Process Scheduler configuration (psprcs.cfg)
• Report to database and/or trace file
• Cobol Statement
• Report to trace file
• SQL Trace

57
Top AE Statements

• 
  AE PC Cum
  Cum
• Stmt
  Execute SQL SQL PC SQL SQL
  Total Total
• Rank Statement ID
  Count Time Time Time Time Time
  Time Time
• ---- ----------------------------------------
  -------- --------- -------- -------- ----- ------
  ----- ------
• 1 GP_PMT_PREP.CA000.CF000.S
  13 11655.56 0.00 0.00 12.8 12.8
  19.2 19.2
• 2 PeopleCode.Rowset.Fill GP_RSLT_ACUM
  4725754 10065.02 0.00 0.00 11.1 23.9
  16.6 35.9
• 3 GP_PMT_PREP.FA000.FH000.S
  15 9828.60 0.00 0.00 10.8 34.8
  16.2 52.1
• 4 GP_PMT_PREP.FA000.FC000.S
  15 8556.60 0.00 0.00 9.4 44.2
  14.1 66.2
• 5 GP_PMT_PREP.FA000.FG000.S
  15 8553.51 0.00 0.00 9.4 53.6
  14.1 80.3
• 6 GP_PMT_PREP.FA000.FB000.S
  15 8322.51 0.00 0.00 9.2 62.8
  13.7 94.1
• 7 PeopleCode.Rowset.Fill GP_RSLT_PIN
  3177786 6906.78 0.00 0.00 7.6 70.4
  11.4 105.5
• 8 PeopleCode.CNuK_
  4725754 4696.51 0.00 0.00 5.2 75.6
  7.8 113.2
• 9 PeopleCode.CDfF0_PPNw
  3409180 2392.33 0.00 0.00 2.6 78.2
  3.9 117.2

58
Oracle SQLTrace TKPROF

• Enable SQL Trace on batch process
• Process trace file with TKPROF
• report Top n statements
• sort by
• Parse/Fetch/Execute
• CPU/Elapsed Time
• statement timings/execution plan
• call count cpu elapsed disk
  query current rows
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• Parse 36 0.02 0.01 0
  0 0 0
• Execute 36 55.09 86.80 0
  2973787 3 1
• Fetch 0 0.00 0.00 0
  0 0 0
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• total 72 55.11 86.81 0
  2973787 3 1

59
Triggers

• Process Scheduler Status Change
• On-Connect

• Enable Trace
• Archiving data during purge routines
• Altering session parameters

60
Process Scheduler

• CREATE OR REPLACE trigger sysadm.set_trace
• before update of runstatus on sysadm.psprcsrqst
• for each row when
• (new.runstatus 7 and old.runstatus ! 7
• and new.prcstype IN('Application Engine','COBOL
  SQL',
• 'SQR Process','SQR Report','SQR Report For WF
  Delivery'))

61
On-Connect Triggers

• create or replace trigger sysadm.psqrysrv_session_
  trigger
• after logon on sysadm.schema
• declare
• l_program VARCHAR(64)
• begin
• SELECT program INTO l_program FROM vsession
• WHERE sid IN(SELECT sid FROM vmystat WHERE
  rownum 1)
• IF substr(l_program,1,8) 'PSQRYSRV' OR
  INSTR(UPPER(l_program),'PSNVS') gt 0 THEN
• sys.dbms_session.set_sql_trace(true)
• ...

62
For example

• sys.dbms_session.set_sql_trace(true)
• ALTER SESSION SET EVENTS '10053 trace name
  context forever, level 1
• ALTER SESSION SET EVENTS '10128 trace name
  context forever, level 2
• ALTER SESSION SET optimizer_modeFIRST_ROWS
• ALTER SESSION SET optimizer_index_caching100
• ALTER SESSION SET optimizer_index_cost_adj1
• ALTER SESSION SET sort_area_size 100000
• sys.dbms_application_info.set_module('nVision','ps
  qrysrv_session_trigger fired')

63
Further sources of Information

• PSFT Customer Connection Red Papers
• 8.4 PIA, Power Users

64
Aphorism

• The problems change from release to release, but
  the methods by which they are investigated remain
  the same.
• Jonathan Lewis (author of Practical Oracle 8i)

65
Questions?
66
Aphorism

• You know my methods, apply them.
• A Study in Scarlet, Arthur Conan-Doyle

67
Performance MetricsWhat to Measure in the
PeopleSoft 8 Environment

• David Kurtz
• Go-Faster Consultancy Ltd.
• david.kurtz_at_go-faster.co.uk
• www.go-faster.co.uk