Skip to Main Content

Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

Digging into performance issue

User_OCZ1TNov 3 2019 — edited Nov 10 2019

Hi we are using version 12.1.0.2.0 of oracle exadata. In this database we used to see delayed block cleanout effect during monthend processing and to avoid that we manually scan the table/index blocks before hand. Also index contention is a known issue in thid DB on which we are working on design changes. But suddenly this monthend(1st nov) we experience the "delayed block cleanout effect" pretty extensively making the read queries to fail multiple times throughout the day which was not the case in previous monthends. I am trying to understand what has caused this drastic degradation in performance this time. My initial thought was it must be because of increase in number of transactions, but I did compare the "user commits"/rollbacks and not seeing significant difference as compared to last month.

1)When i compare the AWR for the last monthend to current monthend. I found the two odd top wait events were related to "system i/o(DB file  parallel write)" and "configuration(flashback buf free by RVWR)" wait classes. We do have flashback enabled in this database as per business agreement, but i am trying to understand what has triggered this wait to be so high this time as compared to earlier?

2)Not much idea about the backup strategies but i see we have UNDO retention is 3600 and db_flashback_retention_target is 4320. We do have RMAN backup(L0 and L1) scheduled as per standard. So my question was as we can recover individual objects from rman backup itself so is it okay to switch off the flashback to get rid of these additional bottlenecks during write/dmls mainly?

3)I see in the "top timed event" section the number of "flashback buf free by RVWR" has been increased from ~140k to ~350k. ANd "DB file  parallel write" in creased from ~22million to ~46million. So Is it correct to say that starting point is "db file parallel write" whose response time degraded and due to that the "flashback buf free by RVWR" has been coming on top and others(delayed block cleanout etc) are result of this?

Below is the comparison of AWR between two monthends, i have only posted below few key sections of the AWR comparison and not all.

      

Snapshot SetBegin Snap IdBegin Snap TimeEnd Snap IdEnd Snap TimeAvg Active UsersElapsed Time (min)DB time (min)
1st27205501-Oct-19 05:00:10 (Tue)27212701-Oct-19 23:00:30 (Tue)21.31,080.3023,022.60
2nd27502301-Nov-19 05:00:02 (Fri)27509501-Nov-19 23:00:04 (Fri)28.81,080.0031,122.50
%Diff35.2035.2

    

Host Configuration Comparison
1st2ndDiff%Diff
Number of CPUs:323200
Number of CPU Cores:161600
Number of CPU Sockets:2200
Physical Memory:257973.7M257973.7M0M0
Load at Start Snapshot:3.813.19-0.62-16.3
Load at End Snapshot:3.272.38-0.89-27.2
%User Time:26.4227.350.933.5
%System Time:4.975.210.244.8
%Idle Time:67.5266.02-1.49-2.2
%IO Wait Time:0.010.0100

    

Cache Sizes
1st (M)2nd (M)Diff (M)%Diff
Memory Target
SGA Target
45,056.0045,056.0000
Buffer Cache
35,200.0035,200.0000
Shared Pool
8,192.008,192.0000
Large Pool
1,024.001,024.0000
Java Pool
12812800
Streams Pool
25625600
PGA Target
46,080.0046,080.0000
Log Buffer12812800
In-Memory Area

      

Load Profile
1st per sec2nd per sec%Diff1st per txn2nd per txn%Diff
DB time:21.328.835.200.120
CPU time:8.28.43.3000
Background CPU time:1.21.528.6000
Redo size (bytes):18,337,036.5017,500,030.90-4.639,452.7037,503.50-4.9
Logical read (blocks):573,369.80552,181.80-3.71,233.601,183.40-4.1
Block changes:91,955.6084,981.60-7.6197.8182.1-7.9
Physical read (blocks):97,379.80103,043.605.8209.5220.85.4
Physical write (blocks):4,750.906,774.0042.610.214.542.1
Read IO requests:7,553.3010,041.8032.916.321.532.4
Write IO requests:2,100.604,042.1092.44.58.791.6
Read IO (MB):760.88055.81.61.75.5
Write IO (MB):37.152.942.60.10.137.5
IM scan rows:000000
Session Logical Read IM:
Global Cache blocks received:771.1694.5-9.91.71.5-10.2
Global Cache blocks served:219.7186.2-15.20.50.4-14.9
User calls:20,240.1020,888.903.243.544.82.8
Parses (SQL):2,341.602,334.50-0.355-0.8
Hard parses (SQL):0.30.2-35.7000
SQL Work Area (MB):1,329.301,341.700.92.92.90.9
Logons:1.21.518.9000
Executes (SQL):6,188.806,093.80-1.513.313.1-2
Transactions:464.8466.60.4
1st2ndDiff
% Blocks changed per Read:1615.4-0.6
Recursive Call %:7.97-0.9
Rollback per transaction %:000
Rows per Sort:2,164.901,637.50-527.4
Avg DB time per Call (sec):000

         

