Prezi

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 the manual

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

Interpreting AWR Report - Straight to the Goal

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 11 June 2014

Comments (0)

Please log in to add your comment.

Report abuse

Transcript of Interpreting AWR Report - Straight to the Goal

Time Model
Timed Events
SQL execution
Average Active Sessions
Elapsed
time
Database
time
Database load
User
Calls
System
resources
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)
. 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
. -------------------------------------------------------------
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:
Effort should be on I/O response time
if not possible, improve to do even less I/O on CUSTOMERS:
partitioning, IOT, CACHE, ...
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
. Top 5 Timed Foreground Events
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. 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
. Top 5 Timed Foreground Events
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. 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
13% of DB time is User CPU
DB CPU load: 0.65
DB CPU utilization: 8%
0.65/8=
608 / (15.64 * 60 ) =
15%=(111572/(111572+640189))
8.2% = load/cpu_count = (0.65 / 8 )
55.1% = DB CPU / BUSY_TIME
BUSY_TIME = SYS_TIME+USER_TIME
CPU utilization: 15% for whole system
Half of it (55%) for that instance
One query responsible for 94% of DB CPU
That CPU part is 12.5% of DB response time
(PL/SQL includes recursive SQL)
12.5% = 93.8% x 13.3% (CPU is 13.3% of DB TIME)
All details in awrsqrpt.sql
5000 data blocks needed
to retreive 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 ?
. 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))
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-11 12:59 11.2.0.1.0 NO
.
. Snap Id Snap Time Sessions Curs/Sess
. --------- ------------------- -------- ---------
. Begin Snap: 330 11-Mar-11 15:18:53 40 5.4
. End Snap: 336 11-Mar-11 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
.
.
2000 bytes per transaction
5000 commits had to wait for lgwr
17 transactions per second
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 ?
1 wait every 3 commits
Remember number of waits:
average commit time: 12 ms
16296/5676 =
189/16296 =
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
. 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
. -------------------------------------------------------------
Locking inventory is expected,
but probably not product description...
FOR UPDATE OF QUANTITY_ON_HAND
Add index: inventories
Move one datafile
Create
one Index
Quick Wins:
on
INVENTORIES
commit is ok, disk i/o will improve that anyway
x 2 on 75% response time
outage: 1 hour
x 1000 on 13% response time
cost: 1 day (dev + test)
Change one SQL (add for update of)
Improves scalability
cost: 1 day (dev + test)
Review disk configuration
x 10 on 75% response time
workload: few days
Move one
Datafile
from D: to C:
on
INVENTORIES
Change
one Query
Long Term:
Review storage configuration
x 2 improvement
with small effort
x 10 improvement
DB time / Elapsed
76.48 / 15.64 =
database load = 4.9
(aka average active sessions)
Same idea as 'CPU load' in unix
4.9 + 14.2 = about 19 foreground (user) sessions
About 20 foreground processes
14.2 average inactive sessions
13327/(15.64 * 60) =
. Snap Id Snap Time Sessions Curs/Sess
. --------- ------------------- -------- ---------
. Begin Snap: 330 11-Mar-11 15:18:53 40 5.4
. End Snap: 336 11-Mar-11 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
...
. -------------------------------------------------------------
DB time > Elapsed Time:
several sessions were active on database concurrently
The AWR statistics have no meaning
when database instance is idle !
4588.7/60=76 minutes
95% of it for SQL execution
Goal: tune SQL queries
Database time is the time to answer user calls.
Database time
. 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

...
76% User I/O
13% DB CPU
4% Log file sync
4% Row lock
. 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
. -------------------------------------------------------------
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
. 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
. -------------------------------------------------------------
Focus only where potential improvement is significant

Get methodically from response time to root cause

Consider only relevant statistics

Can estimate the improvement

Present each point with:
- observation
- explanation
- solutions
- expected result
Unix: in CPU or waiting for CPU
Oracle: in CPU, waiting for CPU or waiting for system call (wait event)
Database load is fundamental
OS load is important as well:
high runqueue can inflate wait events
database load = average active sessions. We can calculate inactive sessions as well...
Why is database time so important ?
= sum(user response time)
= sum(CPU time + Wait time)
Time Model
Timed Events
95% of DB time have their SQL identified
but let's go to the resources involved before
Timed events: CPU or Wait events
Foreground: are involved in user response time
CPU is time running in CPU (not waiting in runqueue)
Wait events are system calls (or runqueue after system call)
runqueue between CPU are not detailed here (but are included in DBA time)
straight
to the goal

