Outer join – where do I put the (+)?

I can never remember where to put the (+) symbols in an Oracle SQL query to make it have an outer join.  I rarely need to write a query with an outer join and when I do I have to build myself a test case to remember how it works.  I did this just today so I thought I’d blog it.

So, I setup two tables with one matching row and one non-matching.  They have one column x which I will join on.

create table a (x number);
create table b (x number);

insert into a values (1);
insert into a values (2);

insert into b values (1);
insert into b values (3);

commit;

So then I join these putting the (+) outer join operator in different places until I find a couple that don’t have syntax errors.  Here is the result:

SQL> select a.x,b.x
  2  from a,b
  3  where a.x=b.x(+);

         X          X
---------- ----------
         1          1
         2

SQL> select a.x,b.x
  2  from a,b
  3  where a.x(+)=b.x;

         X          X
---------- ----------
         1          1
                    3

So, when I see this I think about the real query I’m building and I ask myself “which table gets the (+)?”  So, I think that the side with the (+) is the side that doesn’t have to match.  In the first case table b only matches where x=1 but you see both of a’s records  x=1 and 2.  The second query reverses it.  Or, another way to say this is that the side of the equals sign without the outer join symbol has all of its rows returned and the other side only has the matching rows.

The other thing that confuses me is constants.  Do we need the outer join symbol with a where clause condition on a constant, i.e. on a condition that doesn’t join the two tables?

SQL> select a.x,b.x
  2  from a,b
  3  where a.x(+)=b.x
  4  and a.x=2;

no rows selected

SQL> select a.x,b.x
  2  from a,b
  3  where a.x(+)=b.x
  4  and a.x(+)=2;

         X          X
---------- ----------
                    3
                    1

I would think that the first query would return the same results as the second but it doesn’t.  I guess the meaning of the first query is that you only return rows where a.x=2.  The column a.x is null on the row where a doesn’t match b.  The a row that does match b has a.x=1.  No neither null or 1 equals 2 so you get no rows returned.

The second query is weird because a is null for both of b’s values of x.  But I think the way this works is that the condition a.x=2 is first applied leaving a with one row with x=2.  Then the database treats both rows in b as non-matching because x <> 2 for both rows in b so a.x is null in the output.

So, maybe it is safe to say that without the (+) the database applies the condition after the join and with (+) the database applies the condition before it.

Not very profound but at least having this on my blog will be something I can refer to a month from now when I need this again.

– Bobby

P.S. I was looking at the plans of the two examples with constants and they show how the database processes the two cases. Here is a zip of the example script and its output: zip

Plan with a.x=2:

-----------------------------------
| Id  | Operation          | Name |
-----------------------------------
|   0 | SELECT STATEMENT   |      |
|*  1 |  HASH JOIN         |      |
|*  2 |   TABLE ACCESS FULL| A    |
|*  3 |   TABLE ACCESS FULL| B    |
-----------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("A"."X"="B"."X")
   2 - filter("A"."X"=2)
   3 - filter("B"."X"=2)

Plan with a.x(+)=2:

-----------------------------------
| Id  | Operation          | Name |
-----------------------------------
|   0 | SELECT STATEMENT   |      |
|*  1 |  HASH JOIN OUTER   |      |
|   2 |   TABLE ACCESS FULL| B    |
|*  3 |   TABLE ACCESS FULL| A    |
-----------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("A"."X"="B"."X")
   3 - filter("A"."X"=2)

Notice that the first plan does not do an outer join at all. It filters out all the rows in A and B that don’t have x=2. Then it does a normal hash join. I guess the optimizer transforms the outer join into a standard hash join because it knows that only rows with x=2 from both tables will fulfill the conditions.

The second plan does the outer join but it filters out all rows in A except those that have x=2. Then it does the outer join with the rows in A that survived the filter.

P.P.S. ANSI join versions of the four (+) queries listed in main post:

SQL> select a.x,b.x
  2  from a
  3  left join b
  4  on a.x=b.x;

         X          X
---------- ----------
         1          1
         2

SQL> 
SQL> select a.x,b.x
  2  from a
  3  right join b
  4  on a.x=b.x;

         X          X
---------- ----------
         1          1
                    3

SQL> 
SQL> select a.x,b.x
  2  from a
  3  right join b
  4  on a.x=b.x
  5  where a.x=2;

