Loading presentation...

Present Remotely

Send the link below via email or IM

Copy

Present to your audience

Start remote presentation

  • Invited audience members will follow you as you navigate and present
  • People invited to a presentation do not need a Prezi account
  • This link expires 10 minutes after you close the presentation
  • A maximum of 30 users can follow your presentation
  • Learn more about this feature in our knowledge base article

Do you really want to delete this prezi?

Neither you, nor the coeditors you shared it with will be able to recover it again.

DeleteCancel

Make your likes visible on Facebook?

Connect your Facebook account to Prezi and let your likes appear on your timeline.
You can change this under Settings & Account at any time.

No, thanks

Franck Pachot - Reading AWR/Statspack report

How to get the most relevant information from a Statspack or AWR report in just one hour. Focusing only on the details that can be tuned, and that can potentially improve the user response time. Reading and Understanding AWR reports
by

Franck Pachot

on 14 April 2016

Comments (0)

Please log in to add your comment.

Report abuse

Transcript of Franck Pachot - Reading AWR/Statspack report

AWR report - straight to the goal
Time Model
Timed Events
SQL execution
Average Active Sessions
Elapsed
time
DB Time
DB Time=
sum(user calls)
DB Time=
sum(resource usage)
CPU
Commit
Lock
Tablespaces
Datafiles
Wait histograms
Segments reads
Load profile
Instance stats
Segments
OS CPU
SQL by CPU
SQL by Gets
I/O
Huge difference between 2 disks
disk configuration to be checked
Can expect at least x2 (117->54)
117 millisecond per I/O call
one disk should provide 10x better
Disk reponse time is very bad
90% of I/O calls are > 8ms
1% between 1 and 4 seconds
SQL by Reads
48% of user response time
for CUSTOMER lookup
63% of total I/O to get the customer by PK
76% of database time is I/O
Only 1.5 physical read / execution
but 10000 executions over 15 minutes
Query is optimal:
Average IO call= 110 milliseconds
76% of DB time is User I/O wait
76% of DB time is User I/O wait
30000 single block reads during 15 min
13% of DB time is User CPU
DB CPU load: 0.65
DB CPU utilization: 16%
0.65/4=
608 / (15.64 * 60 ) =
One query responsible for 94% of DB CPU
That CPU part is 12.5% of DB response time
12.5% = 93.8% x 13.3% (CPU is 13.3% of DB TIME)
5000 data blocks needed
to retrieve only 14 rows
SQL ordered by Executions DB/Inst: ORCL/orcl Snaps: 330-336

Elapsed
Executions Rows Processed Rows per Exec Time (s) %CPU %IO SQL Id
------------ --------------- -------------- ---------- ------ ------ -----------
20,698 290,458 14.0 608.0 93.8 .0 0y1prvxqc2r
Module: Browse Products
SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, CATEGORY_ID, WEIG
HT_CLASS, WARRANTY_PERIOD, SUPPLIER_ID, PRODUCT_STATUS, LIST_PRICE, MIN_PRICE, C
ATALOG_URL, QUANTITY_ON_HAND FROM PRODUCTS, INVENTORIES WHERE PRODUCTS.PRODUCT_I
D = :B2 AND INVENTORIES.PRODUCT_ID = PRODUCTS.PRODUCT_ID AND ROWNUM < :B1
bad execution plan ?
Index on INVENTORIES (PRODUCT_ID)
Cost can probably divided by 1000 (5 instead of 5000)
For 94% of instance CPU
For 55% of server CPU
For 15% of DB TIME


WORKLOAD REPOSITORY SQL Report

Snapshot Period Summary

DB Name DB Id Instance Inst Num Startup Time Release RAC
------------ ----------- ------------ -------- --------------- ----------- ---
ORCL 1265891329 orcl 1 11-Mar-14 12:59 12.1.0.1.0 NO

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 330 11-Mar-14 15:18:53 40 5.4
End Snap: 336 11-Mar-14 15:34:32 55 4.7
Elapsed: 15.64 (mins)
DB Time: 76.48 (mins)