Top Timed Events
    Events with a "-" did not make the Top list in this set of snapshots, but are displayed for comparison purposes
1st2nd
EventWait ClassWaitsTime(s)Avg Time(ms)%DB timeEventWait ClassWaitsTime(s)Avg Time(ms)%DB time
CPU time528,463.2638.26cell single block physical readUser I/O552,992,032575,983.201.0430.84
cell single block physical readUser I/O399,804,976463,012.671.1633.52CPU time545,675.3329.22
db file parallel writeSystem I/O22,301,041222,674.799.9816.12db file parallel writeSystem I/O46,409,738522,686.2911.2627.99
buffer busy waitsConcurrency30,172,532117,027.573.888.47flashback buf free by RVWRConfiguration349,855220,141.23629.2411.79
flashback buf free by RVWRConfiguration139,89982,831.01592.086enq: TX - index contentionConcurrency9,578,098219,165.5522.8811.74
enq: TX - index contentionConcurrency6,869,45865,227.559.54.72buffer busy waitsConcurrency40,070,745177,680.914.439.52
flashback log file writeSystem I/O3,726,60739,787.9710.682.88flashback log file writeSystem I/O3,259,12554,879.5716.842.94
log file sequential readSystem I/O1,354,23332,101.1623.72.32log file sequential readSystem I/O1,350,47844,940.8733.282.41
log file syncCommit30,502,74232,088.991.052.32Log archive I/OSystem I/O313,57042,509.85135.572.28
Log archive I/OSystem I/O293,76027,461.5093.481.99log file syncCommit30,215,37434,641.361.151.86

          

Time Model Statistics
    Ordered by absolute value of 'Diff' column of '% of DB time', descending (DB time statistic first, background statistics last)
% of DB time% of Total CPU timeTime (seconds)Time per Trans (seconds)
Statistic Name1st2ndDiff1st2ndDiff1st2nd%Diff1st2nd%Diff
DB CPU38.2629.22-9.0387.2284.652.57528,463.26545,675.333.260.020.020
sql execute elapsed time93.9593.09-0.861,297,821.481,738,320.7333.940.040.0650
PL/SQL execution elapsed time0.050.290.24742.085,507.91642.23000
parse time elapsed0.370.34-0.035,089.266,349.4424.76000
hard parse elapsed time0.080.06-0.021,093.061,071.31-1.99000
sequence load elapsed time0.050.03-0.02711.38591.2-16.89000
hard parse (sharing criteria) elapsed time0.020.040.01287.64661.2129.87000
connection management call elapsed time0.020.020299.81315.935.38000
hard parse (bind mismatch) elapsed time0.010.010125.51121.33-3.33000
repeated bind elapsed time0008.466.29-25.65000
failed parse elapsed time0001.664.29158.43000
PL/SQL compilation elapsed time0005.455.541.65000
background elapsed time464,512.95847,358.5082.420.020.0350
background cpu time12.7815.35-2.5777,431.4098,972.3227.82000
DB time1,381,356.231,867,348.5635.180.050.0620
total CPU time43.8634.52-9.34605,894.67644,647.656.40.020.026.01

          

Wait Classes
    Ordered by absolute value of 'Diff' column of '% of DB time' descending
