Transcript Profile of waitsand cpu - Bobby Durrett`s DBA Blog

Focusing Your Oracle
Database Tuning Efforts
For PeopleSoft
Applications
Bobby Durrett
U. S. Foodservice, Inc.
Introduction
• PeopleSoft is a complicated application
• There are many things that can be tuned – hardware,
operating system, Oracle and the application
• There are many books, articles, etc. on Oracle tuning
• Need a way to focus your efforts on the one area that
will help the most
Oracle Server Processes
• Each PeopleSoft program connects to an Oracle
server process
• If a PeopleSoft program that you care about is slow
you need to see where its Oracle process is spending
its time
• If you can find out where the server process is
spending the majority of its time you can focus your
tuning efforts on reducing that time
Oracle Server Processes continued
• A reduction in the Oracle server process’s time will
result in an equal reduction in the PeopleSoft
program’s time
• An Oracle server process is a window on all the other
pieces of the database - it is where the PeopleSoft
application touches everything else on the database
server
Oracle Database
Server
Shared memory
and disk
Server Processes
Background
Processes
Peoplesoft app
and batch servers
User Processes
Performance Profile
• Oracle supplies CPU time and wait time for a server
process
• You can produce a “Performance Profile” of the
server process or session
• CPU time
• Wait time
• Elapsed time – end time minus start time
• CPU time plus wait time should equal elapsed time –
but doesn’t always
Example Of A Performance Profile
TIMESOURCE
ELAPSED_SECONDS
----------------------------- --------------REALELAPSED
25
db file scattered read
16.000231
CPU
8.87
db file sequential read
1.286592
SQL*Net message from client
.257231
log file sync
.043774
direct path write
.028848
SQL*Net message to client
.000039
Where We Are Going From Here
•
•
•
•
•
Simple way to get a profile
Four different categories time can fall under
How to find the correct Oracle session
A more accurate way to get a profile
A tool that gives you a profile of SQL that has
occurred in the past
• Conclusion and references
How To Get A Performance Profile
Using V$ Tables – Before Script
•
•
•
•
•
Run script to start monitoring an Oracle session
Get waits from V$SESSION_EVENT
Get CPU from V$SESSTAT
Get current time
Store these in a table
DROP TABLE BEFOREOTHERSESSION;
CREATE TABLE BEFOREOTHERSESSION AS
SELECT SID,EVENT TIMESOURCE,(TIME_WAITED/100) SECONDS
FROM V$SESSION_EVENT
WHERE SID=&&MONITORED_SID;
INSERT INTO BEFOREOTHERSESSION
SELECT SID,'CPU' TIMESOURCE,(VALUE/100) SECONDS
FROM V$SESSTAT
WHERE SID=&&MONITORED_SID
AND STATISTIC#=(SELECT STATISTIC#
FROM V$STATNAME WHERE
NAME='CPU used by this session');
COMMIT;
INSERT INTO BEFOREOTHERSESSION
SELECT SID,'REALELAPSED' TIMESOURCE,
(SYSDATE-TO_DATE('01/01/1900','MM/DD/YYYY'))*24*60*60
SECONDS
FROM V$SESSION
WHERE SID=&&MONITORED_SID;
COMMIT;
How To Get A Performance Profile
Using V$ Tables – After Script
• Run script to stop monitoring a session and to get a
performance profile report
• Union together times for waits, CPU and current time
• Subtract the times stored by the before script
• Output the difference in order of most time to least
SELECT AFTER.TIMESOURCE,
AFTER.SECONDS-BEFORE.SECONDS ELAPSED_SECONDS
FROM
(SELECT SID,EVENT TIMESOURCE,(TIME_WAITED/100) SECONDS
FROM V$SESSION_EVENT
WHERE SID=&&MONITORED_SID
UNION
SELECT SID,'CPU' TIMESOURCE,(VALUE/100) SECONDS
FROM V$SESSTAT
WHERE SID=&&MONITORED_SID
AND STATISTIC#=(SELECT STATISTIC#
FROM V$STATNAME
WHERE NAME='CPU used by this session')
UNION
SELECT SID,'REALELAPSED' TIMESOURCE,
(SYSDATE-TO_DATE('01/01/1900','MM/DD/YYYY'))*24*60*60
SECONDS
FROM V$SESSION
WHERE SID=&&MONITORED_SID) AFTER,
BEFOREOTHERSESSION BEFORE
WHERE
BEFORE.SID=AFTER.SID AND
AFTER.TIMESOURCE=BEFORE.TIMESOURCE
ORDER BY ELAPSED_SECONDS DESC;
DROP TABLE BEFOREOTHERSESSION;
Four Types of Time – Main Point
of the Presentation
•
•
•
•
Non-Idle waits - waits within the database
Idle waits – waits outside the database
CPU
Unaccounted-for time – real time minus sum of waits
and CPU
Non-idle Waits
• Ones that you hear most about
• Lots of documentation about what these mean
• Oracle documentation
• Metalink
• Books
• Articles
• Can usually reduce these by changing something in
the database
Common Non-Idle Waits
•
•
•
•
•
•
buffer busy waits
db file scattered read
db file sequential read
enqueue
latch free
log file sync
Non-Idle Wait Example
TIMESOURCE
ELAPSED_SECONDS
----------------------------- --------------REALELAPSED
32
enqueue
30.8
CPU
0
Non-Idle Wait Example
• Enqueue wait comprises almost all of the time
• Indicates that the session is hung on a lock
• Just find the session that is holding the lock and kill it
Idle Waits
•
•
•
•
Typically recommended that you ignore these
Not as frequently discussed
Many begin with “SQL*Net”
Can’t fix by changing something in the database
Idle Wait Example
TIMESOURCE
ELAPSED_SECONDS
----------------------------- --------------REALELAPSED
37
SQL*Net message from dblink
35.51
SQL*Net message from client
1.19
CPU
.48
log file sync
.02
Idle Wait Example
• Almost all of the time spent waiting for “SQL*Net
message from dblink”
• This means that the time is spent on a remote
database
• Need to go to the remote database and find the
session there and tune it
CPU
• Server process’s CPU time
• Means that the database blocks being accessed are
in memory
CPU Example
TIMESOURCE
ELAPSED_SECONDS
----------------------------- --------------REALELAPSED
39
CPU
35.7
db file sequential read
3.18
SQL*Net message from client
1.2
control file parallel write
.01
log file sync
.01
CPU Example
• Almost all of the time is spent using the CPU
• Tune SQL to reduce number of memory accesses
• No need to look at I/O system’s performance
Unaccounted-For Time
• Least-documented concept in this talk
• Difference between real time that elapsed and the
sum of all the waits and the CPU
• It is time that Oracle’s measurements do not account
for
• Best examples are CPU queue wait time and time
spent waiting on paging
Unaccounted-For Time Example
TIMESOURCE
ELAPSED_SECONDS
--------------------------- --------------REALELAPSED
144
CPU
45.14
SQL*Net message from client
.57
db file sequential read
.17
db file scattered read
.08
log file sync
.03
Unaccounted-For Time Example
• The majority of the time (2/3) is not accounted for by
the CPU time or waits
• Three CPU-intensive SQLs running on my singleprocessor laptop
• Unaccounted-for time is time spent on the CPU
queue
• Fixed by reducing contention for the CPU
Determining Your Oracle Session
• To get a profile you have to figure out which session
corresponds to the PeopleSoft program that is slow
• This is complicated by the fact that all PeopleSoft
programs login as the same Oracle user
• Also, some Oracle sessions are shared by multiple
PeopleSoft users
Many PeopleSoft Programs Connect To
One Oracle Session Or Server Process
• Batch
• Sqr
• Cobol
• Crystal
• Nvision
• Application Engine
• Two-tier Windows client
Some PeopleSoft programs share
Oracle sessions
• PeopleSoft’s application server has several
connections to the Oracle database
• PeopleSoft programs that use the app server share
the app server’s Oracle sessions
• Web connections
• Three-tier Windows Client
Database server
Application
Server
Tuxedo
Two-tier Windows
client
Oracle
pstools.exe
Batch programs
Cobol
SQR
Crystal
Nvision
App Engine
How To Find Your Oracle Session
Using V$ Tables
• Can use V$SESSION and V$SQLAREA to find the
active PeopleSoft SQL statements
• Oracle user SYSADM
• Can use CLIENT_INFO column of V$SESSION to
determine PeopleSoft userid and other information
• Need to set parameter EnableDBMonitoring=1 in app
server config file to get CLIENT_INFO populated
Query To Find Oracle Session Id
SELECT
A.SID,
A.SERIAL#,
TO_CHAR(A.LOGON_TIME,'MM-DD-YYYY HH24:MI:SS')
"Logon Time",
A.CLIENT_INFO,
C.SQL_TEXT
FROM V$SESSION A,V$SQLAREA C
WHERE
A.SQL_ADDRESS=C.ADDRESS (+) AND
A.SQL_HASH_VALUE=C.HASH_VALUE (+) AND
A.USERNAME = 'SYSADM' AND
A.STATUS='ACTIVE'
ORDER BY A.STATUS,A.SID,A.SERIAL#;
App Server CLIENT_INFO Example
SMITH,,10.1.2.3,PROD,PSAPPSRV,
• PeopleSoft userid
• User’s IP address
• Database name
• Program name
SQR CLIENT_INFO Example
JONES,12904
• PeopleSoft user id
• SQR Unix process id
Using Extended SQL Trace And
TKPROF To Get A Profile
• Term comes from Cary Millsap and Jeff Holt’s book –
read it for tons more good information about this
• Get Oracle trace with waits – “Extended SQL Trace”
• Use TKPROF to produce report with waits
• Piece together a profile from the TKPROF output
• More accurate than V$ tables – contains wait details
• Only works in 9i or higher (TKPROF waits=yes)
Trace And TKPROF Commands
•
•
•
•
Commands to start and stop trace work from sqlplus
First two arguments are session id and serial number
TKPROF arguments indicate use of waits
Orders SQL by total elapsed time so you see the
longest running SQLs first
Using Extended Trace and TKPROF
To start trace:
execute sys.dbms_system.set_ev(12,23,10046,8,’’);
To end trace:
execute sys.dbms_system.set_ev(12,23,10046,0,’’);
TKPROF command:
tkprof tracefile.txt tkprofout.txt waits=yes
"sort=(PRSELA,EXEELA,FCHELA)" SYS=NO
Example TKPROF Output
• I highlight the numbers that will go on a performance
profile in red
• Elapsed and CPU time come from the first part of the
report
• The wait times come from the second part
Sample TKPROF Output With Waits
select count(*)
from
dba_segments
call
count
rows
------- -----Parse
1
Execute
1
Fetch
2
------- -----total
4
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- --------0.13
0.25
10
52
0
0.00
0.00
0
0
0
7.99
30.57
18953
319306
0
-------- ---------- ---------- ---------- ---------8.12
30.83
18963
319358
0
Sample TKPROF Output With Waits
Elapsed times include waiting on following events:
Event waited on
Times
Max. Wait Total Waited
----------------------------Waited ---------- -----------SQL*Net message to client
2
0.00
0.00
db file scattered read
1974
0.06
17.14
db file sequential read
3621
0.03
5.25
SQL*Net message from client
2
0.01
0.01
***************************************************************
TKPROF Output As A Performance
Profile
TIMESOURCE
ELAPSED_SECONDS
----------------------------- --------------REALELAPSED
30.83
db file scattered read
17.14
CPU
8.12
db file sequential read
5.25
SQL*Net message from client
0.01
Using I3 To Get A Profile Of
Something In The Past
• I3 is a tool from Veritas
• Formerly known as Precise
• Stores information you need to get a profile of a SQL
statement that occurred in the past
• Have to piece together profile from two places
In Oracle Display
• What I3 calls “In Oracle” time corresponds to what I
call:
• Non-idle waits – “I/O Wait”
• CPU – “Using CPU”
• Unaccounted-for time – “CPU wait” or “Memory
wait”
Overall Activity Display
• What I3 calls “Overall Activity” time corresponds to
what I call:
• Idle waits – “Request Wait”
• Everything else – bundled together under “In
Oracle”
Conclusion
• Get a profile of the session that corresponds to the
PeopleSoft program that is slow
• Include all of the information Oracle gives you in the
profile and compare it to the real time that elapses
• Use that profile to direct your tuning efforts so you
don’t waste time trying everything to improve it
References
• Direct Contention Identification Using Oracle's
Session Wait Event Views - Craig Shallahamer
• Microstate Response-time Performance Profiling Danisment Gazi Unal
• Optimizing Oracle Performance – Cary Millsap and
Jeff Holt