no rows selected

SQL> 
SQL> select a.x,b.x
  2  from a
  3  right join b
  4  on a.x=b.x
  5  and a.x=2;

         X          X
---------- ----------
                    3
                    1

ANSI joins example script and log: zip

Posted in Uncategorized | 26 Comments

Testing the performance effect of a change that changes plans

Download this zip of the example scripts and their logs.

This post is to describe how I go about testing the performance affects of a change that has the potential to change the execution plans of many queries.  For example, adding a new index could change the plan of every query that uses the indexed table.  Similarly, changing the way the optimizer statistics are gathered on a table could modify all of plans that involve that table.

One way you could test the effect of a potential plan changing change would be to exercise the various parts of the application on a test database before making the change, make the change, and then test the application again afterwards.  But, as a database administrator I usually don’t know how to run a comprehensive application test myself.  So, an imperfect but helpful alternative is to grab a substantial number of application SQL queries that were run on production and get their plans on a test database with and without the proposed change.  Those whose plans change should then be run both ways to see if the plan change resulted in a worse or better run time.

Here are the files in the zip and what they represent.  Note that I just ran these on a test database to get a simple example.  It isn’t a full scale real production example so it is overly simple.  Here is what’s in the zip and how they would be used in a real test of a potential production change:

createclobtable.sql – This script should be run on your production database to gather SQL statements that meet whatever criteria you define.  In a real situation I would run this script on production and then export the table sqlclobs from my schema on production and import it into my schema on test.

ORCLcreateclobtable.log – this is the output from running the previous script on my sample database.  It is setup to give me up to 3000 SQL statements that have the string “PLANTEST” in their query.  Imagine that you wanted to add an index on a table called PLANTEST.  Then you would want to get all the production SQLs with this table in their text.  Also, if you had an active production system you might want to limit this SQL text extract to the first 3000 so it isn’t too huge an output to work with.

So, to use the script yourself change

((SQL_TEXT like '%PLANTEST%')) and

to whatever criteria you want to limit the SQL statements to the ones that could be impacted by your change.  Change this to the number of results you want – change from 3000:

        EXIT WHEN sqlnumber > 3000;

makeplans.sql – creates an explain plan for every SQL statement in the table created by the previous script.  In a real scenario I would run this on my test database after importing the table sqlclobs into my schema.  I would run it once before making my proposed change and then again after making the change.  Then I would run a diff (unix text file comparison utility) against the two outputs.  This identifies the changed plans.  Then I would go back to the SQL statements whose plans have changed and run them both with and without the change.  Note that I have a number associated with each SQL statement in the table sqlclobs.  This number relates the plan with the query.  So, the first plan is number 1 and the first SQL text is number 1 and so on sequentially afterward.

ORCLmakeplans.log – this is just the output from my simple test.  I ran the script testquery.sql to create the table PLANTEST and run a query against it.  Then I created an AWR snapshot to record these SQL statements in the AWR.  Interestingly only the create table as select statement that populated PLANTEST with data was caught by the AWR.  The select statement must have run too quickly to be considered a top query.  Here is some sample output, the plan of the create table as select:

1 CREATE TABLE STATEMENT
1 LOAD AS SELECT  PLANTEST
1 HASH JOIN
1 FIXED TABLE FULL X$KSPPCV TABLE (FIXED)
1 MERGE JOIN CARTESIAN
1 HASH JOIN RIGHT OUTER
1 TABLE ACCESS FULL SEG$ CLUSTER
1 HASH JOIN RIGHT OUTER
1 TABLE ACCESS FULL USER$ CLUSTER
1 HASH JOIN RIGHT OUTER
1 TABLE ACCESS FULL DEFERRED_STG$ TABLE
1 HASH JOIN OUTER
1 HASH JOIN OUTER
1 HASH JOIN
1 TABLE ACCESS FULL USER$ CLUSTER
1 HASH JOIN
1 HASH JOIN
1 TABLE ACCESS FULL TS$ CLUSTER
1 TABLE ACCESS FULL TAB$ CLUSTER
1 TABLE ACCESS FULL OBJ$ TABLE
1 INDEX FAST FULL SCAN I_OBJ2 INDEX (UNIQUE)
1 INDEX FAST FULL SCAN I_OBJ1 INDEX (UNIQUE)
1 BUFFER SORT
1 FIXED TABLE FULL X$KSPPI TABLE (FIXED)

