Bobby Durrett's DBA Blog

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

They say you learn more from your mistakes than your successes.  I’ve been making a big mistake with a script I was using to tell how many logons had occurred between two AWR snapshots.  I don’t want to lead anyone astray by posting the broken script so here is the one that works:

select 
to_char(sn1.END_INTERVAL_TIME,'YYYY-MM-DD HH24:MI:SS')
 first_snapshot_datetime,
to_char(sn2.END_INTERVAL_TIME,'YYYY-MM-DD HH24:MI:SS')
 second_snapshot_datetime,
after.value-before.value
from 
DBA_HIST_SYSSTAT before, 
DBA_HIST_SYSSTAT after, 
dba_hist_snapshot sn1,
dba_hist_snapshot sn2
where 
before.stat_name='logons cumulative' and
before.stat_name=after.stat_name and
after.snap_id =(select min(ss.snap_id) 
from dba_hist_snapshot ss 
where ss.snap_id > before.snap_id) and
before.snap_id=sn1.snap_id and
after.snap_id=sn2.snap_id
order by before.snap_id;

This takes the total number of logons as recorded by the system statistic “logons cumulative” at the end of one interval and subtracts it from the same statistic as recorded at the end of the next interval.  But my original script used BEGIN_INTERVAL_TIME and only on the first snapshot so I thought the interval was one hour earlier than it really was.  So, I guess the message here is that if you want to get the difference between a system statistic value as recorded by two snapshots use END_INTERVAL_TIME of each snapshot to show you the time frame you are really examining.

– Bobby

P.S. Here is some output from the working script:

FIRST_SNAPSHOT_DATE SECOND_SNAPSHOT_DAT AFTER.VALUE-BEFORE.VALUE
------------------- ------------------- ------------------------
2012-05-15 00:00:01 2012-05-15 01:00:19                      286
2012-05-15 01:00:19 2012-05-15 02:00:33                      186
2012-05-15 02:00:33 2012-05-15 03:00:46                      184
2012-05-15 03:00:46 2012-05-15 04:00:59                      179
2012-05-15 04:00:59 2012-05-15 05:00:12                      201
2012-05-15 05:00:12 2012-05-15 06:00:26                      294

I’m working on a performance toolkit with a coworker of mine. It is great to have someone else to use the tools I’ve been using, streamline them, and document them for the rest of our team.

To figure out what to include in our toolkit I reviewed the performance problems I had worked on for the past couple of years. I keep a folder on a network drive for each incident. I found three scripts (or groups of scripts) that I used more than any other.  So, we decided to document these for the team. I use a bunch of other scripts so it is interesting to think about why these three are the top of the list.  Here is what they are:

AWR report – this is just the standard Oracle delivered AWR report $ORACLE_HOME/rdbms/admin/awrrpt.sql.  Shows the difference between two snapshots of the V$ tables.

getplans.sql – documented in this post. Gets all the plans for a given sql_id.

optimizerstatistics – documented in my SEOUC presentation. Dumps out all the statistics for tables used by a query you are tuning.

So, the process boils down to using the AWR report to find a problem SQL query, using getplans.sql to get the plan(s) for that query, and using the querytuning scripts to dump out the stats for the tables used by that problem query.

But, I use a bunch of other scripts and tools besides these so why are these the top three?  I think it must be because much of the time performance problems boil down to SQL tuning or at least the need for SQL tuning needs to be explored.  But it remains to be seen how well my coworker and I can communicate this to our team and how helpful it would be to just have these three tools as an initial information gathering tool when a performance problem comes in.

– Bobby

I have this test script I use to remind myself of the fastest way I’ve found to copy data into an Oracle table.  It shows three things:

1. Fast way to create a new table populating with data
2. Fast way to create an index on a large table
3. Fast way to insert a lot of data into a table

The essence of this is that you want everything done nologging, in parallel, and using direct path.

In this example we have two tables – source and target.  We are copying data from source to target.  Here is how we create a new table called target with all the data in source:

