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 ) = 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 ? Average wait: not meaningfull when locks > 3 s 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 We will have to 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 Franck Pachot, mail@pachot.net 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(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 futher 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 http://www.pachot.net . 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 . -------------------------- ----- ----- ----- ----- ----- ----- ----- ----- ----- . db file sequential read 85 99.7 .2 .0 . 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 Oracle - Interpreting AWR Report - Straight to the Goal Franck Pachot - Trivadis SA - July 24, 2011 Oracle – Table Lock Modes SS, RS, SX, RX, S, SSX, SRX, X made easy Swiss Oracle User Group - January 6, 2013 Indexing Foreign Keys in Oracle Franck Pachot - Trivadis SA - April 24, 2012 http://prezi.com/glqm9zemzhup/interpreting-awr-report-straight-to-the-goal/ http://www.soug.ch/fileadmin/user_upload/Newsletter/NL_public/NL_2013_1_Award_Article.pdf http://prezi.com/uzdd5ttg4cu0/indexing-foreign-keys-in-oracle/ http://www.pachot.net Contact: mail@pachot.net Other Presentations