We are using version 11.2.0.4 of oracle Exadata 2 node-RAC. But we have mainly application runs on one node. We have a Insert statement which slows down(elapsed time increased from ~1milli sec/execution to 9milli sec/execution) many of the time and apart from the usual waits , we see high concurrency(enq: TX - index contention and buffer busy waits). The top "segment by buffer busy waits, segments by ITL waits, segments by row lock waits" showing two of the indexes from this table. one is unique index on a column(FID) and is populated by Oracle sequence and other is on a date column(CR_DT). This table is list-range composite partitoned but the indexes are all global indexes as because the queries are not using the partition/subpartition key in all scenarios.In total there are 8 indexes on this table including one function based index.As per current statistics , on an Avg there happen to be ~70million rows INSERTS in a day. Max ~5million inserts in an hour. See some of the figures related to index block splits on the instance activity stats section of the AWR report, yet to relate those to the issue. Need experts suggestions on how should i approach to reduce these waits and improve the performance?
Below is the table, and specific column and index statistics:-
TABLE_NAME NUM_ROWS BLOCKS AVG_ROW_LEN SAMPLE_SIZE
TAB1 1296442200 106007359 155 12964422
COLUMN_NAME DATA_TYPE NUM_DISTINCT DENSITY NUM_NULLS SAMPLE_SIZE
FID NUMBER 1296036400 7.71583267260086E-10 0 12960364
CR_DT DATE 4401109 7.29995744124812E-7 0 12960364
INDEX_NAME UNIQUENESS INI_TRANS MAX_TRANS BLEVEL DISTINCT_KEYS LEAF_BLOCKS CLUSTERING_FACTOR NUM_ROWS SAMPLE_SIZE AVG_LEAF_BLOCKS_PER_KEY AVG_DATA_BLOCKS_PER_KEY
TAB1_CRDT NONUNIQUE 20 255 4 4396763 21025300 119239900 1319549700 13195497 4 27
TAB1_UNQ UNIQUE 20 255 4 1293957200 36146700 690771200 1293957200 12939572 1 1
Below is the Oracle sequence definition:-
Increment By 1
Last Cached Value 101941472795
Minimum Value 1
Maximum Value 999999999999999999999999999
Cache Size 10000
Cycle No
Order No
Below is the INSERT query:-
--------------------
INSERT INTO TAB1 (FID, c2,c3, .......) VALUES (SEQ1.NEXTVAL,
:1 , :2 , :3 , :4 , :5 , :6 , :7 ,
:8 , :9 , :10 , :11 , :12 , :13 ,
:14 , :15 , :16 , :17 ,
:18 , :19 , :20 , :21 ,
:22 , :23 , :24 , :25 , :26 , :27 )
Plan hash value: 2358401533
------------------------------------------------------------------
| Id | Operation | Name | Cost |
------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 1 |
| 1 | LOAD TABLE CONVENTIONAL | | |
| 2 | SEQUENCE | SEQ1 | |
------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - INS$1
Note
-----
- cpu costing is off (consider enabling it)
Below is the specific section of AWR report:-
Load Profile
| Per Second | Per Transaction | Per Exec | Per Call |
|---|
| DB Time(s): | 39.9 | 0.1 | 0.01 | 0.00 |
| DB CPU(s): | 6.0 | 0.0 | 0.00 | 0.00 |
| Background CPU(s): | 0.9 | 0.0 | 0.00 | 0.00 |
| Redo size (bytes): | 20,529,812.0 | 28,002.6 | | |
| Logical read (blocks): | 463,563.1 | 632.3 | | |
| Block changes: | 81,572.0 | 111.3 | | |
| Physical read (blocks): | 39,749.8 | 54.2 | | |
| Physical write (blocks): | 3,436.0 | 4.7 | | |
| Read IO requests: | 9,443.6 | 12.9 | | |
| Write IO requests: | 1,049.8 | 1.4 | | |
| Read IO (MB): | 310.6 | 0.4 | | |
| Write IO (MB): | 26.8 | 0.0 | | |
| IM scan rows: | | | | |
| Session Logical Read IM: | | | | |
| Global Cache blocks received: | 325.8 | 0.4 | | |
| Global Cache blocks served: | 3,211.2 | 4.4 | | |
| User calls: | 12,660.7 | 17.3 | | |
| Parses (SQL): | 1,935.9 | 2.6 | | |
| Hard parses (SQL): | 0.3 | 0.0 | | |
| SQL Work Area (MB): | 524.1 | 0.7 | | |
| Logons: | 1.0 | 0.0 | | |
| Executes (SQL): | 4,772.9 | 6.5 | | |
| Rollbacks: | 319.8 | 0.4 | | |
| Transactions: | 733.1 | | | |
Instance Efficiency Percentages (Target 100%)
| Buffer Nowait %: | 99.69 | Redo NoWait %: | 100.00 |
| Buffer Hit %: | 97.65 | In-memory Sort %: | 100.00 |
| Library Hit %: | 100.00 | Soft Parse %: | 99.99 |
| Execute to Parse %: | 59.44 | Latch Hit %: | 99.56 |
| Parse CPU to Parse Elapsd %: | 75.30 | % Non-Parse CPU: | 99.53 |
| Flash Cache Hit %: | 97.38 |
Top 10 Foreground Events by Total Wait Time
| Event | Waits | Total Wait Time (sec) | Wait Avg(ms) | % DB time | Wait Class |
|---|
| cell single block physical read | 32,163,219 | 52.1K | 1.62 | 36.5 | User I/O |
| enq: TX - index contention | 936,008 | 30.3K | 32.41 | 21.3 | Concurrency |
| DB CPU | | 21.5K | | 15.0 | |
| buffer busy waits | 4,073,331 | 17.7K | 4.34 | 12.4 | Concurrency |
| flashback buf free by RVWR | 14,695 | 9068.6 | 617.12 | 6.4 | Configuration |
| log file sync | 1,473,970 | 4502 | 3.05 | 3.2 | Commit |
| read by other session | 311,231 | 2499.7 | 8.03 | 1.8 | User I/O |
| enq: TX - allocate ITL entry | 23,700 | 1091.3 | 46.05 | .8 | Configuration |
| direct path write temp | 25,006 | 990.6 | 39.61 | .7 | User I/O |
| flashback log switch | 1,010 | 792.4 | 784.52 | .6 | Other |
Wait Classes by Total Wait Time
| Wait Class | Waits | Total Wait Time (sec) | Avg Wait (ms) | % DB time | Avg Active Sessions |
|---|
| User I/O | 32,966,865 | 57,051 | 1.73 | 40.0 | 16.0 |
| Concurrency | 5,353,387 | 48,100 | 8.99 | 33.7 | 13.5 |
| System I/O | 2,768,573 | 24,294 | 8.78 | 17.0 | 6.8 |
| DB CPU | | 21,451 | | 15.0 | 6.0 |
| Configuration | 44,582 | 10,767 | 241.52 | 7.5 | 3.0 |
| Other | 5,084,453 | 5,140 | 1.01 | 3.6 | 1.4 |
| Commit | 1,474,017 | 4,502 | 3.05 | 3.2 | 1.3 |
| Cluster | 3,558,865 | 1,028 | 0.29 | .7 | 0.3 |
| Application | 24,851 | 527 | 21.22 | .4 | 0.1 |
| Network | 39,227,377 | 319 | 0.01 | .2 | 0.1 |
Foreground Wait Class
- s - second, ms - millisecond - 1000th of a second
- ordered by wait time desc, waits desc
- %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
- Captured Time accounts for 101.1% of Total DB time 142,720.85 (s)
- Total FG Wait Time: 122,848.39 (s) DB CPU time: 21,451.22 (s)
| Wait Class | Waits | %Time -outs | Total Wait Time (s) | Avg wait (ms) | %DB time |
|---|
| User I/O | 32,804,259 | 0 | 56,549 | 1.72 | 39.62 |
| Concurrency | 5,124,017 | 0 | 48,089 | 9.39 | 33.69 |
| DB CPU | | | 21,451 | | 15.03 |
| Configuration | 43,586 | 16 | 10,739 | 246.39 | 7.52 |
| Commit | 1,473,970 | 0 | 4,502 | 3.05 | 3.15 |
| Other | 2,043,064 | 79 | 1,374 | 0.67 | 0.96 |
| Cluster | 3,549,575 | 0 | 1,021 | 0.29 | 0.72 |
| Application | 24,661 | 0 | 525 | 21.27 | 0.37 |
| Network | 38,911,582 | 0 | 27 | 0.00 | 0.02 |
| System I/O | 33,659 | 0 | 23 | 0.68 | 0.02 |
Back to Wait Events Statistics
Back to Top
Foreground Wait Events
- s - second, ms - millisecond - 1000th of a second
- Only events with Total Wait Time (s) >= .001 are shown
- ordered by wait time desc, waits desc (idle events last)
- %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
| Event | Waits | %Time -outs | Total Wait Time (s) | Avg wait (ms) | Waits /txn | % DB time |
|---|
| cell single block physical read | 32,163,219 | | 52,136 | 1.62 | 12.27 | 36.53 |
| enq: TX - index contention | 936,008 | | 30,334 | 32.41 | 0.36 | 21.25 |
| buffer busy waits | 4,073,331 | | 17,699 | 4.34 | 1.55 | 12.40 |
| flashback buf free by RVWR | 14,695 | 45 | 9,069 | 617.12 | 0.01 | 6.35 |
| log file sync | 1,473,970 | | 4,502 | 3.05 | 0.56 | 3.15 |
| read by other session | 311,231 | | 2,500 | 8.03 | 0.12 | 1.75 |
| enq: TX - allocate ITL entry | 23,700 | 0 | 1,091 | 46.05 | 0.01 | 0.76 |
| direct path write temp | 25,006 | | 991 | 39.61 | 0.01 | 0.69 |
| flashback log switch | 1,010 | 63 | 792 | 784.52 | 0.00 | 0.56 |
| cell multiblock physical read | 73,845 | | 543 | 7.35 | 0.03 | 0.38 |
| log file switch completion | 633 | | 478 | 755.49 | 0.00 | 0.34 |
| enq: TX - row lock contention | 3,082 | | 438 | 142.07 | 0.00 | 0.31 |
| gc cr block busy | 144,685 | | 399 | 2.76 | 0.06 | 0.28 |
| block change tracking buffer space | 308 | 60 | 236 | 767.16 | 0.00 | 0.17 |
| cell smart table scan | 120,582 | 34 | 221 | 1.83 | 0.05 | 0.15 |
| gc cr grant 2-way | 1,430,055 | | 153 | 0.11 | 0.55 | 0.11 |
| gc buffer busy acquire | 202,724 | | 146 | 0.72 | 0.08 | 0.10 |
| reliable message | 12,045 | | 134 | 11.09 | 0.00 | 0.09 |
| cell list of blocks physical read | 32,488 | | 116 | 3.59 | 0.01 | 0.08 |
| gc cr block 2-way | 552,859 | | 85 | 0.15 | 0.21 | 0.06 |
| enq: FB - contention | 51,166 | | 79 | 1.55 | 0.02 | 0.06 |
| gc current grant 2-way | 661,097 | | 68 | 0.10 | 0.25 | 0.05 |
| enq: SQ - contention | 3,834 | | 59 | 15.35 | 0.00 | 0.04 |
| enq: KO - fast object checkpoint | 20,844 | | 54 | 2.59 | 0.01 | 0.04 |
| gc current block 2-way | 405,118 | | 48 | 0.12 | 0.15 | 0.03 |
| gc current block busy | 749 | | 47 | 63.39 | 0.00 | 0.03 |
| enq: RO - fast object reuse | 677 | | 33 | 48.50 | 0.00 | 0.02 |
| undo segment extension | 288 | 93 | 33 | 113.64 | 0.00 | 0.02 |
| latch: ges resource hash list | 259,195 | | 31 | 0.12 | 0.10 | 0.02 |
| gc buffer busy release | 1,253 | 0 | 30 | 24.19 | 0.00 | 0.02 |
| cell smart index scan | 49,998 | 18 | 27 | 0.54 | 0.02 | 0.02 |
| flashback free VI log | 36 | 39 | 26 | 719.97 | 0.00 | 0.02 |
| SQL*Net message to client | 38,785,025 | | 24 | 0.00 | 14.80 | 0.02 |
| gc current grant busy | 107,434 | | 24 | 0.22 | 0.04 | 0.02 |
| gcs drm freeze in enter server mode | 242 | | 23 | 95.48 | 0.00 | 0.02 |
| control file sequential read | 33,655 | | 22 | 0.65 | 0.01 | 0.02 |
| library cache: mutex X | 28,862 | | 19 | 0.67 | 0.01 | 0.01 |
| cursor: pin S wait on X | 176 | | 18 | 104.17 | 0.00 | 0.01 |
| enq: TX - contention | 304 | 2 | 9 | 29.38 | 0.00 | 0.01 |
| enq: HW - contention | 431 | | 8 | 19.63 | 0.00 | 0.01 |
| name-service call wait | 202 | | 7 | 35.48 | 0.00 | 0.01 |
| gc remaster | 139 | | 7 | 51.21 | 0.00 | 0.00 |
| Disk file Mirror Read | 8,249 | | 7 | 0.85 | 0.00 | 0.00 |
Wait Event Histogram
- Units for Total Waits column: K is 1000, M is 1000000, G is 1000000000
- % of Waits: value of .0 indicates value was <.05%; value of null is truly 0
- % of Waits: column heading of <=1s is truly <1024ms, >1s is truly >=1024ms
- Ordered by Event (idle events last)
| | | % of Waits |
|---|
| Event | Total Waits | <1ms | <2ms | <4ms | <8ms | <16ms | <32ms | <=1s | >1s |
|---|
| ADR block file read | 52 | 40.4 | | 1.9 | 48.1 | 9.6 | | | |
| ADR block file write | 10 | 100.0 | | | | | | | |
| ADR file lock | 12 | 100.0 | | | | | | | |
| ARCH wait for archivelog lock | 76 | 100.0 | | | | | | | |
| ARCH wait on SENDREQ | 3603 | 89.3 | 10.1 | .0 | | | | .1 | .5 |
| ASM file metadata operation | 15.3K | 96.3 | 2.6 | .3 | .0 | .0 | .1 | .3 | .4 |
| CGS wait for IPC msg | 71K | 100.0 | | | | | | | |
| CSS initialization | 102 | 50.0 | | 38.2 | 11.8 | | | | |
| CSS operation: action | 190 | 91.1 | 8.9 | | | | | | |
| CSS operation: query | 306 | 97.1 | 2.9 | | | | | | |
| DFS lock handle | 393 | 98.2 | | | | | | 1.5 | .3 |
| Disk file Mirror Read | 78.9K | 64.2 | 14.8 | 12.2 | 7.9 | .6 | .2 | .1 | |
| Disk file operations I/O | 92.4K | 25.6 | 72.0 | 1.6 | .7 | .1 | .0 | .0 | |
| IPC send completion sync | 2902 | 100.0 | | | | | | | |
| KJC: Wait for msg sends to complete | 11 | 100.0 | | | | | | | |
| KSV master wait | 10.7K | 94.5 | 4.0 | .5 | .0 | .0 | .1 | .4 | .5 |
| LGWR wait for redo copy | 1.2M | 99.9 | .1 | .0 | .0 | .0 | | | |
| LNS wait on SENDREQ | 310.1K | 99.9 | .0 | | | .0 | .0 | .1 | .0 |
| Log archive I/O | 5221 | 4.1 | 6.1 | 23.2 | 9.5 | 13.2 | 12.6 | 27.4 | 3.8 |
| PX Deq Credit: free buffer | 406 | 100.0 | | | | | | | |
| PX Deq: Signal ACK EXT | 3246 | 99.1 | .4 | .3 | .2 | .0 | | | |
| PX Deq: Signal ACK RSG | 3246 | 99.7 | .1 | .1 | .1 | .0 | | | |
| PX Deq: Slave Session Stats | 5973 | 96.0 | 1.2 | .5 | 1.8 | .4 | | | |
| PX Deq: reap credit | 70.4K | 100.0 | .0 | | | | | | |
| PX qref latch | 1.2M | 100.0 | .0 | | | | | | |
| Parameter File I/O | 1936 | 71.0 | 9.2 | 6.2 | 5.7 | 3.6 | .7 | 3.6 | |
| SGA: allocation forcing component growth | 8 | 12.5 | | | | | | 87.5 | |
| SQL*Net break/reset to client | 50 | 100.0 | | | | | | | |
| SQL*Net message to client | 38.8M | 100.0 | .0 | .0 | | | | | |
| SQL*Net more data from client | 117.1K | 100.0 | .0 | .0 | .0 | | | | |
| SQL*Net more data to client | 9741 | 99.4 | .0 | .5 | .1 | | | | |
| block change tracking buffer space | 315 | 3.8 | 1.0 | .3 | .6 | .6 | 1.0 | 92.7 | |
| buffer busy waits | 4.1M | 86.8 | 5.6 | 3.3 | 2.0 | .7 | .3 | 1.3 | .0 |
| buffer deadlock | 370.3K | 99.9 | .1 | .0 | .0 | | | | |
| buffer exterminate | 639 | .6 | .5 | .2 | 1.3 | 97.5 | | | |
| cell list of blocks physical read | 32.6K | 47.5 | 15.5 | 17.4 | 14.4 | 3.5 | 1.0 | .6 | .0 |
| cell multiblock physical read | 74K | 43.2 | 23.6 | 14.8 | 9.6 | 3.8 | 2.1 | 2.7 | .0 |
| cell single block physical read | 32.1M | 77.1 | 12.9 | 5.7 | 3.0 | .7 | .2 | .3 | .0 |
| cell smart index scan | 50.1K | 86.6 | 6.8 | 3.8 | 2.2 | .6 | .1 | .0 | |
| cell smart table scan | 120.9K | 87.5 | 5.0 | 3.4 | 2.2 | 1.0 | .5 | .5 | .0 |
| change tracking file synchronous read | 8016 | 49.2 | 6.6 | 3.9 | 7.0 | 10.1 | 6.9 | 16.0 | .2 |
| change tracking file synchronous write | 3946 | 50.4 | 18.9 | 8.0 | 3.9 | 4.4 | 4.3 | 10.1 | .1 |
| control file parallel write | 5607 | 31.6 | 18.6 | 8.9 | 4.4 | 4.9 | 4.8 | 23.1 | 3.7 |
| control file sequential read | 122.4K | 92.1 | 4.3 | 2.2 | 1.0 | .2 | .1 | .1 | .0 |
| control file single write | 12 | 58.3 | | 8.3 | | 8.3 | 16.7 | 8.3 | |
| cursor: mutex S | 6 | 100.0 | | | | | | | |
| cursor: mutex X | 3 | 100.0 | | |
|