I’ve eliminated all of the indention intentionally.  Normally you like to see a plan as a tree with indention to mark the branches.  But, to make it easy to run a diff on the two executions of makeplans.sql I made the plan output something that would only differ if the plan was really different – if that makes sense!  Before I eliminated the indention and other extraneous details I was getting some false differences so I simplified the plan output to this point for ease of comparison.

I know that these scripts could be more user friendly, but these are scripts I really use and they have been a big help to me.  Also the concepts themselves have value and others could no doubt improve on the scripting while applying the same ideas in their own work.

– Bobby

 

 

Posted in Uncategorized | 1 Comment

East Coast Oracle Users Conference

I’ll be doing my Introduction to SQL Tuning talk at the East Coast Users Conference in October.  Come check it out!

– Bobby

Posted in Uncategorized | Leave a comment

Slow insert into stattab with extended statistics

We have hit what is probably a bug on our 11.1 database.  Our optimizer statistics gathering job has been running for hours and consuming a ton of CPU resources.  When we look at an AWR report for this period of time we see inserts into the stattab as the longest running SQL!  Here are the two top inserts, with the stattab name renamed to make it generic:

insert into “TEST”.”STATTAB” select /*+ rule */ :5 statid, ‘C’ type, :6 version, bitand(h.spare2, 7) flags, ot.name c1, null c2, null c3, c.name c4, u.name c5, h.distcnt n1, h.density n2, h.spare1 n3, h.sample_size n4, h.null_cnt n5, h.minimum n6, h.maximum n7, h.avgcln n8, decode(h.cache_cnt, 0, null, 1) n9, hg.bucket n10, hg.endpoint n11, null n12, h.timestamp# d1, h.lowval r1, h.hival r2, hg.epvalue ch1, null cl1 from sys.user$ u, sys.obj$ ot, sys.col$ c, sys.hist_head$ h, histgrm$ hg where :3 is null and u.name = :1 and ot.owner# = u.user# and ot.name = :2 and ot.type# = 2 and c.obj# = ot.obj# and (:4 is null or c.name = :4) and h.obj# = ot.obj# and h.intcol# = c.intcol# and hg.obj#(+) = h.obj# and hg.intcol#(+) = h.intcol# union all select :5 statid, ‘C’ type, :6 version, bitand(h.spare2, 7) flags, ot.name c1, op.subname c2, null c3, c.name c4, u.name c5, h.distcnt n1, h.density n2, h.spare1 n3, h.sample_size n4, h.null_cnt n5, h.minimum n6, h.maximum n7, h.avgcln n8, decode(h.cache_cnt, 0, null, 1) n9, hg.bucket n10, hg.endpoint n11, null n12, h.timestamp# d1, h.lowval r1, h.hival r2, hg.epvalue ch1, null cl1 from sys.user$ u, sys.obj$ ot, sys.col$ c, sys.tabpart$ tp, sys.obj$ op, sys.hist_head$ h, histgrm$ hg where u.name = :1 and ot.owner# = u.user# and ot.name = :2 and ot.type# = 2 and c.obj# = ot.obj# and (:4 is null or c.name = :4) and tp.bo# = ot.obj# and tp.obj# = op.obj# and ((:3 is null and :vc_cascade_parts is not null) or op.subname = :3) and h.obj# = op.obj# and h.intcol# = c.intcol# and hg.obj#(+) = h.obj# and hg.intcol#(+) = h.intcol# union all select :5 statid, ‘C’ type, :6 version, bitand(h.spare2, 7) flags, op.name c1, op.subname c2, null c3, c.name c4, u.name c5, h.distcnt n1, h.density n2, h.spare1 n3, h.sample_size n4, h.null_cnt n5, h.minimum n6, h.maximum n7, h.avgcln n8, decode(h.cache_cnt, 0, null, 1) n9, hg.bucket n10, hg.endpoint n11, null n12, h.timestamp# d1, h.lowval r1, h.hival r2, hg.epvalue ch1, null cl1 from sys.user$ u, sys.col$ c, sys.tabcompart$ tp, sys.obj$ op, sys.hist_head$ h, histgrm$ hg where u.name = :1 and op.owner# = u.user# and op.name = :2 and op.type# = 19 and ((:3 is null and :vc_cascade_parts is not null) or op.subname = :3) and tp.obj# = op.obj# and c.obj# = tp.bo# and (:4 is null or c.name = :4) and h.obj# = op.obj# and h.intcol# = c.intcol# and hg.obj#(+) = h.obj# and hg.intcol#(+) = h.intcol# union all select :5 statid, ‘C’ type, :6 version, bitand(h.spare2, 7) flags, op.name c1, op.subname c2, os.su bname c3, c.name c4, u.name c5, h.distcnt n1, h.density n2, h.spare1 n3, h.sample_size n4, h.null_cnt n5, h.minimum n6, h.maximum n7, h.avgcln n8, decode(h.cache_cnt, 0, null, 1) n9, hg.bucket n10, hg.endpoint n11, null n12, h.timestamp# d1, h.lowval r1, h.hival r2, hg.epvalue ch1, null cl1 from sys.user$ u, sys.col$ c, sys.tabcompart$ tp, sys.obj$ op, sys.tabsubpart$ ts, sys.obj$ os, sys.hist_head$ h, histgrm$ hg where u.name = :1 and op.owner# = u.user# and op.name = :2 and op.type# = 19 and tp.obj# = op.obj# and c.obj# = tp.bo# and (:4 is null or c.name = :4) and ts.pobj# = tp.obj# and ts.obj# = os.obj# and ((:3 is null and :vc_cascade_parts is not null) or (op.subname = :3 and (:vc_cascade_parts is not null — cascade to subpart or os.subname is null)) — matches partition itself or os.subname = :3) and — matches subpartition h.obj# = os.obj# and h.intcol# = c.intcol# and hg.obj#(+) = h.obj# and hg.intcol#(+) = h.intcol# order by c5, c1, c2, c3, c4, n10

