Hi we are using version 12.1.2.0 of Oracle Exadata. And we are seeing high flash back related waits(flashback buf free by RVWR) during peak hours in our database and the DMLs are suffering. We want to see if we can reduce this by some way as we need to have the flashback turned on as per business agreement.
Below is the specific sections of AWR showing "flashback buf free by RVWR" as the second top most "foreground wait event". As per the support team we got the recommendation stating , " We have ~27 log switches per hour which is high and it should be ~4 per hour. And the issue is related to the I/O bottleneck, in order to reduce the write I/O try to increase REDO size and have less REDO switched. The scope of REDO increase is to reduce the log switched and give bandwidth to flashback writer between log switches." ..
Now i am not able to understand how the minimization of redo switch will help in minimizing the "flashback buf free by RVWR" wait. As because RVWR writes the flash back buffer to the flash back log which is off-course on same disk as redolog file but both(redolog and flash back log) writes are performed by two different processes and if we will increase the redolog file size to reduce the log switch then also the amount of log write which has to happen will remain same. So need experts thoughts on, how it will reduce the I/O and help us here? I am not able to relate the flash back log writer i.e RVWR to the redolog writes here. And is there any possible negative side of having the size increased for the redolog file?
Below is the specific section of the AWR for peak 2hrs snap:-
| Snap Id | Snap Time | Sessions | Cursors/Session | Instances |
|---|
| Begin Snap: | 275026 | 01-Nov-19 05:45:21 | 321 | 40.7 | 2 |
| End Snap: | 275034 | 01-Nov-19 07:45:24 | 373 | 42.0 | 2 |
| Elapsed: | | 120.05 (mins) | | | |
| DB Time: | | 5,088.47 (mins) | | | |
Load Profile
| Per Second | Per Transaction | Per Exec | Per Call |
|---|
| DB Time(s): | 42.4 | 0.1 | 0.01 | 0.00 |
| DB CPU(s): | 7.8 | 0.0 | 0.00 | 0.00 |
| Background CPU(s): | 1.4 | 0.0 | 0.00 | 0.00 |
| Redo size (bytes): | 28,606,192.3 | 71,380.8 | | |
| Logical read (blocks): | 509,949.3 | 1,272.5 | | |
| Block changes: | 92,065.5 | 229.7 | | |
| Physical read (blocks): | 27,320.1 | 68.2 | | |
| Physical write (blocks): | 5,663.6 | 14.1 | | |
| Read IO requests: | 11,344.7 | 28.3 | | |
| Write IO requests: | 2,839.6 | 7.1 | | |
| Read IO (MB): | 213.4 | 0.5 | | |
| Write IO (MB): | 44.3 | 0.1 | | |
| IM scan rows: | 0.0 | 0.0 | | |
| Session Logical Read IM: | | | | |
| Global Cache blocks received: | 526.7 | 1.3 | | |
| Global Cache blocks served: | 149.1 | 0.4 | | |
| User calls: | 13,970.3 | 34.9 | | |
| Parses (SQL): | 1,986.7 | 5.0 | | |
| Hard parses (SQL): | 0.1 | 0.0 | | |
| SQL Work Area (MB): | 769.4 | 1.9 | | |
| Logons: | 1.1 | 0.0 | | |
| Executes (SQL): | 4,895.4 | 12.2 | | |
| Rollbacks: | 0.0 | 0.0 | | |
| Transactions: | 400.8 | | | |
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 | 79,110,642 | 92.2K | 1.17 | 30.2 | User I/O |
| flashback buf free by RVWR | 107,079 | 68.8K | 642.53 | 22.5 | Configuration |
| DB CPU | | 56.4K | | 18.5 | |
| buffer busy waits | 5,757,490 | 47.2K | 8.19 | 15.4 | Concurrency |
| enq: TX - index contention | 1,137,926 | 28.4K | 24.96 | 9.3 | Concurrency |
| log file sync | 2,907,893 | 5129.6 | 1.76 | 1.7 | Commit |
| flashback log switch | 5,445 | 4318.5 | 793.11 | 1.4 | Other |
| cell multiblock physical read | 1,111,627 | 1827.7 | 1.64 | .6 | User I/O |
| read by other session | 270,434 | 1341.4 | 4.96 | .4 | User I/O |
| gc cr block busy | 1,163,832 | 1262.7 | 1.08 | .4 | Cluster |
Wait Classes by Total Wait Time
| Wait Class | Waits | Total Wait Time (sec) | Avg Wait (ms) | % DB time | Avg Active Sessions |
|---|
| User I/O | 81,063,595 | 97,656 | 1.20 | 32.0 | 13.6 |
| System I/O | 8,366,957 | 92,660 | 11.07 | 30.3 | 12.9 |
| Concurrency | 7,531,612 | 75,794 | 10.06 | 24.8 | 10.5 |
| Configuration | 160,301 | 71,145 | 443.82 | 23.3 | 9.9 |
| DB CPU | | 56,359 | | 18.5 | 7.8 |
| Other | 18,947,717 | 13,341 | 0.70 | 4.4 | 1.9 |
| Commit | 2,908,091 | 5,130 | 1.76 | 1.7 | 0.7 |
| Cluster | 6,421,815 | 2,014 | 0.31 | .7 | 0.3 |
| Application | 10,049 | 694 | 69.11 | .2 | 0.1 |
| Network | 87,363,494 | 64 | 0.00 | .0 | 0.0 |
Host CPU
| CPUs | Cores | Sockets | Load Average Begin | Load Average End | %User | %System | %WIO | %Idle |
|---|
| 32 | 16 | 2 | 3.72 | 3.54 | 25.7 | 4.6 | 0.0 | 68.5 |
Instance CPU
| %Total CPU | %Busy CPU | %DB time waiting for CPU (Resource Manager) |
|---|
| 29.1 | 92.3 | 0.0 |
IO Profile
| Read+Write Per Second | Read per Second | Write Per Second |
|---|
| Total Requests: | 15,067.0 | 11,511.0 | 3,556.0 |
| Database Requests: | 14,184.3 | 11,344.7 | 2,839.6 |
| Optimized Requests: | 11,383.6 | 11,189.4 | 194.2 |
| Redo Requests: | 656.6 | 43.2 | 613.4 |
| Total (MB): | 465.3 | 271.6 | 193.8 |
| Database (MB): | 257.7 | 213.4 | 44.3 |
| Optimized Total (MB): | 223.9 | 209.7 | 14.2 |
| Redo (MB): | 99.8 | 43.1 | 56.7 |
| Database (blocks): | 32,983.7 | 27,320.1 | 5,663.6 |
| Via Buffer Cache (blocks): | 28,613.7 | 23,101.4 | 5,512.3 |
| Direct (blocks): | 4,370.0 | 4,218.7 | 151.3 |
Memory Statistics
| Begin | End |
|---|
| Host Mem (MB): | 257,973.7 | 257,973.7 |
| SGA use (MB): | 45,056.0 | 45,056.0 |
| PGA use (MB): | 6,105.5 | 6,094.5 |
| % Host Mem used for SGA+PGA: | 19.83 | 19.83 |
Cache Sizes
| Begin | End | | |
|---|
| Buffer Cache: | 35,200M | 35,200M | Std Block Size: | 8K |
| Shared Pool Size: | 8,192M | 8,192M | Log Buffer: | 254,664K |
| In-Memory Area: | 0M | 0M |
Shared Pool Statistics
| Begin | End |
|---|
| Memory Usage %: | 82.48 | 80.86 |
| % SQL with executions>1: | 99.37 | 99.12 |
| % Memory for SQL w/exec>1: | 98.66 | 97.72 |
Background Wait Events
- ordered by wait time desc, waits desc (idle events last)
- Only events with Total Wait Time (s) >= .001 are shown
- %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 | % bg time |
|---|
| db file parallel write | 3,033,926 | 0 | 60,399 | 19.91 | 1.05 | 52.75 |
| Log archive I/O | 90,057 | 0 | 12,305 | 136.63 | 0.03 | 10.75 |
| flashback log file write | 467,826 | 0 | 8,193 | 17.51 | 0.16 | 7.16 |
| log file sequential read | 215,535 | 0 | 8,175 | 37.93 | 0.07 | 7.14 |
| ASM file metadata operation | 71,409 | 0 | 3,051 | 42.72 | 0.02 | 2.66 |
| KSV master wait | 41,501 | 11 | 3,025 | 72.89 | 0.01 | 2.64 |
| log file parallel write | 2,199,365 | 0 | 2,033 | 0.92 | 0.76 | 1.78 |
| control file parallel write | 8,591 | 0 | 806 | 93.82 | 0.00 | 0.70 |
| flashback log file sync | 722 | 51 | 495 | 685.19 | 0.00 | 0.43 |
| enq: RO - fast object reuse | 4,633 | 0 | 429 | 92.50 | 0.00 | 0.37 |
| flashback buf free by RVWR | 795 | 37 | 420 | 528.76 | 0.00 | 0.37 |
| reliable message | 28,772 | 0 | 346 | 12.04 | 0.01 | 0.30 |
| flashback log file read | 19,831 | 0 | 332 | 16.75 | 0.01 | 0.29 |
| control file sequential read | 596,425 | 0 | 326 | 0.55 | 0.21 | 0.28 |
| LGWR wait for redo copy | 2,874,798 | 0 | 209 | 0.07 | 1.00 | 0.18 |
| Disk file operations I/O | 137,327 | 0 | 159 | 1.16 | 0.05 | 0.14 |
| cell single block physical read | 33,901 | 0 | 117 | 3.46 | 0.01 | 0.10 |
| enq: CF - contention | 2,528 | 81 | 111 | 43.88 | 0.00 | 0.10 |
| change tracking file synchronous read | 2,773 | 0 | 110 | 39.61 | 0.00 | 0.10 |
| db file single write | 497 | 0 | 104 | 209.75 | 0.00 | 0.09 |
| | | | | | |
Instance Activity Stats - Thread Activity
- Statistics identified by '(derived)' come from sources other than SYSSTAT
| Statistic | Total | per Hour |
|---|
| log switches (derived) | 54 | 26.99 |
Key Instance Activity Stats
- Ordered by statistic name
| Statistic | Total | per Second | per Trans |
|---|
| db block changes | 663,162,532 | 92,065.48 | 229.73 |
| execute count | 35,262,533 | 4,895.42 | 12.22 |
| gc cr block receive time | 137,106 | 19.03 | 0.05 |
| gc cr blocks received | 2,021,649 | 280.66 | 0.70 |
| gc current block receive time | 25,820 | 3.58 | 0.01 |
| gc current blocks received | 1,772,386 | 246.06 | 0.61 |
| logons cumulative | 8,233 | 1.14 | 0.00 |
| opened cursors cumulative | 15,501,244 | 2,152.01 | 5.37 |
| parse count (total) | 14,310,365 | 1,986.68 | 4.96 |
| parse time elapsed | 24,787 | 3.44 | 0.01 |
| physical reads | 196,791,197 | 27,320.11 | 68.17 |
| physical writes | 40,795,786 | 5,663.59 | 14.13 |
| redo size | 206,055,036,972 | 28,606,192.25 | 71,380.75 |
| session cursor cache hits | 2,274,911 | 315.82 | 0.79 |
| session logical reads | 3,673,247,167 | 509,949.26 | 1,272.47 |
| user calls | 100,630,072 | 13,970.26 | 34.86 |
| user commits | 2,886,692 | 400.75 | 1.00 |
| user rollbacks | 11 | 0.00 | 0.00 |
| workarea executions - onepass | 0 | 0.00 | 0.00 |
| workarea executions - optimal | 3,477,519 | 482.78 | 1.20 |