SQL Summary DB/Inst: ORCL/orcl Snaps: 330-336

Elapsed
SQL Id Time (ms)
------------- ----------
0y1prvxqc2ra9 608,018
Module: Browse Products
getProductDetails
SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, CATEGORY_ID, WEIG
HT_CLASS, WARRANTY_PERIOD, SUPPLIER_ID, PRODUCT_STATUS, LIST_PRICE, MIN_PRICE, C
ATALOG_URL, QUANTITY_ON_HAND FROM PRODUCTS, INVENTORIES WHERE PRODUCTS.PRODUCT_I
D = :B2 AND INVENTORIES.PRODUCT_ID = PRODUCTS.PRODUCT_ID AND ROWNUM < :B1

-------------------------------------------------------------

SQL ID: 0y1prvxqc2ra9 DB/Inst: ORCL/orcl Snaps: 330-336
-> 1st Capture and Last Capture Snap IDs
refer to Snapshot IDs witin the snapshot range
-> SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, CATEGOR...

Plan Hash Total Elapsed 1st Capture Last Capture
# Value Time(ms) Executions Snap ID Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1 357992151 608,018 2,0698 331 336
-------------------------------------------------------------


Plan 1(PHV: 357992151)
----------------------

Plan Statistics DB/Inst: ORCL/orcl Snaps: 330-336
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100

Stat Name Statement Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms) 608,018 29.4 13.3
CPU Time (ms) 570,074 27.5 93.7
Executions 20,698 N/A N/A
Buffer Gets 1.1322E+08 5,470.0 99.4
Disk Reads 0 0.0 0.0
Parse Calls 30 0.0 0.1
Rows 290,458 14.0 N/A
User I/O Wait Time (ms) 54 N/A N/A
Cluster Wait Time (ms) 0 N/A N/A
Application Wait Time (ms) 0 N/A N/A
Concurrency Wait Time (ms) 0 N/A N/A
Invalidations 0 N/A N/A
Version Count 4 N/A N/A
Sharable Mem(KB) 169 N/A N/A
-------------------------------------------------------------

