tkprof: Who? What? How? When? Where? Why? -or-

About This Presentation

Title:

tkprof: Who? What? How? When? Where? Why? -or-

Description:

-or-David Kurtz Go-Faster Consultancy Ltd. david.kurtz_at_go-faster.co.uk www.go-faster.co.uk SQL Trace: All of the Questions and None of the Answers David Kurtz Go ... – PowerPoint PPT presentation

Number of Views:404

Avg rating:3.0/5.0

Slides: 89

Provided by: homepageN8

Category:

Tags: tkprof

more less

Transcript and Presenter's Notes

Title: tkprof: Who? What? How? When? Where? Why? -or-

1
tkprof Who? What? How? When? Where? Why?-or-

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

2
SQL Trace All of the Questions and None of the
Answers

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

3
Resources

If you cant hear me say so now.
Please feel free to ask questions as we go along.
The presentation will be available from
www.ukoug.org
www.go-faster.co.uk

4
Sales Pitch

DBA
Independent consultant
Performance tuning
PeopleSoft
UKOUG Unix SIG

5
Chief Objective

How to think about performance issues.

6
Two Chief Objectives

How to think about performance issues.
How to use TKPROF to help solve those problems.

7
Among a number of Chief Objectives

How to think about performance issues.
How to use TKPROF to help solve those problems.
How easy it is to present at UKOUG SIG meetings.

8
UKOUG Unix SIG

Next Meeting
10th June 2004
Meriden, Solihull
www.ukoug.org
BQUFTH
What are you going to present?
Perhaps you didnt expect the Spanish Inquisition!

9
Surprise, Fear and Ruthless Efficiency
10
How to think about performance issues?

All the tools are free!
And this is the most important tool of all

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

Performance is poor when the users perception
does not match their expectation.

12
YAPP

R S W
Where
R response time
S service time
W wait time

YAPP
1999
Anjo Kolk
Shari Yamaguschi
Jim Viscusi
www.oraperf.com

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

14
A Practitioners Guide to Optimizing Response
Time

Optimizing Oracle Performance
Cary Millsap
with Jeff Holt
OReilly
www.hotsos.com

15
Another book also recommended by Cary Millsap

The Goal A Process of Ongoing Improvement
Eliyahu Goldratt, Jeff Cox

16
Identify your bottlenecks

Performance Tuning is a search for lost time.
Time lost at a bottleneck is not just time lost
at a bottleneck, it affects the whole system.
If it isnt a problem, or it isnt going to be a
problem, then dont tune it.

17
Metrics

Users
Often very useful, but not always 100 reliable
Webserver
Application Server
Batch scheduling software

18
Sources of metrics
Proxy Server Access Log
Tuxedo Service Trace
Oracle SQLTrace
Tuxedo tmadmin script
Webserver Access Log
19
Webserver 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
2003-12-01 094438 0.192 726 10.1.37.148 10.1.37.
148 GET 200 /psp/f84dev/EMPLOYEE/ERP/c/REQUISITION
_ITEMS.REQUISITIONS.GBL FolderMYFAVORITES
2003-12-01 094438 0.312 4506 10.1.37.148 10.1.37
.148 GET 200 /psc/f84dev/EMPLOYEE/ERP/s/WEBLIB_PT_
NAV.ISCRIPT1.FieldFormula.IScript_PT_NAV_INFRAME c
1h2bwtoAlFUliqGxwwyIRXz9HzFApegKeFolderMYFAVOR
ITESPortalActualURLhttp3a2f2fxxx.com2fpsc2f
f84dev2fEMPLOYEE2fERP2fc2fREQUISITION_ITEMS.RE
QUISITIONS.GBL3fFolder3dMYFAVORITESPortalConten
tURLhttp3a2f2fxxx.com2fpsc2ff84dev2fEMPLOYE
E2fERP2fc2fREQUISITION_ITEMS.REQUISITIONS.GBLP
ortalContentProviderERPPortalRegistryNameEMPLOY
EEPortalServletURIhttp3a2f2fxxx.com2fpsp2ff
84dev2fPortalURIhttp3a2f2fxxx.com2fpsc2ff8
4dev2fPortalHostNodeERPPortalIsPagelettrueNo
Crumbsyes