insert into “TEST”.”STATTAB” (statid, type, version, flags, c1, c4, c5, cl1) select /*+ rule */ :5 statid, ‘E’ type, :6 version, 256, ot.name c1, c.name c4, u.name c5, to_lob(c.default$) cl1 from sys.user$ u, sys.obj$ ot, sys.col$ c where u.name = :1 and ot.owner# = u.user# and ot.name = :2 and ot.type# = 2 and c.obj# = ot.obj# and bitand(c.property, 32) = 32 and bitand(c.property, 65536) = 65536 and substr(c.name, 1, 6) = ‘SYS_ST’ and (:4 is null or c.name = :4) and (:5, ‘E’, :6, ot.name, c.name, u.name) not in (select statid, type, version, c1, c4, c5 from “TEST”.”STATTAB”)

We have some custom written statistics gathering scripts that were written before 11g came out.  Part of the design was to use a stattab to store the previous version of the statistics.  Theoretically if you had a performance problem you could revert back to the previous statistics or at least see what they were before the performance went south.  I believe that 11g comes with a feature like this built in.  Anyway, the database in question was setup with the standard pre-11g scripts and was working fine at first but then started getting the described terrible performance.  I traced this down to the tables with extended statistics.  In 11g you have the ability to add statistics on a grouping of columns  in a table.  This helps counter issues with correlated predicates on those columns.  But, there must be some bug related to backing up the extended statistics because in my testing I made a copy of a table without the extended stats and it ran fine.  With the extended stats added the above inserts were prevalent.

Anyway, this may not be of much use to anyone else, but if someone searches the web for the inserts listed they might be helped by this post.  Bottom line – extended stats on 11g and stattab – if the stattab insert is slow get rid of the stattab.  You probably don’t need it anyway on 11g.

– Bobby

Posted in Uncategorized | Leave a comment

Two ways to see predicates added by VPD or FGAC

We use a feature called “Virtual Private Database” or VPD on our 11g database.  This looks a lot like what used to be called “Fine Grained Access Control” or FGAC on our 10g database.  The idea behind both of these features is that a particular user in a particular situation would see a tailored view of the data rather than have all users see all of the data all the time.  VPD or FGAC accomplishes this feat by secretly adding predicates to a user’s query’s where clause predicates so they only see the rows allowed by that predicate.

The problem is that when you need to tune a poorly performing query that accesses tables protected by VPD you can’t see the real query through any of the normal methods.  Even a 10046 trace just gives you the unmodified query as the user ran it not the one with the new VPD additions.  I found two ways to see what the real where clause conditions are after the query is modified by VPD – dbms_xplan.display_cursor and 10053 trace.