Execution Plan
---------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 52 (100)| |
| 1 | COUNT STOPKEY | | | | | |
| 2 | NESTED LOOPS | | 14 | 5684 | 52 (0)| 00:00:01 |
| 3 | NESTED LOOPS OUTER | | 1 | 396 | 3 (0)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| PRODUCT_INFORMATION | 1 | 177 | 2 (0)| 00:00:01 |
| 5 | INDEX UNIQUE SCAN | PRODUCT_INFORMATION_PK | 1 | | 1 (0)| 00:00:01 |
| 6 | TABLE ACCESS BY INDEX ROWID| PRODUCT_DESCRIPTIONS | 1 | 219 | 1 (0)| 00:00:01 |
| 7 | INDEX UNIQUE SCAN | PRD_DESC_PK | 1 | | 0 (0)| |
| 8 | TABLE ACCESS FULL | INVENTORIES | 14 | 140 | 49 (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------------



Full SQL Text

SQL ID SQL Text
------------ -----------------------------------------------------------------
0y1prvxqc2ra SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, CA
ATEGORY_ID, WEIGHT_CLASS, WARRANTY_PERIOD, SUPPLIER_ID, PRODUCT_S
TATUS, LIST_PRICE, MIN_PRICE, CATALOG_URL, QUANTITY_ON_HAND FROM
PRODUCTS, INVENTORIES WHERE PRODUCTS.PRODUCT_ID = :B2 AND INVENTO
RIES.PRODUCT_ID = PRODUCTS.PRODUCT_ID AND ROWNUM < :B1

.
5000 commits had to wait for lgwr
Average wait: 33 milliseconds (i/o)
4% of DB time is log file sync
Short transactions, frequent commit
Too many commits
or too long i/o ?
commit time when user waits: 33ms on average
about 1/3 of commits have to wait (pl/sql batch nowait optimization)
Waited for locked rows
Most of waits are < 2 seconds
What was locked ?
4% of DB time is lock wait
Histogram
Search for that table in SQL section
Search for Select for update
Check Data Model
Locks on table PRODUCT_INFORMATION
Locking inventory is expected,
but probably not product description...
FOR UPDATE OF QUANTITY_ON_HAND
DB time / Elapsed
76.48 / 15.64 =
database load = 4.9

Same idea as 'CPU load' in unix
4.9 + 14.2 = about 19 user connected sessions
14.2 average inactive sessions
13327/(15.64 * 60) =
DB time > Elapsed Time:
several sessions were active on database concurrently

During 15 minutes, each session can use 15 minutes of database
4588.7/60=76 minutes
95% user calls
are SQL execution
76% User I/O
13% DB CPU
4% Log file sync
4% Row lock
Focus on DB Time
Navigate to root cause
Estimate expectations
Document each point







Once implemented compare
new report with expectations
95% of DB time have their SQL identified
'Timed events' or 'Foreground events':
CPU time
Wait events
DB CPU is time running in CPU (waiting in runqueue
not
included)
Wait events are system calls (including runqueue after system call)

solutions: review disks, move one datafile
solution: Fix index on inventories
solution: For scalability,
lock only required tables
(FOR UPDATE OF ...)
This is optimal for an OLTP application:
short transactions, frequent commits.
Quantify the gain expectation
Our goal is to have:
10ms average i/o
divide by 1000 the CPU usage on 571 seconds
db file sequential read is single block i/o
detail by tablespaces
detail by datafiles
Beyond averages: histograms
Detail by segments (tables, index,...)
Finally, by queries
Detail by Queries
logical reads and number of executions
Even if only 3% of response time currently, locks will prevent scalability
. Wait Event Histogram Detail (64 msec to 2 sec)DB/Inst: ORCL/orcl Snaps:
. % of Total Waits
. -----------------------------------------------
. Waits
. 64ms
. Event to 2s <32ms <64ms <1/8s <1/4s <1/2s <1s <2s >=2s
. -------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
. enq: TX - index contention 1 80.0 20.0
. enq: TX - row lock content 116 2.9 2.2 .7 8.6 9.4 24.5 38.1 13.7

Wait Event Histogram Detail (4 sec to 2 min)DB/Inst: ORCL/orcl Snaps: 330-33
.
. % of Total Waits
. -----------------------------------------------
. Waits
. 4s
. Event to 2m <2s <4s <8s <16s <32s < 1m < 2m >=2m
. -------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
. enq: TX - row lock content 19 86.3 11.5 2.2
. -------------------------------------------------------------
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 31,762 3,497 110 76.2 User I/O
DB CPU 608 13.3
log file sync 5,676 189 33 4.1 Commit
enq: TX - row lock contention 139 171 1229 3.7 Applicatio
control file sequential read 1,105 9 8 .2 System I/O
SQL ordered by Gets DB/Inst: ORCL/orcl Snaps: 330-336

Buffer Gets Elapsed
Gets Executions per Exec %Total Time (s) %CPU %IO SQL Id
----------- ----------- ------------ ------ ---------- ------ ------ -----------
1.13217E+08 20,698 5,470.0 99.4 608.0 93.8 .0 0y1prvxqc2r
Module: Browse Products
...
5 users 99% busy

or 10 users half idle

or...
What does it mean?
also called
Average Active Sessions
How many sessions ?
inactive
Always check if you have all statements
If unaccounted % DB time is high
most wait events are irrelevant
Always check Host CPU !
Here 85% idle is calculated from 8 CPUs
It's only 40% when related to the 4 cores
Cores
Load Average
Always compare to
http://www.dbi-services.com/index.php/blog/entry/sockets-cores-virtual-cpu-logical-cpu-hyper-threading-what-is-a-cpu-nowadays-1
of host cores
Host statistics
Take care of hyper-threading / SMT

BUSY_TIME = SYS_TIME+USER_TIME,
BUSY_TIME+IDLE_TIME= 15 minutes * 8 threads
8.2% is related to NUM_CPUs, it's 16.4% of cores
55.1% = DB CPU / BUSY_TIME
AWR/Statspack reports - Straight to the goal
13.04.2015
AWR/Statspack reports - Straight to the goal
13.04.2015
AWR/Statspack reports - Straight to the goal
13.04.2015
AWR/Statspack reports - Straight to the goal
13.04.2015
Core Message
@awrsqrpt.sql

SQL Id
-----------
0y1prvxqc2r
@ awrsqrpt.sql
No predicate section :(
Time Model Statistics DB/Inst: ORCL/orcl Snaps: 330-336
-> Total time in database user-calls (DB Time): 4588.7s
-> Statistics including the word "background" measure background process
time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name

Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 4,358.6 95.0
DB CPU 608.4 13.3
parse time elapsed 18.8 .4
hard parse elapsed time 15.7 .3
PL/SQL execution elapsed time 13.6 .3
connection management call elapsed time 8.3 .2
hard parse (sharing criteria) elapsed time 2.5 .1
hard parse (bind mismatch) elapsed time 2.1 .0
PL/SQL compilation elapsed time 1.7 .0
repeated bind elapsed time 0.0 .0
sequence load elapsed time 0.0 .0
DB time 4,588.7
background elapsed time 629.5
background cpu time 6.8
-------------------------------------------------------------
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 330 11-Mar-14 15:18:53 40 5.4
End Snap: 336 11-Mar-14 15:34:32 55 4.7
Elapsed: 15.64 (mins)
DB Time: 76.48 (mins)

Foreground Wait Events DB/Inst: ORCL/orcl Snaps: 330-336
Avg
%Time Total Wait wait Waits % DB
Event Waits -outs Time (s) (ms) /txn time
-------------------------- ------------ ----- ---------- ------- -------- ------

SQL*Net more data to clien 172 0 0 0 0.0 .0
SQL*Net message from clien 16,464 0 13,327 809 1.0

-------------------------------------------------------------

WORKLOAD REPOSITORY report for

DB Name DB Id Instance Inst Num Startup Time Release RAC
------------ ----------- ------------ -------- --------------- ----------- ---
ORCL 1265891329 orcl 1 11-Mar-14 12:59 12.1.0.1.0 NO

Host Name Platform CPUs Cores Sockets Memory(GB)
---------------- -------------------------------- ---- ----- ------- ----------
LTFRP01 Microsoft Windows x86 64-bit 8 4 1 3.93

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 330 11-Mar-14 15:18:53 40 5.4
End Snap: 336 11-Mar-14 15:34:32 55 4.7
Elapsed: 15.64 (mins)
DB Time: 76.48 (mins)
SQL ordered by Elapsed Time DB/Inst: ORCL/orcl Snaps: 330-336
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100
-> %Total - Elapsed Time as a percentage of Total DB time
-> %CPU - CPU Time as a percentage of Elapsed Time
-> %IO - User I/O Time as a percentage of Elapsed Time
-> Captured SQL account for 94.6% of Total DB Time (s): 4,589
-> Captured PL/SQL account for 94.5% of Total DB Time (s): 4,589

Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
2,312.5 6,944 0.33 50.4 25.0 72.9 147a57cxq3w5y
Module: JDBC Thin Client
BEGIN :1 := orderentry.browseproducts(:2 ,:3 ,:4 ); END;

1,992.0 10,640 0.19 43.4 .2 99.9 8dq0v1mjngj7t
Module: New Order
SELECT CUSTOMER_ID, CUST_FIRST_NAME, CUST_LAST_NAME, NLS_LANGUAGE, NLS_TERRITORY
, CREDIT_LIMIT, CUST_EMAIL, ACCOUNT_MGR_ID FROM CUSTOMERS WHERE CUSTOMER_ID = :B
2 AND ROWNUM

...
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Total Wait Wait % DB Wait
Event Waits Time (sec) Avg(ms) time Class
------------------------------ ----------- ---------- ------- ------ ----------
db file sequential read 31,762 3,497 110 76.2 User I/O
DB CPU 608 13.3
log file sync 5,676 189 33 4.1 Commit
enq: TX - row lock contention 139 171 1229 3.7 Applicatio
control file sequential read 1,105 9 8 .2 System I/O
Host CPU
~~~~~~~~ Load Average
CPUs Cores Sockets Begin End %User %System %WIO %Idle
----- ----- ------- --------- --------- --------- --------- --------- ---------
8 4 1 1.5 1.1 11.2 3.5 49.2 85.2
. Tablespace IO Stats DB/Inst: ORCL/orcl Snaps: 330-336
. -> ordered by IOs (Reads + Writes) desc
.
. Tablespace
. ------------------------------
. Av Av Av Av Buffer Av Buf
. Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
. -------------- ------- ------- ------- ------------ -------- ---------- -------
. SOE
. 28,368 30 117.3 1.0 5,444 6 79 0.8
. USERS
. 2,145 2 69.8 1.0 3,452 4 0 0.0
. SYSAUX
. 506 1 17.5 1.1 959 1 0 0.0
. SYSTEM
. 812 1 10.0 1.0 21 0 8 0.0
. UNDOTBS1
. 2 0 145.0 1.0 215 0 35 0.0
. TEMP
. 4 0 15.0 1.0 10 0 0 0.0
. -------------------------------------------------------------
File IO Stats DB/Inst: ORCL/orcl Snaps: 330-336
-> ordered by Tablespace, File

Tablespace Filename
------------------------ ----------------------------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------- ------- ------------ -------- ---------- -------
SOE C:\ORA\ORADATA\ORCL\SOE01.DBF
14,679 16 54.5 1.0 3,434 4 48 1.3
SOE D:\ORA\ORADATA\ORCL\SOE02.DBF
13,689 15 184.6 1.0 2,010 2 31 0.0
SYSAUX C:\ORA\ORADATA\ORCL\SYSAUX01.DBF
506 1 17.5 1.1 959 1 0 0.0
SYSTEM C:\ORA\ORADATA\ORCL\SYSTEM01.DBF
812 1 10.0 1.0 21 0 8 0.0
TEMP C:\ORA\ORADATA\ORCL\TEMP01.DBF
4 0 15.0 1.0 10 0 0 N/A
UNDOTBS1 C:\ORA\ORADATA\ORCL\UNDOTBS01.DBF
2 0 145.0 1.0 215 0 35 0.0
USERS C:\ORA\ORADATA\ORCL\USERS01.DBF
2,145 2 69.8 1.0 3,452 4 0 0.0
-------------------------------------------------------------
Wait Event Histogram . DB/Inst: ORCL/orcl Snaps: 330-336

% of Waits
-----------------------------------------------
Total
Event Waits <1ms <2ms <4ms <8ms <16ms <32ms <=1s >1s
-------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
...
db file sequential read 31.8K 2.3 .3 .5 6.2 19.8 22.6 46.8 1.6
enq: TX - row lock content 139 .7 .7 1.4 45.3 51.8
log file sync 5689 39.9 14.6 15.3 6.1 2.5 3.4 18.2 .0
-------------------------------------------------------------


Wait Event Histogram Detail (4 sec to 2 min)DB/Inst: ORCL/orcl Snaps: 330-33

% of Waits
-----------------------------------------------
Waits
4s
Event to 2m <2s <4s <8s <16s <32s < 1m < 2m >=2m
-------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
db file sequential read 85 99.7 .2 .0
enq: TX - row lock content 19 86.3 11.5 2.2
-------------------------------------------------------------
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Total Wait Wait % DB Wait
Event Waits Time (sec) Avg(ms) time Class
------------------------------ ----------- ---------- ------- ------ ----------
db file sequential read 31,762 3,497 110 76.2 User I/O
DB CPU 608 13.3
log file sync 5,676 189 33 4.1 Commit
enq: TX - row lock contention 139 171 1229 3.7 Applicatio
control file sequential read 1,105 9 8 .2 System I/O
Segments by Physical Reads DB/Inst: ORCL/orcl Snaps: 330-336
-> Total Physical Reads: 31,947
-> Captured Segments account for 95.5% of Total

Tablespace Subobject Obj. Physical
Owner Name Object Name Name Type Reads %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
SOE SOE CUSTOMERS TABLE 10,352 32.40
SOE SOE CUSTOMERS_PK INDEX 9,620 30.11
SOE SOE ORDERS TABLE 2,145 6.71
SOE USERS ORD_WAREHOUSE_IX INDEX 2,145 6.71
** UNAVAIL ** UNAVAIL ** UNAVAILABLE ** AILABLE ** UNDEF 1,879 5.88
-------------------------------------------------------------
SQL ordered by Reads DB/Inst: ORCL/orcl Snaps: 330-336
-> %Total - Physical Reads as a percentage of Total Disk Reads
-> %CPU - CPU Time as a percentage of Elapsed Time
-> %IO - User I/O Time as a percentage of Elapsed Time
-> Total Disk Reads: 31,947
-> Captured SQL account for 100.9% of Total

Physical Reads Elapsed
Reads Executions per Exec %Total Time (s) %CPU %IO SQL Id
----------- ----------- ---------- ------ ---------- ------ ------ -------------
15,798 10,640 1.5 49.5 1,992.0 .2 99.9 8dq0v1mjngj7t
Module: New Order
SELECT CUSTOMER_ID, CUST_FIRST_NAME, CUST_LAST_NAME, NLS_LANGUAGE, NLS_TERRITORY
, CREDIT_LIMIT, CUST_EMAIL, ACCOUNT_MGR_ID FROM CUSTOMERS WHERE CUSTOMER_ID = :B
2 AND ROWNUM < :B1
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 31,762 3,497 110 76.2 User I/O
DB CPU 608 13.3
WORKLOAD REPOSITORY report for

DB Name DB Id Instance Inst Num Startup Time Release RAC
------------ ----------- ------------ -------- --------------- ----------- ---
ORCL 1265891329 orcl 1 11-Mar-11 12:59 11.2.0.1.0 NO

Host Name Platform CPUs Cores Sockets Memory(GB)
---------------- -------------------------------- ---- ----- ------- ----------
LTFRP01 Microsoft Windows x86 64-bit 8 4 1 3.93

Instance CPU
~~~~~~~~~~~~
% of total CPU for Instance: 8.2
% of busy CPU for Instance: 55.1
%DB time waiting for CPU - Resource Mgr: 0.0

Operating System Statistics DB/Inst: ORCL/orcl Snaps: 330-336


Statistic Value End Value
------------------------- ---------------------- ----------------
...
BUSY_TIME 111,572
IDLE_TIME 640,189
SYS_TIME 26,197
USER_TIME 85,376
...
NUM_CPUS 8
NUM_CPU_CORES 4
NUM_CPU_SOCKETS 1
-------------------------------------------------------------
SQL ordered by CPU Time DB/Inst: ORCL/orcl Snaps: 330-336



CPU CPU per Elapsed
Time (s) Executions Exec (s) %Total Time (s) %CPU %IO SQL Id
---------- ------------ ---------- ------ ---------- ------ ------ -------------
578.8 6,944 0.08 95.1 2,312.5 25.0 72.9 147a57cxq3w5y
Module: JDBC Thin Client
BEGIN :1 := orderentry.browseproducts(:2 ,:3 ,:4 ); END;

570.1 20,698 0.03 93.7 608.0 93.8 .0 0y1prvxqc2ra9
Module: Browse Products
SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION, CATEGORY_ID, WEIG
HT_CLASS, WARRANTY_PERIOD, SUPPLIER_ID, PRODUCT_STATUS, LIST_PRICE, MIN_PRICE, C
ATALOG_URL, QUANTITY_ON_HAND FROM PRODUCTS, INVENTORIES WHERE PRODUCTS.PRODUCT_I
D = :B2 AND INVENTORIES.PRODUCT_ID = PRODUCTS.PRODUCT_ID AND ROWNUM < :B1
SQL> EXPLAIN PLAN for
SELECT PRODUCTS.PRODUCT_ID, PRODUCT_NAME, PRODUCT_DESCRIPTION,
CATEGORY_ID, WEIGHT_CLASS, WARRANTY_PERIOD, SUPPLIER_ID,
PRODUCT_STATUS, LIST_PRICE, MIN_PRICE, CATALOG_URL, QUANTITY_ON_HAND
FROM PRODUCTS, INVENTORIES WHERE PRODUCTS.PRODUCT_ID = :B2 AND
INVENTORIES.PRODUCT_ID = PRODUCTS.PRODUCT_ID AND ROWNUM < :B1
/
select * from table(dbms_xplan.display);

---------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 903 | 358K| 3060 (1)| 00:00:37 |
|* 1 | COUNT STOPKEY | | | | | |
| 2 | NESTED LOOPS | | 903 | 358K| 3060 (1)| 00:00:37 |
| 3 | NESTED LOOPS OUTER | | 1 | 396 | 3 (0)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| PRODUCT_INFORMATION | 1 | 177 | 2 (0)| 00:00:01 |
|* 5 | INDEX UNIQUE SCAN | PRODUCT_INFORMATION_PK | 1 | | 1 (0)| 00:00:01 |
| 6 | TABLE ACCESS BY INDEX ROWID| PRODUCT_DESCRIPTIONS | 1 | 219 | 1 (0)| 00:00:01 |
|* 7 | INDEX UNIQUE SCAN | PRD_DESC_PK | 1 | | 0 (0)| 00:00:01 |
|* 8 | TABLE ACCESS FULL | INVENTORIES | 903 | 9030 | 3057 (1)| 00:00:37 |
---------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

1 - filter(ROWNUM<TO_NUMBER(:B1))
5 - access("I"."PRODUCT_ID"=TO_NUMBER(:B2))
7 - access("D"."PRODUCT_ID"(+)=TO_NUMBER(:B2) AND
"D"."LANGUAGE_ID"(+)=SYS_CONTEXT('USERENV','LANG'))
8 - filter("INVENTORIES"."PRODUCT_ID"=TO_NUMBER(:B2))

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 31,762 3,497 110 76.2 User I/O
DB CPU 608 13.3
log file sync 5,676 189 33 4.1 Commit
Load Profile Per Second Per Transaction Per Exec Per Call
~~~~~~~~~~~~~~~ --------------- --------------- --------- ---------
DB Time(s): 4.9 0.3 0.05 0.15
DB CPU(s): 0.7 0.0 0.01 0.02
Background CPU(s): 0.0 0.0 0.00 0.00
Redo size (bytes): 36,961.6 2,128.9
Logical read (blocks): 121,370.5 6,990.8
Block changes: 346.9 20.0
Physical read (blocks): 34.0 2.0
Physical write (blocks): 17.6 1.0
Read IO requests: 36.3 2.1
Write IO requests: 27.6 1.6
Read IO (MB): 278.7 16.8
Write IO (MB): 144.4 8.6
IM scan rows: 0.0 0.0
Session Logical Read IM:
User calls: 32.3 1.9
Parses (SQL): 44.7 2.6
Hard parses (SQL): 12.0 0.7
Logons: 0.1 0.0
Executes (SQL): 105.8 6.1
Rollbacks: 0.0 0.0
Transactions: 17.4
Instance Activity Stats DB/Inst: ORCL/orcl Snaps: 330-336
-> Ordered by statistic name

Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
...
user calls 30,310 32.3 1.9
user commits 16,296 17.4 1.0
user rollbacks 1 0.0 0.0
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 31,762 3,497 110 76.2 User I/O
DB CPU 608 13.3
log file sync 5,676 189 33 4.1 Commit
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 31,762 3,497 110 76.2 User I/O
DB CPU 608 13.3
log file sync 5,676 189 33 4.1 Commit
enq: TX - row lock contention 139 171 1229 3.7 Applicatio
Segments by Row Lock Waits DB/Inst: ORCL/orcl Snaps: 330-336
-> % of Capture shows % of row lock waits for each top segment compared
-> with total row lock waits for all segments captured by the Snapshot

Row
Tablespace Subobject Obj. Lock % of
Owner Name Object Name Name Type Waits Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
SOE SOE PRODUCT_INFORMATION TABLE 138 77.53
** UNAVAIL ** UNAVAIL ** UNAVAILABLE ** AILABLE ** UNDEF 7 3.93
SYS SYSAUX WRH$_EVENT_HISTOGRAM 891329_304 INDEX 6 3.37
SYS SYSAUX WRH$_LATCH_PK 891329_304 INDEX 6 3.37
SYS SYSAUX WRI$_ADV_PARAMETERS_ INDEX 3 1.69
-------------------------------------------------------------

Elapsed
Executions Rows Processed Rows per Exec Time (s) %CPU %IO SQL Id
------------ --------------- -------------- ---------- ------ ------ -----------
1,861 1,688 0.9 0.2 .0 .1 45c5h3832ja
Module: New Order
SELECT QUANTITY_ON_HAND FROM PRODUCT_INFORMATION P, INVENTORIES I WHERE I.PRODUC
T_ID = :B2 AND I.PRODUCT_ID = P.PRODUCT_ID AND I.WAREHOUSE_ID = :B1 FOR UPDATE
AWR/Statspack reports - Straight to the goal
13.04.2015
Findings summary and recommendations
Gain: high,
Effort: medium
Gain: medium,
Effort: medium
Gain: scalability,
Effort: medium
----- 317
Total DB Time: 4588
76% DB Time
13% DB Time
4% DB Time
4% DB Time
--- 38
--- 10
-> 1408 response time divided by 3
-> 838 response time divided by 5
Addressing the CPU only -> 4081 response time divided by 1.1 only
Any questions? Please do ask.
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Total Wait Wait % DB Wait
Event Waits Time (sec) Avg(ms) time Class
------------------------------ ----------- ---------- ------- ------ ----------
db file sequential read 31,762 3,497 110 76.2 User I/O
DB CPU 608 13.3
log file sync 5,676 189 33 4.1 Commit
enq: TX - row lock contention 139 171 1229 3.7 Applicatio
control file sequential read 1,105 9 8 .2 System I/O
>
>
>
>







>
Fix disk configuration



Fix index on INVENTORIES



commit is ok,
i/o will improve it anyway


change one SQL (for update of)

>



>



>



>

expectation: 10ms instead of 110ms



expectation: - 570 seconds of CPU







expectation: better scalability


That example is AWR,
could be done with Statspack as well
Report
Sections
DB Time
host CPU
findings
recommendations
expectation
Time
Model
Timed
Events
Statements by ...
SQL by ...
I/O by ...
Wait event histograms
Instance statistics
Report
Sections
DB Time
host CPU
findings
recommendations
expectation
Time
Model
Timed
Events
Franck Pachot
Interpreting AWR reports - straight to the Goal

>
>
http://awrrpt.pachot.net
Full transcript