20
Longest http conversations
21
So what should I SQL trace?

If I know which business transactions are my
bottleneck
and if I understand the structure of the
application in question
then I can determine which session I should trace.

22
What is SQL trace?

Session or database level
Sessions shadow process writes to a text file in
user_dump_dest.
Trace file contains
User and recursive SQL statements
Execution plan, phyiscal logical reads
Timing information
Wait and bind information (optional)

23
What is SQL trace?

First appeared in Oracle 6.
More instrumentation added at each release.
Not friendly format, can be read by humans.
And sometimes that is necessary
Usually process it with tkprof

24
Initialisation parameters

timed_statistics TRUE
user_dump_dest 'ltdirectory namegt'
max_dump_file_size ltsizegt
_trace_files_public TRUE
trace_file_identifier 'ltstringgt'

25
timed_statistics TRUE

You must set this initialisation variable to true
otherwise you wont get any timing information
anywhere in the database
including the SQL trace files
Low overhead
Always set it true

26
max_dump_file_size

Be careful that your trace files are not
truncated.
look at tail for message
DUMP FILE SIZE IS LIMITED
Your file may be truncated prior to the point of
interest.
Parameter expressed in O/S blocks, Kb, or Mb
Dynamic parameter from Oracle 9.x

27
_trace_files_public TRUE

This parameter controls the OS permission of the
trace file.
Setting it true allows the trace file to be read
outside the DBA group
Not dynamically alterable.
Consider security issue.

28
tracefile_identifier ltstringgt

Set at init.ora or setting level
Available from Oracle 8.1.7
Trace file identifier string appended to name of
trace file
Can alter after starting trace, and so get two
trace files.
Do not put space ( ) or hyphen (-) in the
identifier. You get an invalid file error.

29
tracefile_identifier ltstringgt

ALTER SESSION SET TRACE_FILE_IDENTIFIER
nVision_Report_NVSRUN_159
/u01/app/oracle/admin/F84SP1/udump/f84sp1_ora_4177
6_nVision_Report_NVSRUN_159.trc

30
How to enable SQL trace

From UKOUG2002
Advanced Oracle Diagnostics
Julian Dyke
www.juliandyke.com
Chair of UKOUG RAC SIG
10 methods of enabling trace information in Oracle

31
How to enable SQL trace

ALTER SESSION SET EVENTS '10046 trace name
context forever, level ltngt'

32
How to enable SQL trace

At instance level
Enable SQL trace for instance
sql_trace TRUE
or
Enable SQLtrace with binds for instance
event '10046 trace name context forever, level
4'

33
How to disable SQL trace

SQL Trace parameter cannot be altered directly
--Enable SQL trace for instance
ALTER SYSTEM SET EVENTS'10046 trace name context
forever, level 1
or
--Disable trace for instance
ALTER SYSTEM SET EVENTS'10046 trace name context
off'

34
How to enable SQL trace

Either
--Enable SQL trace for instance
ALTER SYSTEM SET SQL_TRACETRUE
or
--Disable trace for instance
ALTER SYSTEM SET SQL_TRACEFALSE

35
How to enable SQL trace

Either
--Enable SQL trace for session
ALTER SESSION SET SQL_TRACETRUE
or
--Disable trace for session
ALTER SESSION SET SQL_TRACEFALSE

36
How to enable SQL trace

In current session with supplied PL/SQL
procedures
--Enable SQL trace for session
DBMS_SESSION.SET_SQL_TRACE
(
FLAG BOOLEAN -- TRUE to enable -- FALSE to
disable
)

37
How to enable SQL trace

In current session
--Enable SQL trace for session
DBMS_SUPPORT.START_TRACE
(
WAITS BOOLEAN, -- Include waits (default FALSE)
BINDS BOOLEAN -- Include binds (default FALSE)
)
--Disable SQL Trace for session
DBMS_SUPPORT.STOP_TRACE

38
How to enable SQL trace

In another session
DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION
(
SI NUMBER, -- SID SE NUMBER, -- Serial
Number
SQL_TRACE BOOLEAN -- TRUE to enable --
FALSE to disable
)
SID and SERIAL from VSESSION.

39
How to enable SQL trace