Here is how to use dbms_xplan.display_cursor to show the VPD predicates:

SQL> select count(*) from test.table_list;

  COUNT(*)
----------
      1858

SQL> select * from table(
dbms_xplan.display_cursor(null,null,'ALLSTATS'));

PLAN_TABLE_OUTPUT
-------------------------------------------------------
SQL_ID  2fuam6x1dyt5v, child number 0
-------------------------------------
select count(*) from test.table_list

Plan hash value: 1374414456

--------------------------------------------------
| Id  | Operation          | Name       | E-Rows |
--------------------------------------------------
|   0 | SELECT STATEMENT   |            |        |
|   1 |  SORT AGGREGATE    |            |      1 |
|*  2 |   TABLE ACCESS FULL| TABLE_LIST |   2028 |
--------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("OWNER"<>'SYS')

Note that the predicate owner<>’SYS’ isn’t in the query but was added by the VPD.  The idea here is that the table TEST.TABLE_LIST contains a list of table names but the user doing the query doesn’t have permission to see the names of the tables owned by SYS.

Here is how to use a 10053 trace to see the VPD predicates:

ALTER SESSION SET EVENTS 
'10053 trace name context forever, level 1';

select /* comment to force parse */ count(*) from test.table_list;

ALTER SESSION SET EVENTS '10053 trace name context OFF';

trace output:

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT COUNT(*) "COUNT(*)" FROM "TEST"."TABLE_LIST" "TABLE_LIST" 
WHERE "TABLE_LIST"."OWNER"<>'SYS'

I had to add the comment to make sure the query got reparsed.  The 10053 trace only produces a trace when a query is parsed.  Note that the trace file has the description: “Final query after transformations”.  I’m not sure what all transformations are possible but it stands to reason that using a 10053 trace will give you a clearer picture of the real query being parsed.  It shows you the text the parser itself starts with before it starts to break it down into an execution plan that can be run.

– Bobby

p.s.  Here is a zip of a test script and trace file that demonstrates setting up VPD on a table and displaying the hidden predicate.

Posted in Uncategorized | 1 Comment

Newer sqlplus versions give better plan output

This is another funny thing I’ve been doing wrong for years.  I’ve been using an older version of sqlplus and missing out on the improvements made in the way autotrace displays a query’s execution plan.

Apparently somewhere around the version 10 of sqlplus they changed the autotrace command to use DBMS_XPLAN.DISPLAY to show the plan of a query run with set autotrace on.  But, I’ve never taken advantage of this feature because I’m using a 9.2 version of the Oracle client on my laptop.

You may wonder why anyone would use the 9.2 version of the Oracle client which is years old.  I do this because I have to support version 8 databases and the 9.2 client will connect to every version I have to support.  We do have a version 7 database but thankfully I don’t really need to access it very often and when I do I just login to the DB server.

So, this post may not be helpful to anyone, but if you are like me using an older version of sqlplus to run queries using “set autotrace on” you should use a more current version.  Of course, if like me you are supporting an 8i database then you will be stuck using a 9.2 or earlier client as I am.

Here is what the 9.2 client’s output looks like:

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=ALL_ROWS (Cost=2 Card=1 Bytes=2)
   1    0   TABLE ACCESS (FULL) OF 'DUAL' (TABLE) (Cost=2 Card=1 Bytes
      =2)

Here is what the 11.2 client’s output looks like:

Execution Plan
----------------------------------------------------------
Plan hash value: 3543395131

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |     2 |     2   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| DUAL |     1 |     2 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("DUMMY"<>' ')

Pretty cool.

– Bobby

Posted in Uncategorized | Leave a comment

Three ways to get a plan with dbms_xplan

Click here to get a zip of the three different scripts I talk about in this post.

There are two different functions in the Oracle supplied package DBMS_XPLAN that I use all the time for tuning SQL queries, DBMS_XPLAN.DISPLAY and DBMS_XPLAN.DISPLAY_AWR.

DBMS_XPLAN.DISPLAY extracts a query’s plan from a plan_table, which is populated by running the EXPLAIN PLAN statement on the query.  I use the script fullplan.sql to run DBMS_XPLAN.DISPLAY.  This script is great for a long running SQL statement when you just want to get a plan and not wait for the SQL to run.  If you are trying different ways to improve the statement and if you know what a fast plan looks like for the statement it is nice to just get the plan of your various attempted fixes.