% of DB time# Waits/sec (Elapsed Time)Total Wait Time (sec)Avg Wait Time (ms)
Wait Class1st2ndDiff1st2nd%Diff1st2nd%Diff1st2nd%Diff
System I/O24.8737.1912.321,091.041,863.1470.77343,525.77694,524.19102.184.865.7518.31
Concurrency13.5121.578.06689.19825.2319.74186,591.93402,793.72115.874.187.5380.14
User I/O40.2434.32-5.926,606.878,929.2735.15555,877.70640,826.2815.281.31.11-14.62
Configuration6.4812.255.765.238.664.4489,576.64228,685.11155.3264.48410.3755.16
Other4.15.951.851,888.724,147.47119.5956,629.39111,176.8696.320.460.41-10.87
Cluster1.851.34-0.5819.61,045.4527.5625,489.9425,075.63-1.630.480.37-22.92
Commit2.321.86-0.47470.58466.27-0.9232,088.9934,641.367.951.051.159.52
Application0.130.250.120.971.554.641,850.054,656.25151.6829.4448.0163.08
Network0.070.04-0.0318,096.8918,724.983.47940.24776.87-17.38000

          

Wait Events
    Ordered by absolute value of 'Diff' column of '% of DB time' descending (idle events last)
% of DB time# Waits/sec (Elapsed Time)Total Wait Time (sec)Avg Wait Time (ms)
EventWait Class1st2ndDiff1st2nd%Diff1st2nd%Diff1st2nd%Diff
db file parallel writeSystem I/O16.1227.9911.87344.05716.18108.16222,674.79522,686.29134.739.9811.2612.83
enq: TX - index contentionConcurrency4.7211.747.01105.98147.8139.4765,227.55219,165.552369.522.88140.84
flashback buf free by RVWRConfiguration611.795.792.165.415082,831.01220,141.23165.77592.08629.246.28
cell single block physical readUser I/O33.5230.84-2.676,167.968,533.5838.35463,012.67575,983.2024.41.161.04-10.34
direct path readUser I/O1.970-1.9680.930.75-99.0727,180.6487.36-99.685.181.79-65.44
wait for a undo recordOther01.51.506.58100027,931.83100065.48100
flashback log switchOther0.361.451.090.130.48269.235,016.0227,102.46440.32583.05867.8348.84
buffer busy waitsConcurrency8.479.521.04465.48618.3632.84117,027.57177,680.9151.833.884.4314.18
reliable messageOther1.10.23-0.8615.424.11-73.3515,143.184,371.77-71.1315.1516.48.25
direct path read tempUser I/O1.670.9-0.7618.7813.89-26.0423,061.7416,894.29-26.7418.9518.76-1
cell multiblock physical readUser I/O1.650.99-0.67163.17150.24-7.9222,816.5918,403.96-19.342.161.89-12.5
log file syncCommit2.321.86-0.47470.58466.27-0.9232,088.9934,641.367.951.051.159.52
PX Deq: Slave Session StatsOther0.470.02-0.451.762.6751.76,463.75368.36-94.356.562.13-96.23
log file parallel writeSystem I/O1.320.97-0.35427.42393.68-7.8918,240.4718,039.00-1.10.660.717.58
read by other sessionUser I/O0.260.550.2938.9240.163.193,572.2510,279.20187.751.423.95178.17
Log archive I/OSystem I/O1.992.280.294.534.846.8427,461.5042,509.8554.893.48135.5745.03
ASM file metadata operationOther0.730.990.269.749.7-0.4110,106.3418,480.0282.8616.0129.4183.7

           

Key Instance Activity Stats
Ordered by statistic name
Valueper Second (DB time)per Second (Elapsed Time)per Trans
Statistic1st2nd%Diff1st2nd%Diff1st2nd%Diff1st2nd%Diff
db block changes5,960,523,0245,506,966,155-7.614,314.982,949.08-31.6591,955.5584,981.58-7.58197.84182.12-7.95
execute count401,158,419394,888,894-1.56290.41211.47-27.186,188.846,093.79-1.5413.3213.06-1.95
gc cr block receive time1,669,7071,766,8435.821.210.95-21.4925.7627.275.860.060.060
gc cr blocks received23,064,69323,417,6691.5316.712.54-24.91355.83361.371.560.770.770
gc current block receive time2,755,5701,104,899-59.91.990.59-70.3542.5117.05-59.890.090.04-55.56
gc current blocks received26,915,90321,589,244-19.7919.4911.56-40.69415.24333.16-19.770.890.71-20.22
logons cumulative79,14694,17818.990.060.05-16.671.221.4518.85000
opened cursors cumulative163,696,327159,404,749-2.62118.585.36-27.972,525.412,459.88-2.595.435.27-2.95
parse count (total)151,781,535151,278,949-0.33109.8881.01-26.272,341.602,334.48-0.35.045-0.79
parse time elapsed420,941508,40520.780.30.27-106.497.8520.960.010.02100
physical reads6,312,117,7156,677,416,9395.794,569.513,575.88-21.7497,379.75103,043.565.82209.52220.835.4
physical writes307,952,792438,965,56642.54222.94235.075.444,750.926,773.9642.5810.2214.5242.07
redo size1,188,599,573,7921,134,034,937,892-4.59860,458.40607,296.87-29.4218,337,036.5117,500,030.91-4.5639,452.6637,503.47-4.94
session cursor cache hits16,018,38915,796,254-1.3911.68.46-27.07247.12243.76-1.360.530.52-1.89
session logical reads37,165,610,35335,782,418,780-3.7226,905.1619,162.15-28.78573,369.85552,181.78-3.71,233.621,183.35-4.07
user calls1,311,953,2951,353,637,0363.18949.76724.9-23.6820,240.0720,888.853.2143.5544.772.8
user commits30,127,13730,237,9930.3721.8116.19-25.77464.78466.620.4110
user rollbacks10014141000000000
workarea executions - onepass18561-67.03000000000
workarea executions - optimal32,184,54832,572,2581.223.317.44-25.15496.52502.641.231.071.080.93

           