create table target parallel 4 nologging as 
select /*+parallel(source 4) */ * from source;

The parallel 4 makes the inserts into the target table be done with 4 parallel processes.  Nologging prevents these changes from going to the redo logs for recovery.  The hint – parallel (source 4) – causes the source table to be queried with four parallel processes.  What makes this so fast is that both the select and insert are done in parallel.  Also, in this “nologging create table as select” scenario the database uses direct path inserts which loads the blocks up in bulk rather than one row at a time.

Next I build an index on the target table:

create index target_idx on target (KEY1) parallel 4 nologging;

This is fast because again you are not logging to the redo logs and you are using 4 parallel processes.

Lastly, and most important this is how to insert a lot of data into an existing table very quickly:

ALTER SESSION ENABLE PARALLEL DML;

insert into target select /*+parallel(source 4) */* from source;

This assumes your target table was created with parallel 4 just as in our previous example.  The alter session command is essential because without it the database will not insert the data in parallel.  If you do the alter session and the target table has parallel greater than 1 then your insert will be in parallel and it will use direct path load.  But, you also have to make sure your query is done with equal parallelism.  In this example the target table was parallel 4 so the parallel hint on the select makes the select parallel 4.

Here is the plan for the insert statement:

The key here is the LOAD AS SELECT which tells you it is using direct path inserts.  Also, the PARALLEL_… on the LOAD tells you it is loading in parallel.  Lastly the PX BLOCK ITERATOR tells you it is querying the table in parallel.  You can’t have any of these missing or else you won’t have the fastest way to do the insert: parallel read and write and direct path insert.

– Bobby

Click here for a simple but useful script that shows how the execution of a given query has changed over time. (current version).

This script just queries DBA_HIST_SQLSTAT for a given sql_id. A sql_id corresponds to a single SQL query.  I’ve changed the units to milliseconds because I think in terms of disk reads which take a few milliseconds each.

Here is the text of the query:

select ss.sql_id,
sn.END_INTERVAL_TIME,
ss.executions_delta,
ELAPSED_TIME_DELTA/(executions_delta*1000) "Elapsed Average ms",
CPU_TIME_DELTA/(executions_delta*1000) "CPU Average ms",
IOWAIT_DELTA/(executions_delta*1000) "IO Average ms",
BUFFER_GETS_DELTA/executions_delta "Average buffer gets",
DISK_READS_DELTA/executions_delta "Average disk reads"
from DBA_HIST_SQLSTAT ss,DBA_HIST_SNAPSHOT sn
where ss.sql_id = '7gnz0zx8070n9'
and ss.snap_id=sn.snap_id
and executions_delta > 0
order by ss.snap_id,ss.sql_id;

I’ve hard coded the sql_id as 7gnz0zx8070n9 but you would change that to the sql_id of the query you want to investigate.  You can get the sql_id from an AWR report.

Typical output:

SQL_ID        END_INTERVAL_TIME         EXECUTIONS_DELTA Elapsed Average ms CPU Average ms IO Average ms Average buffer gets Average disk reads
------------- ------------------------- ---------------- ------------------ -------------- ------------- ------------------- ------------------
7gnz0zx8070n9 14-MAY-12 12.00.04.795 PM               11         84726.4826     29198.7186    1606.64882          37011.7273         2950.72727
7gnz0zx8070n9 14-MAY-12 01.00.31.734 PM               18         176928.853     40828.9464    11324.6743          288660.056         15410.1111
7gnz0zx8070n9 14-MAY-12 02.00.05.723 PM               11         213522.486      58663.698    16163.4455          576307.545         24678.5455
7gnz0zx8070n9 14-MAY-12 03.00.43.561 PM               27         224199.385     61645.2061    7544.87026              898836         4479.62963
7gnz0zx8070n9 14-MAY-12 04.00.04.411 PM                5         104387.372     60219.0786     7351.9572           1546004.2             4287.6
7gnz0zx8070n9 21-MAY-12 12.28.46.943 PM               15         72550.5727     28886.7986     3299.5736               67194         5001.86667
7gnz0zx8070n9 21-MAY-12 01.09.43.427 PM                9         166778.289     47970.0616    12468.9748          266338.111               7342
7gnz0zx8070n9 21-MAY-12 02.00.54.605 PM                7         335266.608     68207.2234    15403.1189          457152.143         17968.8571
7gnz0zx8070n9 21-MAY-12 03.00.42.256 PM               12         395749.327     57734.2631    25077.6642            701764.5              19920
7gnz0zx8070n9 21-MAY-12 04.01.00.514 PM               23         271734.101     66244.0698    7713.01161          2645183.43         3724.08696
7gnz0zx8070n9 21-MAY-12 05.00.30.643 PM                6         93118.3805     58891.7195      8212.002          1142748.67               3662

