Example of sql performance degrading as data grows

Ran into an example this week using my sqlstat.sql 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

About Bobby

I live in Chandler, Arizona with my wife and three daughters. I work for US Foods, the second largest food distribution company in the United States. I've been working as an Oracle database administrator and PeopleSoft administrator since 1994. I'm very interested in Oracle performance tuning.
This entry was posted in Uncategorized. Bookmark the permalink.

Leave a Reply