Other Instance Activity Stats
Ordered by statistic name
Valueper Second (DB time)per Second (Elapsed Time)per Trans
Statistic1st2nd%Diff1st2nd%Diff1st2nd%Diff1st2nd%Diff
transaction rollbacks1,148,7741,144,077-0.410.830.61-26.5117.7217.65-0.40.040.040
transaction tables consistent read rollbacks382,182383,7900.420.280.21-255.95.920.340.010.010
transaction tables consistent reads - undo records applied94,081,724174,332,73685.368.1193.3637.071,451.442,690.2485.353.125.7784.94
rollback changes - undo records applied31,833,45563,051,93998.0723.0533.7746.51491.1197398.121.062.0997.17
rollbacks only - consistent read gets2,463,7233,084,06725.181.781.65-7.338.0147.5925.20.080.125
cleanout - number of ktugct calls468,851,008470,343,1090.32339.41251.88-25.797,233.177,258.170.3515.5615.55-0.06
cleanouts and rollbacks - consistent read gets49,846,25617,909,477-64.0736.099.59-73.43769276.37-64.061.650.59-64.24
cleanouts only - consistent read gets320,381,864286,709,747-10.51231.93153.54-33.84,942.674,424.40-10.4910.639.48-10.82

          

Operating System Statistics
Ordered by 'Statistic Name'
Value (centi-seconds)per Second (DB time)per Second (Elapsed Time)per Trans
Statistic Name1st2nd1st2nd%Diff1st2nd%Diff1st2nd%Diff
BUSY_TIME66,313,64169,228,13648.0137.07-22.791,023.051,068.304.422.22.294.09
FREE_MEMORY_BYTES1,997,733,888-646,643,7121,446.21-346.29-123.9430,819.90-9,978.78-132.3866.31-21.39-132.26
GLOBAL_RECEIVE_SIZE_MAX00000000000
GLOBAL_SEND_SIZE_MAX00000000000
IDLE_TIME137,841,014134,531,07999.7972.04-27.812,126.532,076.04-2.374.584.45-2.84
INACTIVE_MEMORY_BYTES-120,803,328-137,617,408-87.45-73.7-15.72-1,863.68-2,123.6613.95-4.01-4.5513.47
IOWAIT_TIME25,36426,2630.020.01-500.390.415.13000
NICE_TIME242,236240,2360.180.13-27.783.743.71-0.80.010.010
RSRC_MGR_CPU_WAIT_TIME00000000000
SWAP_FREE_BYTES00000000000
SYS_TIME10,147,37610,610,9187.355.68-22.72156.55163.744.590.340.352.94
TCP_RECEIVE_SIZE_DEFAULT00000000000
TCP_RECEIVE_SIZE_MAX00000000000
TCP_RECEIVE_SIZE_MIN00000000000
TCP_SEND_SIZE_DEFAULT00000000000
TCP_SEND_SIZE_MAX00000000000
TCP_SEND_SIZE_MIN00000000000
USER_TIME53,940,22755,728,28539.0529.84-23.59832.16859.983.341.791.842.79
VM_IN_BYTES00000000000
VM_OUT_BYTES00000000000
Comments
Post Details
Added on Nov 3 2019
7 comments
1,364 views