In this example we compare the May 14 run to the May 21 run of the same query.  The output shows two things:

1 – The query ran about the same number of times both weeks

2 – The run time, CPU and disk I/O per execution were about the same

If the number of executions for one week over the next were different that would indicate a change in query volume.  If the per execution times were different that would indicate a change in the way each query ran.

Pretty simple, but helpful when tracking down whether a query is behaving the same today as the last time it ran.

– Bobby

I use this script all the time to get the plans for a given SQL statement I’ve identified from an AWR report:

getplans.sql

Recently I’ve found out that you can do something like this with the delivered awr script $ORACLE_HOME/rdbms/admin/awrsqrpt.sql

But, I like my version because it dumps out a text version of the plans and it shows me the last AWR snapshot that had the given plan.  This is helpful if you want to tell when the plan changed.

Here is how you run it:

SQL> @getplans j3h4j56k6j

Where j3h4j56k6j is a sql_id you’ve found in your AWR report.

– Bobby

One of my coworkers asked a really good question:
“Where is the documentation that explains all the sections of the AWR report?”

The answer is that there is no comprehensive section-by-section documentation of an AWR report.

But, there is a note on Oracle’s support site that gives examples of how to use AWR reports:

FAQ: How to Use AWR reports to Diagnose Database Performance Issues [ID 1359094.1]

The AWR report contains the difference between two snapshots of the V$ views.  So, to understand what is listed on a section of the AWR report you must find the V$ view it is based on.  The snapshots of the V$ views are visible in the DBA_HIST views.

Here is an example of a mapping of a section of an AWR report to the V$ view:

“SQL ordered by Elapsed Time” -> DBA_HIST_SQLSTAT -> V$SQL

You find this mapping by reviewing the DBA_HIST and V$ views and comparing what they contain with what the AWR report contains.  You make a guess based on the contents of the report and the descriptions of the columns.

I had discussed this and appreciate the input from the people on these two forum threads:

Orafaq thread

OTN thread

– Bobby

I couldn’t help notice the Oracle product placement in The Avengers movie as I watched it for the second time in two weeks with my eleven year old daughter.  I was wondering what sort of systems they were supposed to be, but Oracle has a page on their site all about this:

http://www.oracle.com/us/theavengers/index.html – NO LONGER EXISTS

It is good to know that the superheroes of the world run on Oracle 🙂

– Bobby

I’ve updated the “Resources” page on my blog to include all my old presentation, papers, and scripts that I’ve published before.  I used to have a free Geocities blog but that disappeared.  I’ve been waiting to see if this new one – which I’m paying a small amount for – is stable before loading my old stuff.  It looks good.

Here is my resources page. You  can also find this off the menu on my blog.

– Bobby

I’ve done an update on my introduction to SQL tuning paper.

Updated paper as of 05/29/2012

Example SQL script and its log – in zip with paper

I’ve added cardinality hint and breakup of a SQL query into smaller pieces with global temporary tables holding the results.  Hopefully I’ve cleaned up a few things.  Also put section headers to make the outline clear – intro, join order, join method, access method, conclusion.

– Bobby