In another session
DBMS_SUPPORT.START_TRACE_IN_SESSION
(
SI NUMBER, -- SID SE NUMBER, --
Serial Number (can be 0)
WAITS BOOLEAN, -- Include waits (default FALSE)
BINDS BOOLEAN -- Include binds (default
FALSE)
)

40
How to disable SQL trace

In another session
DBMS_SUPPORT.STOP_TRACE_IN_SESSION
(
SI NUMBER, -- SID SE NUMBER, --
Serial Number (can be 0)
)

41
How to enable SQL trace

Set event in another session
DBMS_SYSTEM.SET_EV
(
SI NUMBER, -- SID SE NUMBER, -- Serial Number
(can be 0)
EV NUMBER, -- Event Number e.g. 10046 LE
NUMBER, -- Level e.g. 4 NM VARCHAR2 -- Action
Name can be '
)
Disable with level 0

42
Using logon triggers to enable SQL trace

Login trigger to trace from the very beginning.
CREATE OR REPLACE TRIGGER sys.trace_logon_sysadm
AFTER LOGON ON sysadm.schema
BEGIN
sys.dbms_session.set_sql_trace(true)
END
/

43
Using triggers to enable SQL trace (i)

Trigger fired by starting process.
CREATE OR REPLACE TRIGGER sysadm.set_trace
AFTER 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','Crystal','nVision-Report','SQR
Process','SQR Report','SQR Report For WF
Delivery')
--AND new.prcsname GPPDPRUN
AND new.begindttm lt TO_DATE('200312031800','YYYYM
MDDHH24MI'))

44
Using triggers to enable SQL trace (ii)

BEGIN
EXECUTE IMMEDIATE 'ALTER SESSION SET
TIMED_STATISTICS TRUE'
EXECUTE IMMEDIATE 'ALTER SESSION SET
MAX_DUMP_FILE_SIZE UNLIMITED'
EXECUTE IMMEDIATE 'ALTER SESSION SET
TRACEFILE_IDENTIFIER '''
translate(new.prcstype,' -','__')'_'
translate(new.prcsname,' -','__')'_'
new.prcsinstance''''
EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS
''10046 trace name context forever, level 8'''
END
/

45
Other Events

Other write additional information to trace file
10128 Partition Elimination
10053 CBO Analysis
10104 Hash Activity
10032 Sort Statistics
10033 Sort I/O
10391 Parallel Slave

46
What is in the SQL trace file

See Metalink Note 39817.1 for details of trace
file structure

47
SQL trace file sections

Trace Sections
DBMS_APPLICATION_INFO settings
Cursors
Operations
Parse, exec, fetch, (sort) unmap
Errors
Stat
Execution Plans
Xctend
End of transaction

48
SQL trace file sections

With event 10046
Binds
Waits
Timings
centisecond timings (Oracle 7 8)
microsecond from Oracle 9

49
SQL trace file contents

/u01/app/oracle/admin/F84SP1/udump/f84sp1_ora_4177
6_nVision_Report_NVSRUN_159.trc
Oracle9i Enterprise Edition Release 9.2.0.1.0 -
64bit Production
JServer Release 9.2.0.1.0 - Production
ORACLE_HOME /u01/app/oracle/product/9.2.0
System name AIX
Node name xxxxxxxxx
Release 3
Version 4
Machine 0000C6BF4C00
Instance name F84SP1
Redo thread mounted by this instance 1
Oracle process number 28
Unix process pid 41776, image oracle_at_xxxxxxxxx
(TNS V1-V3)

50
SQL trace file contents

PARSING IN CURSOR 3 len58 dep0 uid24 oct3
lid24 tim1045288408856870 hv2952492898
ad'3b36970'
SELECT VERSION FROM PSVERSION WHERE
OBJECTTYPENAME 'SYS'
END OF STMT
PARSE 3c0,e1836,p0,cr0,cu0,mis1,r0,dep0,
og4, tim1045288408856862
EXEC 3c0,e80,p0,cr0,cu0,mis0,r0,dep0,og
4, tim1045288408857230
WAIT 3 nam'SQLNet message to client' ela 3
p11413697536 p21 p30
FETCH 3c0,e75,p0,cr2,cu0,mis0,r1,dep0,og
4, tim1045288408857420
WAIT 3 nam'SQLNet message from client' ela
47544 p11413697536 p21 p30
STAT 3 id1 cnt1 pid0 pos1 obj31453
op'TABLE ACCESS BY INDEX ROWID PSVERSION '
STAT 3 id2 cnt1 pid1 pos1 obj31454
op'INDEX UNIQUE SCAN PS_PSVERSION '

51
tkprof

Oracle supplied utility
Processes SQL trace files
Provides a easy to read report
Timings
Sorted by CPU or Elapsed Timings
Wait analysis from Oracle 9
Even on Oracle 8 trace!
Execution plans
Aggregate identical statements

52
tkprof sample

SELECT VERSION
FROM
PSVERSION WHERE OBJECTTYPENAME 'SYS'
call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 1 0.00 0.00 0
0 0 0
Execute 1 0.00 0.00 0
0 0 0
Fetch 1 0.00 0.00 0
2 0 1
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 3 0.00 0.00 0
2 0 1
Misses in library cache during parse 1
Optimizer goal CHOOSE
Parsing user id 24
Rows Row Source Operation
------- -----------------------------------------
----------

53
Row source statistics

From Oracle 9.2.0.2
Added to SQL Trace stat line
Appears in tkprof output
Performance overhead
See BQFTH in Oracle Scene 16
Oracle Bug 3009359

54
Row source statistics

SELECT A.START_DATE, A.STOP_DATE
FROM
PS_X_PYE_OVRD_ET A WHERE A.EMPLID 1 AND
A.EMPL_RCD 2 AND A.PIN_NUM
3 AND A.START_DATElt 4 AND A.STOP_DATEgt 5
AND A.START_DATElt 6
ORDER BY A.START_DATE DESC
call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 1 0.02 0.17 0
0 0 0
Execute 116759 20.76 40.24 0
0 0 0
Fetch 116759 25.60 88.40 1910
440408 0 89622
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 233519 46.38 128.81 1910
440408 0 89622

55
Row source statistics

Rows Row Source Operation
------- -----------------------------------------
----------
89622 SORT ORDER BY
(cr440408 r1910 w0 time72942929 us)
89622 PARTITION RANGE SINGLE PARTITION KEY
KEY
(cr440408 r1910 w0 time58756548 us)
89622 TABLE ACCESS BY LOCAL INDEX ROWID
OBJ(165144) PARTITION KEY KEY
(cr440408 r1910 w0 time57904868 us)
89622 INDEX RANGE SCAN DESCENDING
OBJ(166035) PARTITION KEY KEY
(cr350786 r451 w0 time20700497 us)
(object id 166035)

56
How to tune with tkprof

Identify your bottlenecks
Decide what to trace
Enable SQL trace
Tkprof
Sort(fchela,exeela,prsela)
Waitsyes
Print10
Explainltconnect stringgt

57
Example 1 SQL Problem

You have traced your process
you run tkprof
And at the top of the report you have a big block
of SQL.
What do you do next?

58
SQL statement

INSERT INTO PS_PP_CUST_TMP2 ( PROCESS_INSTANCE,
DEPOSIT_BU, DEPOSIT_ID,
PAYMENT_SEQ_NUM, CUST_ID, PAYMENT_AMT,
PAYMENT_DT, PP_METHOD, SETID,
SUBCUST_QUAL1, SUBCUST_QUAL2, PP_HOLD,
PP_MET_SW, PAYMENT_CURRENCY )
SELECT DISTINCT P.PROCESS_INSTANCE,
P.DEPOSIT_BU, P.DEPOSIT_ID,
P.PAYMENT_SEQ_NUM, C.CUST_ID, P.PAYMENT_AMT,
P.PAYMENT_DT, O.PP_METHOD,
O.SETID, C.SUBCUST_QUAL1, C.SUBCUST_QUAL2,
O.PP_HOLD, 'N',
P.PAYMENT_CURRENCY FROM PS_CUST_OPTION O,
PS_ITEM I, PS_CUSTOMER C,
PS_SET_CNTRL_REC S, PS_PAYMENT_ID_ITEM X,
PS_PP_PAYMENT_TMP P WHERE
P.PROCESS_INSTANCE 212 AND S.RECNAME
'CUSTOMER' AND S.SETID
C.SETID AND S.SETCNTRLVALUE
I.BUSINESS_UNIT AND I.CUST_ID
C.CUST_ID AND I.ITEM_STATUS 'O' AND
O.SETID C.REMIT_FROM_SETID
AND O.CUST_ID C.REMIT_FROM_CUST_ID AND
O.EFFDT ( SELECT
MAX(Z.EFFDT) FROM PS_CUST_OPTION Z
WHERE Z.SETID
O.SETID AND Z.CUST_ID
O.CUST_ID
AND Z.EFF_STATUS 'A'
AND Z.EFFDT lt
P.PAYMENT_DT ) AND O.PP_METHOD ltgt ' '
AND P.DEPOSIT_BU
X.DEPOSIT_BU AND P.DEPOSIT_ID
X.DEPOSIT_ID AND P.PAYMENT_SEQ_NUM
X.PAYMENT_SEQ_NUM AND X.REF_QUALIFIER_CODE
'I' AND X.REF_VALUE
I.ITEM

59
Statistics

count number of times OCI procedure was
executed
cpu cpu time in seconds executing
elapsed elapsed time in seconds executing
disk number of physical reads of buffers
from disk
query number of buffers gotten for
consistent read
current number of buffers gotten in current
mode (usually for update)
rows number of rows processed by the fetch
or execute call
call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 1 0.31 0.33 4
0 4 0
Execute 1 156.61 160.23 164769
3981545 0 0
Fetch 0 0.00 0.00 0
0 0 0
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 2 156.92 160.56 164773
3981545 4 0

60
Execution plan (from stat lines)

Rows Execution Plan
------- -----------------------------------------
----------
0 INSERT STATEMENT GOAL CHOOSE
0 SORT (UNIQUE)
0 FILTER
0 NESTED LOOPS
8 NESTED LOOPS
1000040 NESTED LOOPS
360 NESTED LOOPS
10 NESTED LOOPS
10 TABLE ACCESS BY INDEX ROWID
PS_PP_PAYMENT_TMP
11 INDEX (RANGE SCAN) (object id
9329)
20 INDEX (RANGE SCAN) OF (object id
8105)
360 TABLE ACCESS (BY INDEX ROWID) OF
'PS_SET_CNTRL_REC'
370 INDEX (RANGE SCAN) OF (object id
12020)
1000040 TABLE ACCESS (BY INDEX ROWID) OF
'PS_CUSTOMER'
1000400 INDEX (RANGE SCAN) OF (object id
4751)
1000048 INDEX (RANGE SCAN) OF 'PSITEM'
(NON-UNIQUE)
8 TABLE ACCESS (BY INDEX ROWID) OF
'PS_CUST_OPTION'

61
Execution plan (if you connect tkprof to the
database)

Rows Execution Plan
------- -----------------------------------------
----------
0 INSERT STATEMENT GOAL CHOOSE
0 SORT (UNIQUE)
0 FILTER
0 NESTED LOOPS
8 NESTED LOOPS
1000040 NESTED LOOPS
360 NESTED LOOPS
10 NESTED LOOPS
10 TABLE ACCESS (BY INDEX ROWID) OF
'PS_PP_PAYMENT_TMP'
11 INDEX (RANGE SCAN) OF
'PSAPP_PAYMENT_TMP'
(NON-UNIQUE)
20 INDEX (RANGE SCAN) OF
'PSAPAYMENT_ID_ITEM'
(NON-UNIQUE)
360 TABLE ACCESS (BY INDEX ROWID) OF
'PS_SET_CNTRL_REC'
370 INDEX (RANGE SCAN) OF
'PSBSET_CNTRL_REC'
(NON-UNIQUE)

62
1. Make the statement readable

SELECT DISTINCT P.PROCESS_INSTANCE, P.DEPOSIT_BU,
P.DEPOSIT_ID,
P.PAYMENT_SEQ_NUM, C.CUST_ID, P.PAYMENT_AMT,
P.PAYMENT_DT, O.PP_METHOD,
O.SETID, C.SUBCUST_QUAL1, C.SUBCUST_QUAL2,
O.PP_HOLD, 'N',
P.PAYMENT_CURRENCY
FROM PS_CUST_OPTION O, PS_ITEM I, PS_CUSTOMER C,
PS_SET_CNTRL_REC S, PS_PAYMENT_ID_ITEM X,
PS_PP_PAYMENT_TMP P
WHERE P.PROCESS_INSTANCE 212
AND S.RECNAME 'CUSTOMER'
AND S.SETID C.SETID
AND S.SETCNTRLVALUE I.BUSINESS_UNIT
AND I.CUST_ID C.CUST_ID
AND I.ITEM_STATUS 'O'
AND O.SETID C.REMIT_FROM_SETID
AND O.CUST_ID C.REMIT_FROM_CUST_ID
AND O.EFFDT ( SELECT MAX(Z.EFFDT)
FROM PS_CUST_OPTION Z
WHERE Z.SETID O.SETID
AND Z.CUST_ID O.CUST_ID
AND Z.EFF_STATUS 'A'

63
2. Start to draw the query
64
3. Put the joins in
65
4. Get the order from the plan

0 FILTER
0 NESTED LOOPS
8 NESTED LOOPS
1000040 NESTED LOOPS
360 NESTED LOOPS
10 NESTED LOOPS
10 (1)TABLE ACCESS (BY INDEX ROWID)
OF
'PS_PP_PAYMENT_TMP'
11 INDEX (RANGE SCAN) OF
'PSAPP_PAYMENT_TMP'
(NON-UNIQUE)
20 (2)INDEX (RANGE SCAN) OF
'PSAPAYMENT_ID_ITEM'
(NON-UNIQUE)
360 (3)TABLE ACCESS (BY INDEX ROWID)
OF 'PS_SET_CNTRL_REC'
370 INDEX (RANGE SCAN) OF
'PSBSET_CNTRL_REC'
(NON-UNIQUE)
1000040 (4)TABLE ACCESS (BY INDEX ROWID)
OF 'PS_CUSTOMER'
1000400 INDEX (RANGE SCAN) OF
'PSCUSTOMER' (NON-UNIQUE)
1000048 (5)INDEX (RANGE SCAN) OF 'PSITEM'
(NON-UNIQUE)
8 (6)TABLE ACCESS (BY INDEX ROWID) OF
'PS_CUST_OPTION'

66
5. Put the order in the diagram
67
6. This time, the answer is an index

CREATE INDEX PSBITEM ON PS_ITEM
(ITEM,
CUST_ID,
BUSINESS_UNIT,
ITEM_STATUS)
TABLESPACE PSINDEX
STORAGE (INITIAL 10K NEXT 98K MAXEXTENTS 110
PCTINCREASE 0)
/

68
New execution order
69
Statistics

Before
call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 1 0.31 0.33 4
0 4 0
Execute 1 156.61 160.23 164769
3981545 0 0
Fetch 0 0.00 0.00 0
0 0 0
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 2 156.92 160.56 164773
3981545 4 0
After
call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 1 0.35 2.56 3
0 3 0
Execute 1 0.03 0.05 38
289 3 0
Fetch 0 0.00 0.00 0
0 0 0
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 2 0.38 2.61 41
289 6 0

70
Example 2 Wait Events

How do you know its not the database?
Event 10046,8 enable wait information.

71
CPU v- elapsed time

INSERT /GPPRDMGR_I_ACUM/ INTO PS_GP_RSLT_ACUM
(CAL_RUN_ID ,EMPLID ,EMPL_RCD
,GP_PAYGROUP ,CAL_ID ,RSLT_SEG_NUM ,PIN_NUM
,EMPL_RCD_ACUM ,ACM_FROM_DT ,
ACM_THRU_DT ,USER_KEY1 ,USER_KEY2 ,USER_KEY3
,USER_KEY4 ,SLICE_BGN_DT ,
SLICE_END_DT ,COUNTRY ,ACM_TYPE ,ACM_PRD_OPTN
,CALC_RSLT_VAL ,CALC_VAL ,
USER_ADJ_VAL ,PIN_PARENT_NUM ,CORR_RTO_IND )
VALUES
(1,2,3,4,5,6,7,8,9,10,11,12,13,14,1
5,16,17,18,19,20,21,
22,23,24)
call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 1 0.00 0.00 0
0 0 0
Execute 22510 73.30 1269.24 31542
45040 503607 558966
Fetch 0 0.00 0.00 0
0 0 0
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 22511 73.30 1269.24 31542
45040 503607 558966

72
Wait events report discrepancy

Elapsed times include waiting on following
events
Event waited on Times Max.
Wait Total Waited
----------------------------- Waited
---------- ------------
SQLNet more data from client 27495
0.56 1036.26
db file sequential read 31542
0.97 148.99
SQLNet message from client 22510
0.44 80.41
SQLNet message to client 22510
0.01 0.08
latch free 5
0.02 0.08
free buffer waits 19
1.02 4.74
buffer busy waits 1
0.00 0.00
log file switch completion 1
0.06 0.06

73
After resolving network problem

call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 1 0.00 0.00 0
0 0 0
Execute 22264 103.07 113.04 2521
86624 553966 662676
Fetch 0 0.00 0.00 0
0 0 0
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 22265 103.07 113.04 2521
86624 553966 662676
Event waited on Times Max.
Wait Total Waited
----------------------------- Waited
---------- ------------
SQLNet more data from client 29138
0.47 6.69
SQLNet message from client 22264
0.47 88.84

74
Example 3 Waits events

UPDATE /GPPDPDM4_U_TRIGGER/ PS_GP_SEG_TRGR SET
CAL_RUN_ID 1
WHERE
TRGR_EFFDTgt2 AND TRGR_EFFDTlt3 AND EMPLID4
AND COUNTRY5 AND
SEG_TRGR_STATUS'A' AND CAL_RUN_ID' ' AND
(EMPL_RCD6 OR SEG_TRGR_LVL'E')
AND TRGR_EVENT_ID IN (SELECT SEC.TRGR_EVENT_ID
FROM PS_GP_SEG_EVT SEC
WHERE SEC.SEG_TYPE'P' AND SEC.COUNTRY7 )
call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 5858 0.57 0.51 0
0 0 0
Execute 27973 7.60 1989.00 1630
95825 662 645
Fetch 0 0.00 0.00 0
0 0 0
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 33831 8.17 1989.52 1630
95825 662 645

75
Wait Events

Elapsed times include waiting on following
events
Event waited on Times Max. Wait
Total Waited
--------------------------- Waited ----------
------------
SQLNet message to client 27973 0.00
0.05
SQLNet message from client 27973 1.34
99.10
db file sequential read 1630 0.27
8.67
enqueue 658 3.34
1973.10
latch free 2 0.00
0.00

76
Example 4 Idle wait?

SQLNet message from client
Often call an idle wait
It means that the database is idle
What is a batch process?

77
What is a batch process?

It is a process that runs for a period of time
without waiting for user input.
So if the database is idle then the client
process must be busy.
SQLNet message from client
Application busy time

78
Summary at bottom of report

Active process making lots of calls to the
database
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk
query current rows
------- ------ -------- ---------- ----------
---------- ---------- ----------
Parse 12197 3.85 4.50 621
25979 0 0
Execute 870343 537.36 750.89 70625
18372702 2047141 2657717
Fetch 710951 405.99 917.94 229999
10341004 73 3030039
------- ------ -------- ---------- ----------
---------- ---------- ----------
total 1593491 947.20 1673.34 301245
28739685 2047214 5687756

79
Is it the database?

Elapsed times include waiting on following
events
Event waited on Times Max.
Wait Total Waited
----------------------------- Waited
---------- ------------
SQLNet message to client 881285
0.01 1.68
SQLNet message from client 881285
1.22 2491.24
log file sync 185
1.01 28.18
SQLNet more data from client 62845
0.40 5.27
SQLNet more data to client 21008
0.00 1.54
db file sequential read 201760
2.39 451.60
direct path write 2632
0.67 49.76
direct path read 4034
0.71 28.97

80
Is it the database?

Perhaps this time we should look at the
application

81
Example 4 tkprof can mislead

Different plans
One from stat lines
How the statement was actually executed
One from explain plan for command
How the analyser might execute the statement in
the future on the basis of the current statistics
Some numbers can be nonsense

82
A simple SQL statement