.
. 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
.
. Snap Id Snap Time Sessions Curs/Sess
. --------- ------------------- -------- ---------
. Begin Snap: 330 11-Mar-11 15:18:53 40 5.4
. End Snap: 336 11-Mar-11 15:34:32 55 4.7
. Elapsed: 15.64 (mins)
. DB Time: 76.48 (mins)
.
. Cache Sizes Begin End
. ~~~~~~~~~~~ ---------- ----------
. Buffer Cache: 656M 656M Std Block Size: 8K
. Shared Pool Size: 364M 364M Log Buffer: 5,408K
.
. 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
. Redo size: 36,961.6 2,128.9
. Logical reads: 121,370.5 6,990.8
. Block changes: 346.9 20.0
. Physical reads: 34.0 2.0
. Physical writes: 17.6 1.0
. User calls: 32.3 1.9
. Parses: 44.7 2.6
. Hard parses: 12.0 0.7
. W/A MB processed: 0.3 0.0
. Logons: 0.1 0.0
. Executes: 105.8 6.1
. Rollbacks: 0.0 0.0
. Transactions: 17.4
.
. Instance Efficiency Percentages (Target 100%)
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. Buffer Nowait %: 100.00 Redo NoWait %: 100.00
. Buffer Hit %: 99.97 In-memory Sort %: 100.00
. Library Hit %: 89.78 Soft Parse %: 73.18
. Execute to Parse %: 57.73 Latch Hit %: 98.84
. Parse CPU to Parse Elapsd %: 47.56 % Non-Parse CPU: 99.47
.
. Shared Pool Statistics Begin End
. ------ ------
. Memory Usage %: 65.31 66.68
. % SQL with executions>1: 95.87 46.73
. % Memory for SQL w/exec>1: 86.55 47.45
.
. Top 5 Timed Foreground Events
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. 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
. Host CPU (CPUs: 8 Cores: 4 Sockets: 1)
. ~~~~~~~~ Load Average
. Begin End %User %System %WIO %Idle
. --------- --------- --------- --------- --------- ---------
. 11.4 3.5 85.2
.
. 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
.
. Memory Statistics
. ~~~~~~~~~~~~~~~~~ Begin End
. Host Mem (MB): 4,027.5 4,027.5
. SGA use (MB): 1,048.0 1,048.0
. PGA use (MB): 129.6 155.2
. % Host Mem used for SGA+PGA: 29.24 29.87
.
. 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
. -------------------------------------------------------------
.
. Operating System Statistics DB/Inst: ORCL/orcl Snaps: 330-336
. -> *TIME statistic values are diffed.
. All others display actual values. End Value is displayed if different
. -> ordered by statistic type (CPU Use, Virtual Memory, Hardware Config), Name
.
. Statistic Value End Value
. ------------------------- ---------------------- ----------------
. AVG_BUSY_TIME 13,919
. AVG_IDLE_TIME 79,995
. AVG_SYS_TIME 3,242
. AVG_USER_TIME 10,640
. BUSY_TIME 111,572
. IDLE_TIME 640,189
. SYS_TIME 26,197
. USER_TIME 85,376
. VM_IN_BYTES -7.926511259279421E+18
. VM_OUT_BYTES 1.3225805433024102E+17
. PHYSICAL_MEMORY_BYTES 4,223,160,320
. NUM_CPUS 8
. NUM_CPU_CORES 4
. NUM_CPU_SOCKETS 1
. -------------------------------------------------------------
.
. Operating System Statistics - Detail DB/Inst: ORCL/orcl Snaps: 330-336
.
. Snap Time Load %busy %user %sys %idle %iowait
. --------------- -------- -------- -------- -------- -------- --------
. 11-Mar 15:18:53 0.0 N/A N/A N/A N/A N/A
. 11-Mar 15:22:30 0.0 16.7 13.4 3.3 83.3 0.0
. 11-Mar 15:27:01 0.0 15.7 12.2 3.5 84.3 0.0
. 11-Mar 15:30:06 0.0 17.1 13.3 3.8 82.9 0.0
. 11-Mar 15:30:33 0.0 9.3 4.7 4.6 90.7 0.0
. 11-Mar 15:30:40 0.0 8.7 4.7 4.0 91.3 0.0
. 11-Mar 15:34:32 0.0 11.1 7.8 3.3 88.9 0.0
. -------------------------------------------------------------
.
. Foreground Wait Class DB/Inst: ORCL/orcl Snaps: 330-336
. -> s - second, ms - millisecond - 1000th of a second
. -> ordered by wait time desc, waits desc
. -> %Timeouts: value of 0 indicates value was
. Instance Activity Stats DB/Inst: ORCL/orcl Snaps: 330-336
. -> Ordered by statistic name
.
. Statistic Total per Second per Trans
. -------------------------------- ------------------ -------------- -------------
. Batched IO (bound) vector count 0 0.0 0.0
. Batched IO (full) vector count 0 0.0 0.0
. Batched IO block miss count 0 0.0 0.0
. Batched IO buffer defrag count 0 0.0 0.0
. Batched IO double miss count 0 0.0 0.0
. Batched IO same unit count 0 0.0 0.0
. Batched IO single block count 0 0.0 0.0
. Batched IO slow jump count 0 0.0 0.0
. Batched IO vector block count 0 0.0 0.0
. Batched IO vector read count 0 0.0 0.0
. Block Cleanout Optim referenced 18 0.0 0.0
. CCursor + sql area evicted 4 0.0 0.0
. CPU used by this session 60,704 64.7 3.7
. CPU used when call started 60,724 64.7 3.7
. CR blocks created 165,431 176.2 10.2
. Cached Commit SCN referenced 6,448 6.9 0.4
. Commit SCN cached 62 0.1 0.0
. DB time 1,358,097 1,446.8 83.3
. DBWR checkpoint buffers written 14,524 15.5 0.9
. DBWR checkpoints 0 0.0 0.0
. DBWR object drop buffers written 0 0.0 0.0
. DBWR revisited being-written buf 0 0.0 0.0
. DBWR tablespace checkpoint buffe 0 0.0 0.0
. DBWR transaction table writes 89 0.1 0.0
. DBWR undo block writes 1,385 1.5 0.1
. HSC Heap Segment Block Changes 45,158 48.1 2.8
. Heap Segment Array Inserts 537 0.6 0.0
. Heap Segment Array Updates 324 0.4 0.0
. IMU CR rollbacks 7,569 8.1 0.5
. IMU Flushes 1,331 1.4 0.1
. IMU Redo allocation size 5,252,508 5,595.6 322.3
. IMU commits 15,219 16.2 0.9
. IMU contention 633 0.7 0.0
. IMU ktichg flush 4 0.0 0.0
. IMU pool not allocated 0 0.0 0.0
. IMU recursive-transaction flush 2 0.0 0.0
. IMU undo allocation size 18,151,352 19,337.0 1,113.8
. IMU- failed to get a private str 0 0.0 0.0
. Number of read IOs issued 102 0.1 0.0
. PX local messages recv'd 0 0.0 0.0
. PX local messages sent 0 0.0 0.0
. RowCR - row contention 242 0.3 0.0
. RowCR attempts 14,831 15.8 0.9
. RowCR hits 14,581 15.5 0.9
. SMON posted for dropping temp se 0 0.0 0.0
. SMON posted for undo segment shr 1 0.0 0.0
. SQL*Net roundtrips to/from clien 16,460 17.5 1.0
. TBS Extension: bytes extended 0 0.0 0.0
. TBS Extension: files extended 0 0.0 0.0
. TBS Extension: tasks created 0 0.0 0.0
. TBS Extension: tasks executed 0 0.0 0.0
. active txn count during cleanout 205,164 218.6 12.6
. application wait time 17,091 18.2 1.1
. background checkpoints completed 0 0.0 0.0
. background checkpoints started 0 0.0 0.0
. background timeouts 3,884 4.1 0.2
. branch node splits 0 0.0 0.0
. buffer is not pinned count 382,849 407.9 23.5
. buffer is pinned count 964,352 1,027.3 59.2
. bytes received via SQL*Net from 3,669,707 3,909.4 225.2
. Instance Activity Stats DB/Inst: ORCL/orcl Snaps: 330-336
. -> Ordered by statistic name
.
. Statistic Total per Second per Trans
. -------------------------------- ------------------ -------------- -------------
. bytes sent via SQL*Net to client 3,057,845 3,257.6 187.6
. calls to get snapshot scn: kcmgs 122,026 130.0 7.5
. calls to kcmgas 184,187 196.2 11.3
. calls to kcmgcs 188,615 200.9 11.6
. cell physical IO interconnect by 488,999,424 520,940.9 30,005.5
. change write time 101 0.1 0.0
. cleanout - number of ktugct call 149,940 159.7 9.2
. cleanouts and rollbacks - consis 148,731 158.5 9.1
. cleanouts only - consistent read 219 0.2 0.0
. cluster key scan block gets 1,277 1.4 0.1
. cluster key scans 1,169 1.3 0.1
. commit batch performed 0 0.0 0.0
. commit batch requested 0 0.0 0.0
. commit batch/immediate performed 5 0.0 0.0
. commit batch/immediate requested 5 0.0 0.0
. commit cleanout failures: block 4 0.0 0.0
. commit cleanout failures: buffer 0 0.0 0.0
. commit cleanout failures: callba 55 0.1 0.0
. commit cleanout failures: cannot 582 0.6 0.0
. commit cleanouts 48,381 51.5 3.0
. commit cleanouts successfully co 47,740 50.9 2.9
. commit immediate performed 5 0.0 0.0
. commit immediate requested 5 0.0 0.0
. commit txn count during cleanout 1,512 1.6 0.1
. concurrency wait time 24 0.0 0.0
. consistent changes 270,620 288.3 16.6
. consistent gets 113,690,229 121,116.5 6,976.1
. consistent gets - examination 763,228 813.1 46.8
. consistent gets direct 115 0.1 0.0
. consistent gets from cache 113,690,114 121,116.4 6,976.1
. consistent gets from cache (fast 112,771,868 120,138.1 6,919.8
. cursor authentications 88 0.1 0.0
. data blocks consistent reads - u 246,609 262.7 15.1
. db block changes 325,619 346.9 20.0
. db block gets 238,396 254.0 14.6
. db block gets direct 33 0.0 0.0
. db block gets from cache 238,363 253.9 14.6
. db block gets from cache (fastpa 45,107 48.1 2.8
. deferred (CURRENT) block cleanou 9,334 9.9 0.6
. dirty buffers inspected 1,450 1.5 0.1
. enqueue conversions 220 0.2 0.0
. enqueue deadlocks 1 0.0 0.0
. enqueue releases 62,035 66.1 3.8
. enqueue requests 62,058 66.1 3.8
. enqueue timeouts 0 0.0 0.0
. enqueue waits 144 0.2 0.0
. execute count 99,354 105.8 6.1
. failed probes on index block rec 1 0.0 0.0
. file io service time 0 0.0 0.0
. file io wait time 5,159,140,347 5,496,135.9 316,569.9
. free buffer inspected 64,669 68.9 4.0
. free buffer requested 203,119 216.4 12.5
. heap block compress 113 0.1 0.0
. hot buffers moved to head of LRU 4,586 4.9 0.3
. immediate (CR) block cleanout ap 148,950 158.7 9.1
. immediate (CURRENT) block cleano 2,628 2.8 0.2
. index crx upgrade (positioned) 748 0.8 0.1
. index fast full scans (full) 0 0.0 0.0
. index fetch by key 170,427 181.6 10.5
. index scans kdiixs1 17,563 18.7 1.1
. Instance Activity Stats DB/Inst: ORCL/orcl Snaps: 330-336
. -> Ordered by statistic name
.
. Statistic Total per Second per Trans
. -------------------------------- ------------------ -------------- -------------
. leaf node 90-10 splits 91 0.1 0.0
. leaf node splits 122 0.1 0.0
. lob reads 7,189 7.7 0.4
. lob writes 6,318 6.7 0.4
. lob writes unaligned 6,318 6.7 0.4
. logons cumulative 59 0.1 0.0
. max cf enq hold time 593 0.6 0.0
. messages received 23,662 25.2 1.5
. messages sent 23,662 25.2 1.5
. min active SCN optimization appl 55 0.1 0.0
. no work - consistent read gets 112,545,173 119,896.6 6,905.9
. non-idle wait count 89,709 95.6 5.5
. non-idle wait time 425,833 453.7 26.1
. opened cursors cumulative 113,735 121.2 7.0
. parse count (describe) 17 0.0 0.0
. parse count (failures) 0 0.0 0.0
. parse count (hard) 11,264 12.0 0.7
. parse count (total) 41,999 44.7 2.6
. parse time cpu 322 0.3 0.0
. parse time elapsed 677 0.7 0.0
. physical read IO requests 31,858 33.9 2.0
. physical read bytes 261,709,824 278,804.7 16,058.8
. physical read total IO requests 34,092 36.3 2.1
. physical read total bytes 298,049,536 317,518.2 18,288.6
. physical read total multi block 0 0.0 0.0
. physical reads 31,947 34.0 2.0
. physical reads cache 31,832 33.9 2.0
. physical reads cache prefetch 89 0.1 0.0
. physical reads direct 115 0.1 0.0
. physical reads direct (lob) 102 0.1 0.0
. physical reads direct temporary 0 0.0 0.0
. physical reads prefetch warmup 0 0.0 0.0
. physical write IO requests 10,108 10.8 0.6
. physical write bytes 135,192,576 144,023.4 8,295.6
. physical write total IO requests 25,949 27.6 1.6
. physical write total bytes 190,949,888 203,422.8 11,716.9
. physical write total multi block 84 0.1 0.0
. physical writes 16,503 17.6 1.0
. physical writes direct 33 0.0 0.0
. physical writes direct (lob) 19 0.0 0.0
. physical writes direct temporary 1 0.0 0.0
. physical writes from cache 16,470 17.6 1.0
. physical writes non checkpoint 7,297 7.8 0.5
. pinned buffers inspected 0 0.0 0.0
. pinned cursors current 17 0.0 0.0
. prefetch warmup blocks aged out 0 0.0 0.0
. prefetch warmup blocks flushed o 0 0.0 0.0
. process last non-idle time 709 0.8 0.0
. recovery blocks read 0 0.0 0.0
. recursive calls 257,570 274.4 15.8
. recursive cpu usage 59,319 63.2 3.6
. redo blocks checksummed by FG (e 15,116 16.1 0.9
. redo blocks read for recovery 0 0.0 0.0
. redo blocks written 80,789 86.1 5.0
. redo buffer allocation retries 0 0.0 0.0
. redo entries 201,456 214.6 12.4
. redo k-bytes read for recovery 0 0.0 0.0
. redo k-bytes read total 0 0.0 0.0
. redo log space requests 0 0.0 0.0
. redo log space wait time 0 0.0 0.0
. Instance Activity Stats DB/Inst: ORCL/orcl Snaps: 330-336
. -> Ordered by statistic name
.
. Statistic Total per Second per Trans
. -------------------------------- ------------------ -------------- -------------
. redo ordering marks 707 0.8 0.0
. redo size 34,695,312 36,961.6 2,128.9
. redo size for direct writes 1,092 1.2 0.1
. redo subscn max counts 2,579 2.8 0.2
. redo synch time 18,838 20.1 1.2
. redo synch writes 13,097 14.0 0.8
. redo wastage 5,110,400 5,444.2 313.6
. redo write time 19,588 20.9 1.2
. redo writes 14,831 15.8 0.9
. rollback changes - undo records 28 0.0 0.0
. rollbacks only - consistent read 17,113 18.2 1.1
. rows fetched via callback 117,883 125.6 7.2
. session connect time 0 0.0 0.0
. session cursor cache hits 99,097 105.6 6.1
. session logical reads 113,928,625 121,370.5 6,990.8
. shared hash latch upgrades - no 26,298 28.0 1.6
. shared hash latch upgrades - wai 1 0.0 0.0
. sorts (memory) 4,746 5.1 0.3
. sorts (rows) 59,465 63.4 3.7
. sql area evicted 11,016 11.7 0.7
. sql area purged 1 0.0 0.0
. summed dirty queue length 7,499 8.0 0.5
. switch current to new buffer 1,064 1.1 0.1
. table fetch by rowid 611,812 651.8 37.5
. table fetch continued row 536 0.6 0.0
. table scan blocks gotten 112,631,754 119,988.9 6,911.2
. table scan rows gotten 9,248,475,852 9,852,587.2 567,495.6
. table scans (cache partitions) 20,719 22.1 1.3
. table scans (direct read) 0 0.0 0.0
. table scans (long tables) 0 0.0 0.0
. table scans (short tables) 2,835 3.0 0.2
. temp space allocated (bytes) 1,048,576 1,117.1 64.3
. total cf enq hold time 3,557 3.8 0.2
. total number of cf enq holders 46 0.1 0.0
. total number of times SMON poste 1 0.0 0.0
. transaction rollbacks 5 0.0 0.0
. undo change vector size 7,914,968 8,432.0 485.7
. user I/O wait time 351,282 374.2 21.6
. user calls 30,310 32.3 1.9
. user commits 16,296 17.4 1.0
. user rollbacks 1 0.0 0.0
. workarea executions - optimal 4,200 4.5 0.3
. write clones created in foregrou 9 0.0 0.0
. -------------------------------------------------------------
.
. Instance Activity Stats - Absolute Values DB/Inst: ORCL/orcl Snaps: 330-336
. -> Statistics with absolute values (should not be diffed)
.
. Statistic Begin Value End Value
. -------------------------------- --------------- ---------------
. session pga memory max 276,020,688 307,290,704
. session cursor cache count 7,356 9,292
. session uga memory 43,005,571,128 47,316,288,472
. opened cursors current 214 261
. logons current 40 55
. session uga memory max 513,959,392 586,648,008
. session pga memory 122,731,984 144,958,032
. -------------------------------------------------------------
.
. Instance Activity Stats - Thread Activity DB/Inst: ORCL/orcl Snaps: 330-336
. -> Statistics identified by '(derived)' come from sources other than SYSSTAT
.
. Statistic Total per Hour
. -------------------------------- ------------------ ---------
. log switches (derived) 0 .00
. -------------------------------------------------------------
Ratios
Foreground Events
Background Events
Histograns
SQL ordered
by elapsed time
by CPU time
by Gets
by Reads
by executions
Instance statistics
IO Stats
by function
by filetype
tablespace statistics
file statistics
latch statistics
segment statistics
. . .

Statspack
or AWR report

solutions: review disks, move one datafile
solution: Add index on inventories
solution: For scalability,
lock only required tables
(FOR UPDATE OF ...)
This is optimal for an OLTP application:
short transactions, frequent commits.
During 15 minutes, each session can use 15 minutes of database time
if they are active all the time, or less if they have some idle time
Expectation:
Avg I/O wait= 50ms or even 10ms
DB CPU time divided by 1000
Enqueue Waits=0
Total DB time can be divided by 2 or even 10
Main ideas
during 15 minutes, each session can use 15 minutes of database
First things to check:
Elapsed time: is the application behaviour significant during that time?
DB time: How much time was spent in database during that time ?
From that, calculate the database load to see how application was active on doing database calls
DB time links the resource consumption
with the user response time
All the further analysis will be base on Top 5 timed events:
Take them one by one, and get specific details about it
Investigate the I/O
average wait time
db file sequential read is single block i/o
investigate the number of i/o calls
detail by tablespaces
detail by datafiles
Beyond averages: histograms
Detail by segments
(tables, index,...)
Finally, by queries
Reads are number of blocks read from disk
It is equal to the number of I/O calls as we have
single block reads (db file sequential read)
That was for our instance only
We have stats from OS for the whole system
Detail by Queries
We check other info for the same SQL statement
CPU is often caused by high number of buffer gets
Beyond AWRRPT we have the AWRSQRPT for all details on one SQL statement
Even if only 3% of response time currently, locks will prevent scalability
Summary of observations
and possible improvement
That was calculated by replacing the current values
by those that we can expect from our tuning actions
Brief summary to expose the propositions
with cost and
expected result
. Top 5 Timed Foreground Events
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. 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
. Redo size: 36,961.6 2,128.9
. Logical reads: 121,370.5 6,990.8
. Block changes: 346.9 20.0
. Physical reads: 34.0 2.0
. Physical writes: 17.6 1.0
. User calls: 32.3 1.9
. Parses: 44.7 2.6
. Hard parses: 12.0 0.7
. W/A MB processed: 0.3 0.0
. Logons: 0.1 0.0
. Executes: 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 5 Timed Foreground Events
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. 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
. 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
. -------------------------------------------------------------
.
. 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
. Top 5 Timed Foreground Events
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. 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
.
. 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
.
. Snap Id Snap Time Sessions Curs/Sess
. --------- ------------------- -------- ---------
. Begin Snap: 330 11-Mar-11 15:18:53 40 5.4
. End Snap: 336 11-Mar-11 15:34:32 55 4.7
. Elapsed: 15.64 (mins)
. DB Time: 76.48 (mins)
. 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
. -------------------------------------------------------------
. Top 5 Timed Foreground Events
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. 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
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 Total 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 5 Timed Foreground Events
. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
. 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
.
. 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 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
. 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
Franck Pachot
Oracle Database 12c Administrator Certified Professional
Oracle Database 11g Performance Tuning Certified Expert

franck.pachot@dbi-services.com
http://www.dbi-services.com
http://twitter.com/FranckPachot
See the full transcript