DBMS_XPLAN.DISPLAY_AWR extracts the plan for a particular query that ran in the past.  We keep six weeks of AWR history so I can go back and find the plan of a problem query as it ran this week and as it ran a month ago.  Many times the plan has changed and then I just need to find out why and cause the query to use the original faster plan.  I use the script getplans.sql to call DBMS_XPLAN.DISPLAY_AWR.

One DBMS_XPLAN function I don’t use much, and probably should, is DBMS_XPLAN.DISPLAY_CURSOR.  This shows the plan of a SQL that is still cached in the shared pool.  The great thing about DISPLAY_CURSOR is that it shows you the plan the query really used when it ran and not the output from explain plan which doesn’t run the query.  Many times these are the same, but there are cases where they are different.  The files test.sql and test.log show how to use DBMS_XPLAN.DISPLAY_CURSOR to run a query and then get its plan.

My typical tuning process is to use getplans.sql to extract historical plans and then fullplan.sql to try different fixes and then run the modified and original queries to compare their run times.  But, in addition to the run time it is nice to see the plans used during the before and after tests to verify that the fix changed the plan as expected.

Right now when I test a query to see how long it runs and to get its plan I usually just use these sqlplus statements:

set autotrace on
set timing on

These give you a plan, timing, and some statistics about disk and memory block reads:

SQL> SELECT * from dual;

D
-
X

Elapsed: 00:00:00.00

Execution Plan
----------------------------------------------------------
0    SELECT STATEMENT Optimizer=ALL_ROWS (Cost=2 Card=1 Bytes=2)
1  0   TABLE ACCESS (FULL) OF 'DUAL' (TABLE) (Cost=2 Card=1 Bytes=2)

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          3  consistent gets
          0  physical reads
          0  redo size
        201  bytes sent via SQL*Net to client
        277  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

Set autotrace on runs an EXPLAIN PLAN statement against the query to generate an estimated plan so it doesn’t necessarily show you the plan your query really runs.  It also shows you some statistics about the way the query actually ran.  With DBMS_XPLAN.DISPLAY_CURSOR you can extract the actual plan after the query runs and it shows you statistics about how each step of the plan really ran.

SQL> SELECT /*+gather_plan_statistics*/ * from dual;

D
-
X

SQL>
SQL> SET LINESIZE 130
SQL> SET PAGESIZE 0
SQL> select * 
from table(dbms_xplan.display_cursor(null,null,'ALLSTATS'));

SQL_ID  266x2hrt9mwtp, child number 0
-------------------------------------

SELECT /*+gather_plan_statistics*/ * from dual

Plan hash value: 3543395131

------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------
|   1 |  TABLE ACCESS FULL| DUAL |      2 |      1 |      2 |00:00:00.01 |       6 |
------------------------------------------------------------------------------------

12 rows selected.

This shows the actual rows, actual time, and buffers for the one step of this simple plan.  I had to add the gather_plan_statistics hint to get these statistics.

Also, like DBMS_XPLAN.DISPLAY, DBMS_XPLAN.DISPLAY_CURSOR shows the predicates.  In the above example there is no where clause and hence no predicates.  But if we add a predicate like this:

SELECT /*+gather_plan_statistics*/ * from dual where dummy <> ' ';

Then you get the predicate from display_cursor:

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("DUMMY"<>' ')

Note that display_awr doesn’t give you the predicates, but you can’t have everything!

Time will tell if using DBMS_XPLAN.DISPLAY_CURSOR to run tests on queries and get their plan will replace my current method of using autotrace but it looks promising.  I’ve had a lot of success with DBMS_XPLAN.DISPLAY and DBMS_XPLAN.DISPLAY_AWR so it stands to reason that all three will work together to provide me the best methods to get execution plans for Oracle query tuning.

– Bobby

 

Posted in Uncategorized | 10 Comments

Example of sql performance degrading as data grows

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

Posted in Uncategorized | Leave a comment

DBA_HIST_SNAPSHOT BEGIN and END_INTERVAL_TIME

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
Posted in Uncategorized | Leave a comment

Working on Performance Toolkit

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.sqldocumented in this post. Gets all the plans for a given sql_id.

optimizerstatisticsdocumented 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

Posted in Uncategorized | 1 Comment