Ran into an example this week using my sqlstat.sql(updated) script to see how a query’s performance changed over time. Notice that the average disk reads per execution is steadily increasing as is the average elapsed time per execution:
select ss.sql_id, 2 sn.END_INTERVAL_TIME, 3 ss.executions_delta, 4 ELAPSED_TIME_DELTA/(executions_delta*1000) "Elapsed Average ms", 5 CPU_TIME_DELTA/(executions_delta*1000) "CPU Average ms", 6 IOWAIT_DELTA/(executions_delta*1000) "IO Average ms", 7 CLWAIT_DELTA/(executions_delta*1000) "Cluster Average ms", 8 APWAIT_DELTA/(executions_delta*1000) "Application Average ms", 9 CCWAIT_DELTA/(executions_delta*1000) "Concurrency Average ms", 10 BUFFER_GETS_DELTA/executions_delta "Average buffer gets", 11 DISK_READS_DELTA/executions_delta "Average disk reads" 12 from DBA_HIST_SQLSTAT ss,DBA_HIST_SNAPSHOT sn 13 where ss.sql_id = '802u1q8fvqc44' 14 and ss.snap_id=sn.snap_id 15 and executions_delta > 0 16 order by ss.snap_id,ss.sql_id; SQL_ID END_INTERVAL_TIME EXECUTIONS_DELTA Elapsed Average ms CPU Average ms IO Average ms Cluster Average ms Application Average ms Concurrency Average ms Average buffer gets Average disk reads ------------- ------------------------- ---------------- ------------------ -------------- ------------- ------------------ ---------------------- ---------------------- ------------------- ------------------ 802u1q8fvqc44 27-MAY-12 01.00.53.165 PM 76 4550.05576 512.894737 4205.39158 0 33.24925 4.67793421 30309.3947 23732.0263 802u1q8fvqc44 27-MAY-12 02.00.21.025 PM 43 4792.31077 607.44186 4360.49872 0 19.5679302 4.91506977 32833.1395 25584.3256 802u1q8fvqc44 27-MAY-12 03.00.18.224 PM 145 4417.90731 599.862069 4035.30441 0 5.09386207 1.46462759 33049.7448 25760.2621 802u1q8fvqc44 27-MAY-12 04.00.36.633 PM 229 4419.17388 598.820961 4019.30439 0 5.92725328 1.39149782 32770.0524 25543.9214 802u1q8fvqc44 27-MAY-12 05.00.15.884 PM 152 4992.60376 592.302632 4601.60099 0 6.62842105 .803697368 32602.4145 25416.0329 802u1q8fvqc44 03-JUN-12 01.00.34.649 PM 356 5025.73943 585 4657.40092 0 6.03489888 .756384831 31650.2865 27277.1798 802u1q8fvqc44 03-JUN-12 02.00.26.500 PM 176 5074.12577 631.761364 4647.03274 0 6.60205682 1.35873864 33081.9261 28509.4148 802u1q8fvqc44 03-JUN-12 03.00.53.393 PM 362 4974.11425 636.519337 4549.83139 0 5.3591326 .381052486 33267.2348 28668.6464 802u1q8fvqc44 03-JUN-12 04.00.27.109 PM 54 5009.35063 623.518519 4575.34676 0 9.82888889 2.92405556 33000.7593 28442.4074 802u1q8fvqc44 03-JUN-12 05.00.32.405 PM 354 4872.50067 626.525424 4456.90127 0 5.51079379 .899313559 33290.8672 28687.7853 802u1q8fvqc44 03-JUN-12 06.00.28.102 PM 378 4938.6356 628.280423 4522.84507 0 4.52484127 .79752381 33355.6931 28747.8016 802u1q8fvqc44 11-JUN-12 01.00.23.707 PM 16977 191.757352 79.0033575 80.4338613 0 .10159669 1.06228827 4768.66673 522.539848 802u1q8fvqc44 11-JUN-12 02.00.04.189 PM 46854 336.389179 63.5098391 272.984666 0 .467670636 .361043283 3613.40748 1550.09901 802u1q8fvqc44 11-JUN-12 03.00.48.296 PM 51434 462.159148 91.369911 371.236689 0 .573707586 .108251312 5070.58903 2055.70529 802u1q8fvqc44 11-JUN-12 04.00.41.573 PM 4375 6138.79435 696.914286 5697.08249 0 10.5047317 .026778743 37432.5838 31807.8965 802u1q8fvqc44 11-JUN-12 05.00.44.241 PM 4191 6435.63102 696.921976 5998.24776 0 9.45825889 .039125507 37423.3899 31801.2226 802u1q8fvqc44 11-JUN-12 06.01.00.011 PM 4297 6293.8751 704.728881 5831.22402 0 8.69642309 .028096114 37395.6109 31779.69 802u1q8fvqc44 11-JUN-12 07.00.14.168 PM 4109 6472.0113 705.222682 6012.87032 0 8.88741008 .026022147 37456.5505 31828.688 802u1q8fvqc44 11-JUN-12 08.00.59.167 PM 4518 6044.5061 702.248783 5588.6904 0 7.47196259 .02852324 37402.2512 31783.4332 802u1q8fvqc44 11-JUN-12 09.00.36.334 PM 3903 6885.61222 700.622598 6444.15398 0 5.99801127 .02731053 37349.4497 31737.6656 802u1q8fvqc44 11-JUN-12 10.00.18.204 PM 19088 4.04684524 4.10467309 .003602997 0 .032002881 .000181947 24.2372695 .001152557 802u1q8fvqc44 17-JUN-12 11.00.32.523 PM 6478 136.216292 75.182155 2.06508089 0 0 4.03177215 4226.01019 2.3956468 802u1q8fvqc44 18-JUN-12 12.00.54.969 AM 41745 486.488137 91.2849443 382.096094 0 1.08226401 .335159732 5334.13707 2160.18544 802u1q8fvqc44 18-JUN-12 01.00.17.578 AM 86938 134.188246 52.6724792 71.1402068 0 .100528802 .136617601 3029.96048 363.510019 802u1q8fvqc44 18-JUN-12 02.00.39.710 AM 3917 6975.09487 725.33061 6523.2955 0 5.98766862 .003856523 42785.9678 34902.3962 802u1q8fvqc44 18-JUN-12 03.00.48.153 AM 3921 6936.53108 726.090283 6479.83043 0 8.00393012 .006519765 42728.2244 34854.4583 802u1q8fvqc44 18-JUN-12 04.00.28.751 AM 3911 6925.22896 719.936078 6478.9565 0 4.71812196 .003972641 42717.774 34845.1723 802u1q8fvqc44 18-JUN-12 05.00.35.366 AM 4216 6462.49332 724.399905 5999.17317 0 4.72160721 .005662002 42641.4656 34783.9293 802u1q8fvqc44 18-JUN-12 06.00.25.077 AM 4139 6537.11419 724.935975 6074.58728 0 6.97848321 .003660063 42735.3663 34860.488 802u1q8fvqc44 18-JUN-12 07.00.47.635 AM 3664 7452.82414 744.241266 6968.81033 0 6.14636681 .025799945 42767.3139 34886.2615 802u1q8fvqc44 18-JUN-12 08.00.18.207 AM 3756 7157.32826 737.686368 6668.20073 0 5.91747045 .013735357 42587.308 34738.4135 802u1q8fvqc44 18-JUN-12 09.00.04.003 AM 25602 898.12377 109.259042 821.407491 0 .688565776 .00354691 6327.45528 4277.78814 802u1q8fvqc44 25-JUN-12 04.00.31.069 PM 25221 554.479071 126.651203 405.86581 0 1.0780948 .923108719 8317.96788 2139.04595 802u1q8fvqc44 25-JUN-12 05.00.06.023 PM 71794 207.469314 55.0378862 150.927739 0 .17914933 .348713834 3376.00794 792.932306 802u1q8fvqc44 25-JUN-12 06.00.25.713 PM 56496 484.258305 105.377372 367.74063 0 .427907268 .081330891 6417.41406 1900.56726 802u1q8fvqc44 25-JUN-12 07.00.46.577 PM 3212 8505.82402 882.303861 7942.8326 0 8.54433344 .022919676 57984.4788 38238.406 802u1q8fvqc44 25-JUN-12 08.00.09.860 PM 3437 7815.16069 874.346814 7239.25801 0 8.55406517 .019672389 56038.5333 38175.3678 802u1q8fvqc44 25-JUN-12 09.00.31.828 PM 3304 8264.60204 860.741525 7712.75074 0 7.77044128 .024324455 54189.1217 38188.5614 802u1q8fvqc44 25-JUN-12 10.00.53.313 PM 2710 10065.7573 851.782288 9565.58963 0 13.2508299 .026005535 52556.6672 38184.8424 802u1q8fvqc44 25-JUN-12 11.00.53.489 PM 3263 8349.20635 811.832669 7848.78782 0 7.34030432 .005171008 50744.1388 38046.4671 802u1q8fvqc44 26-JUN-12 12.00.04.490 AM 3422 7831.07274 800.926359 7330.73663 0 10.203848 .003371128 49157.2011 38193.5716 802u1q8fvqc44 26-JUN-12 01.00.35.140 AM 3338 8210.67996 790.22169 7729.04846 0 10.9132882 .004516477 47364.7055 38242.4233 802u1q8fvqc44 26-JUN-12 02.00.51.604 AM 3556 7697.60785 783.014623 7211.35294 0 7.08369348 .003949944 45831.2109 38124.7362 802u1q8fvqc44 26-JUN-12 03.00.05.212 AM 3530 7604.85364 779.045326 7115.06682 0 8.62746884 .004017847 45767.6714 38123.2076 802u1q8fvqc44 26-JUN-12 04.00.18.973 AM 27423 631.546164 82.5175947 572.039736 0 .68061164 .001258287 4798.57058 3007.29227 802u1q8fvqc44 01-JUL-12 08.00.08.190 PM 27424 132.767789 79.2116394 .644979252 0 0 1.12470457 4571.40789 .656906359 802u1q8fvqc44 01-JUL-12 09.00.51.146 PM 7313 3266.56101 425.323397 2795.03839 0 7.930214 .692773964 28115.6274 16279.6255 802u1q8fvqc44 01-JUL-12 10.00.11.954 PM 173854 86.1860254 49.045636 25.6670641 0 .047255956 .182451833 2889.93638 132.302961 802u1q8fvqc44 01-JUL-12 11.00.34.941 PM 3044 8960.83572 930.259527 8364.77014 0 8.1673502 .007529238 65950.6439 41434.7063 802u1q8fvqc44 02-JUL-12 12.00.45.692 AM 2919 8950.39508 920.037684 8306.22989 0 53.5768907 .318717026 64466.4491 41447.5005 802u1q8fvqc44 02-JUL-12 01.00.13.349 AM 2649 10110.4334 914.367686 9540.51111 0 4.26751642 .330056248 62844.8011 41389.6006 802u1q8fvqc44 02-JUL-12 02.00.47.194 AM 3011 9090.32049 890.567918 8537.87716 0 2.31629326 .009625374 61213.2405 41361.1023 802u1q8fvqc44 02-JUL-12 03.00.32.874 AM 3082 8757.92578 883.926022 8211.43049 0 7.73967813 .003743348 59631.8381 41432.2145 802u1q8fvqc44 02-JUL-12 04.00.05.192 AM 3166 8502.09514 875.246368 7959.14061 0 7.5716693 .003863866 57701.277 41258.9763 802u1q8fvqc44 02-JUL-12 05.00.22.285 AM 3314 8228.55345 869.849125 7683.39885 0 6.6919828 .00443271 56118.908 41390.4819 802u1q8fvqc44 02-JUL-12 06.00.45.080 AM 3379 8106.52728 859.872743 7572.49087 0 3.50910832 .005485943 54285.599 41375.9763 802u1q8fvqc44 02-JUL-12 07.00.25.427 AM 3067 8790.45427 866.149332 8244.55467 0 7.36902804 .011985654 52628.4689 41450.9941 802u1q8fvqc44 02-JUL-12 08.00.59.559 AM 2940 9299.19928 861.87415 8759.19049 0 8.3071085 .026342177 50765.2378 41328.1677 802u1q8fvqc44 02-JUL-12 09.00.21.414 AM 2848 9397.81077 841.685393 8883.13508 0 8.24150211 .04480302 49014.9442 41189.5348 802u1q8fvqc44 02-JUL-12 10.00.38.157 AM 3209 8485.45741 832.645684 7977.05293 0 7.4276943 .010869741 47819.7093 41431.287
We discovered that this query was doing a full scan on a subpartition. Apparently as the data grows in the heavily accessed subpartitions the average disk reads increases. There are more blocks to scan as time goes on. Our solution, not yet proven, is to force the query to use an index. It should be much less dependent on the size of the data in the subpartition with an index range scan.
– Bobby
