Bobby Durrett's DBA Blog

I was testing a script that did a lot of very short SQL statements and running many of them at the same time to bog down the CPU on the database server.  I kept seeing high “SQL*Net message from client” waits from my profiling SQL code.

Normally a profile of a single long running statement when there is a large CPU queue looks like this:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                             74        100
UNACCOUNTED_TIME                       37         50
CPU                                    37         50

This is a one CPU VM with two 100% CPU queries.  Each one’s CPU accounts for half of the total elapsed time leaving the other half unaccounted for.

But, take a high CPU load system and run a bunch of short sql statements the profile looks like this:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                             13        100
SQL*Net message from client             8         62
log file sync                           5         38
CPU                                     1          8

This is a script with a bunch of insert/commit combinations like this:

insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;

Without the high CPU load the profile is like this:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                              3        100
SQL*Net message from client             1         33
CPU                                     1         33
log file sync                           1         33

It looks like the SQL*Net message from client and log file sync times were both inflated by the high CPU load in the previous profile.

I tried this for shared and dedicated servers and for some reason shared servers reports even more SQL*Net waits for the same CPU load:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                             20        100
SQL*Net message from client            14         70
log file sync                           6         30
CPU                                     1          5

In further testing I was getting twice as many SQL*Net message from client waits for the same script with shared servers compared to dedicated so maybe that is why shared server connections are more sensitive to high CPU loads and report higher SQL*Net message from client waits.

Here is what the CPU looked like for the shared server example:

Notice the six loops – a simple C program with infinite loop.  These should be starving the other oracle processes for the CPU.  Note that this is the “c” option of top which is really helpful because it shows you the oracle process names like ora_lgwr_orcl similar to the default display on HP-UX’s glance tool.

So, I guess I was surprised that SQL*Net message from client waits were inflated by queuing on the CPU but it looks like they are.  This appears to be most visible when you have a lot of short run time SQL statements.

– Bobby

Hopefully this is not too redundant to previous posts but I’ve found that I keep using a particular script to debug performance issues and I thought I’d share it and explain what I use it for.  It’s helpful to me so I’m sure someone could use it unless they have their own tools which meet the same needs.

The first usergroup presentation I did was on the topic of profiles and was based on things I had learned a variety of places including Jeff Holt and Cary Millsap’s excellent book titled “Optimizing Oracle Performance”.

Out of all that came a simple set of SQL and sqlplus commands that I tag on to the end of a sqlplus script that I want to get a profile of.  In my case a profile includes:

• Real Elapsed time
• CPU
• Waits

The main point of my paper and the critical point I got from the Holt and Millsap book and other things was to compare the total waits and CPU to the real time.  So, this SQL/sqlplus code is a quick and dirty way to get this kind of profile for a sqlplus script that you are running as part of a performance testing exercise.  Here is the code:

VARIABLE monitored_sid number;

begin

SELECT sid into :monitored_sid from v$session 
where audsid=USERENV('SESSIONID');

end;
/

SELECT SID, substr(USERNAME,1,12) Username, 
substr(TIMESOURCE,1,30), SECONDS, 
ROUND(SECONDS/(SELECT ROUND((SYSDATE-LOGON_TIME)*24*60*60,0) 
FROM V$SESSION WHERE SID= :monitored_sid),2)*100 
AS PERCENTAGE
FROM
(SELECT logon_time, SID, username, 'TOTAL_TIME' TIMESOURCE,
ROUND((SYSDATE-LOGON_TIME)*24*60*60,0) SECONDS
FROM V$SESSION 
WHERE SID= :monitored_sid
UNION ALL
SELECT a.logon_time, a.SID,a.USERNAME,'CPU' TIMESOURCE,
ROUND((VALUE/100),0) SECONDS
FROM V$SESSION a, V$SESSTAT b
where a.SID = b.SID
and a.SID = :monitored_sid
and b.STATISTIC# = (SELECT STATISTIC# FROM V$STATNAME 
WHERE NAME='CPU used by this session')
UNION ALL
SELECT b.logon_time, a.SID,b.USERNAME,a.EVENT TIMESOURCE,
ROUND((TIME_WAITED/100),0) SECONDS
FROM V$SESSION_EVENT a, V$SESSION b
WHERE a.SID = b.SID
AND a.SID= :monitored_sid
UNION ALL
select b.logon_time, a.sid, b.username, 
'UNACCOUNTED_TIME' TIMESOURCE,
ROUND(MAX(SYSDATE-LOGON_TIME)*24*60*60,0)-
(ROUND(SUM((TIME_WAITED/100)),0)+ROUND(MAX(VALUE/100),0)) 
as UNACCOUNTED_FOR_TIME
FROM V$SESSION_EVENT a, V$SESSION b, V$SESSTAT c
WHERE a.SID = b.SID
AND b.sid = c.sid
and c.STATISTIC# = (SELECT STATISTIC# FROM V$STATNAME 
WHERE NAME='CPU used by this session')
AND a.SID= :monitored_sid
group by b.logon_time, a.sid, b.username)
order by SECONDS desc;

And here is some typical output:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                             43        100
direct path read                       30         70
CPU                                     5         12
db file scattered read                  4          9
db file sequential read                 4          9
Disk file operations I/O                0          0
SQL*Net message to client               0          0
SQL*Net message from client             0          0
events in waitclass Other               0          0
enq: KO - fast object checkpoi          0          0
UNACCOUNTED_TIME                       -1         -2

I left off the initial SID and username columns so the output would fit on this page, but if you run it you get that information as well.  The output contains waits and CPU which I think are typical but the two values TOTAL_TIME and UNACCOUNTED_TIME may be unusual.

TOTAL_TIME is the real elapsed time since the user first logged in to this session.

UNACCOUNTED_TIME is TOTAL_TIME-sum of the waits and CPU.  If there is a lot of queuing for the CPU then UNACCOUNTED_TIME goes up.

Here is a zip of an example of the use of this code in a script.

The idea is that you run the script like this:

username/password@dbname < profileexample.sql

If you want to learn how to use this kind of profile I would encourage you to read the paper, but the short answer is to just look at which is the biggest consumer of time – CPU, a particular wait, or something unknown, and let that lead the next steps of your investigation.

– Bobby

Today I saw two different plans with the same plan hash value but different numbers of partitions.  So, the partition numbers must not factor into the plan hash value.  So, you can’t count on the plan hash value to fully indicate whether two plans are the same.

I’ve taken the real plans and just modified the table and index names so I won’t expose our real names.  But, otherwise this is the real thing:

10/30/2013 plan

Plan hash value: 11498413

----------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name              | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
----------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | MERGE STATEMENT                         |                   |       |       |  4440 (100)|          |       |       |        |      |            |
|   1 |  MERGE                                  | TABLE_ONE         |       |       |            |          |       |       |        |      |            |
|   2 |   PX COORDINATOR                        |                   |       |       |            |          |       |       |        |      |            |
|   3 |    PX SEND QC (RANDOM)                  | :TQ10000          | 21446 |    45M|  4440   (1)| 00:01:03 |       |       |  Q1,00 | P->S | QC (RAND)  |
|   4 |     VIEW                                |                   |       |       |            |          |       |       |  Q1,00 | PCWP |            |
|   5 |      NESTED LOOPS OUTER                 |                   | 21446 |    45M|  4440   (1)| 00:01:03 |       |       |  Q1,00 | PCWP |            |
|   6 |       PX PARTITION RANGE ALL            |                   | 21446 |    22M|  1459   (1)| 00:00:21 |     1 |   156 |  Q1,00 | PCWC |            |
|   7 |        TABLE ACCESS BY LOCAL INDEX ROWID| TABLE_TWO         | 21446 |    22M|  1459   (1)| 00:00:21 |     1 |   156 |  Q1,00 | PCWP |            |
|   8 |         INDEX RANGE SCAN                | INDEX_TABLE_TWO   | 21593 |       |    26   (0)| 00:00:01 |     1 |   156 |  Q1,00 | PCWP |            |
|   9 |       TABLE ACCESS BY GLOBAL INDEX ROWID| TABLE_ONE         |     1 |  1145 |     0   (0)|          | ROWID | ROWID |  Q1,00 | PCWP |            |
|  10 |        INDEX UNIQUE SCAN                | PK_TABLE_ONE      |     1 |       |     0   (0)|          |       |       |  Q1,00 | PCWP |            |
----------------------------------------------------------------------------------------------------------------------------------------------------------

11/11/2013 plan

Plan hash value: 11498413

----------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name              | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
----------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | MERGE STATEMENT                         |                   |       |       |  4845 (100)|          |       |       |        |      |            |
|   1 |  MERGE                                  | TABLE_ONE         |       |       |            |          |       |       |        |      |            |
|   2 |   PX COORDINATOR                        |                   |       |       |            |          |       |       |        |      |            |
|   3 |    PX SEND QC (RANDOM)                  | :TQ10000          | 21966 |    46M|  4845   (1)| 00:01:08 |       |       |  Q1,00 | P->S | QC (RAND)  |
|   4 |     VIEW                                |                   |       |       |            |          |       |       |  Q1,00 | PCWP |            |
|   5 |      NESTED LOOPS OUTER                 |                   | 21966 |    46M|  4845   (1)| 00:01:08 |       |       |  Q1,00 | PCWP |            |
|   6 |       PX PARTITION RANGE ALL            |                   | 21966 |    22M|  1469   (1)| 00:00:21 |     1 |   208 |  Q1,00 | PCWC |            |
|   7 |        TABLE ACCESS BY LOCAL INDEX ROWID| TABLE_TWO         | 21966 |    22M|  1469   (1)| 00:00:21 |     1 |   208 |  Q1,00 | PCWP |            |
|   8 |         INDEX RANGE SCAN                | INDEX_TABLE_TWO   | 22638 |       |    33   (0)| 00:00:01 |     1 |   208 |  Q1,00 | PCWP |            |
|   9 |       TABLE ACCESS BY GLOBAL INDEX ROWID| TABLE_ONE         |     1 |  1151 |     0   (0)|          | ROWID | ROWID |  Q1,00 | PCWP |            |
|  10 |        INDEX UNIQUE SCAN                | PK_TABLE_ONE      |     1 |       |     0   (0)|          |       |       |  Q1,00 | PCWP |            |
----------------------------------------------------------------------------------------------------------------------------------------------------------

One of these queries was run on 10/30/2013 (the one with fewer partitions).  The other was run yesterday and is still running.  Looks like the range scan has a bunch more partitions worth of data today and that is why the query, despite the same plan hash value, is running longer.

The Pstop column has the high partition number so it looks like we had 156 partitions on 10/30 and 208 yesterday unless I’m missing something.

– Bobby

So,  I play one computer game – Nethack.  I have a page on the blog if you want some information about it.  I just finished building a 32 bit Linux virtual machine running on VMware player for the purpose of compiling Nethack.  I used the latest version of Oracle Enterprise Linux and configured it as a software development workstation.

I did this because I wanted to be able to putty into the VM and have the screen look the same as it does when I putty into nethack.alt.org.  I got my putty settings working well now with I think IBM graphics for the symbols.  But, it is helpful to compile your own copy of the game when you want to figure out how something works.  Plus it is fun to dork around with C code every once and a while since my normal job hardly ever requires it.

I used to use Cygwin to compile my own copy and ran it on a CRT monitor on Windows XP as a DOS window.  This was the most like the character based terminals that nethack originally ran on when I played it in college.  But, now I have a nice 22 inch flat screen monitor at home and I’ve upgraded to Windows 7 which doesn’t have the DOS window anymore.  So, I’ve moved to putty as my method of choice for playing Nethack.

I had downloaded the 64 bit version of OEL to use to install Oracle 12c and 11.2.0.3 in virtual machines that I could run from my new 64 bit OS laptop.  So, my first choice for a Nethack VM was a 64 bit Linux VM.  I was thinking I would use it for both playing with Nethack and other development type tasks where Linux was helpful.  But, I was getting grief from the 64 bit environment.  Evidently the Nethack code has some places that convert unsigned integers into pointers and vice-versa.  On 64-bit OEL these variables are different lengths.  So, after messing with this for longer than I intended – all I’m trying to do is get it where I can run the games from putty – I gave up on 64-bit Linux.

But, the question was, does Oracle still have 32-bit Linux because the new 12c download was only on 64-bit – at least the last time I checked.  Sure enough, Oracle still supports 32 bit Linux and so I downloaded that version and it worked pretty much the same as the 64 bit install except that the Nethack code compiled without all the pointer to integer conversion warnings.

So, I have a 32 bit Nethack VM and two 64 bit Oracle database VMs.  Fun!

– Bobby

I wasn’t sure if people would find a post on a bug that interesting.  If you don’t have the same bug I’m not sure what you would get out of it.  But, it is what I’m working on.

Here are my earlier rants on the same problem: 9b4m3fr3vf9kn and an4593dzvqr4v, SQLT Data Explosion.

So, I worked with Oracle support and they became convinced we were hitting this base bug:

16864042: KKPOSAGEPROPSCBK() MAY CAUSE UNNECESSARY EXADATA PERFORMANCE REGRESSION

It made sense to me because this was the base bug for another bug:

Bug 16694856 : EXADATA: SUBPARTITION WITH ‘LIBRARY CACHE LOCK’ ON RAC + INDEX OPERATION

16694856 has similar symptoms to what we have in production namely a lot of 9b4m3fr3vf9kn and an4593dzvqr4v internal query executions.  Anyway, Oracle development looked at the information I uploaded and concluded we had indeed hit bug 16864042 and produced a back ported patch for our release which is great.

So, I’ve applied the patch on dev and qa but I can’t reproduce the problem anywhere but prod so I won’t really know if the patch helps until it goes all the way through.  I built this script as a test of the bug:

drop table executions_before;

create table executions_before as 
select sum(executions) before_executions from v$sql where
sql_id = 'an4593dzvqr4v';

explain plan for select count(*) from OURPROBLEMTABLE;

select after_executions-before_executions
from 
(select sum(executions) after_executions
from v$sql where
sql_id = 'an4593dzvqr4v'),executions_before;

On dev and qa before and after the patch it produces the same results.  It returns a value > 0 once and then afterwards looks like this every time it is run:

AFTER_EXECUTIONS-BEFORE_EXECUTIONS
----------------------------------
                                 0

But on prod every time it is run it returns a value > 0:

AFTER_EXECUTIONS-BEFORE_EXECUTIONS
----------------------------------
                              1224

So, I’m hoping that after I apply the patch prod will start behaving like dev and qa and it will start returning 0 after the first run like in dev and qa.  At least that would be a quick test of the prod patch once it is in.

Anyway, just thought I would share my pain.  Not sure what to get out of this except that you can’t always duplicate a bug you are seeing on prod on a dev/test system.

– Bobby

I’m on call this week so I didn’t plan to do any blog posting but I had an interesting performance issue this morning that I thought would be helpful to document.  This is somewhat redundant to earlier posts but maybe another real example would be helpful to others (and myself as I try to explain it).

So, I got paged at 5:16 AM today because the session count had gone up on a key database.  I connected using Toad and saw many active sessions.  A number were hung on row locks but others were running a normal query.  At first I thought the locks were the issue until I looked at the AWR report.

I executed DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT, waited a couple of minutes, and then ran it again.  This gave me a short time period while the problem was occurring.  These were the top events:

Top 5 Timed Foreground Events

So, this pointed to the locks, but then I looked at the top sql:

This is a pretty normal query but there isn’t anything on our system that runs for more than a fraction of a second normally so a top query running for 13 seconds means there was a problem.

So, then I ran my sqlstat.sql(updated) script for the one query b9ad7h2rvtxwf.  Here were the results (edited to fit on the blog):

SQL_ID        PLAN_HASH_VALUE END_INTERVAL_TIME         EXECUTIONS_DELTA Elapsed Average ms CPU Average ms IO Average ms
------------- --------------- ------------------------- ---------------- ------------------ -------------- -------------
b9ad7h2rvtxwf      3569562598 22-OCT-13 04.00.09.971 PM             5058         147.520418     55.2906287    84.5061609
b9ad7h2rvtxwf      3569562598 22-OCT-13 05.00.29.056 PM             3553         138.164556     52.4176752    81.5798179
b9ad7h2rvtxwf      3569562598 22-OCT-13 06.00.48.108 PM             1744         131.999904     50.7224771    78.9727196
b9ad7h2rvtxwf      3569562598 22-OCT-13 07.00.07.435 PM             1151         129.623057     42.0590791    85.9294535
b9ad7h2rvtxwf      3569562598 22-OCT-13 08.00.28.121 PM              872         120.398335     36.7775229    83.2977339
b9ad7h2rvtxwf      3569562598 22-OCT-13 09.00.49.553 PM              604         132.635639     33.8245033    97.5104901
b9ad7h2rvtxwf      3569562598 22-OCT-13 10.00.09.004 PM              495         133.393253     33.1111111    99.2305293
b9ad7h2rvtxwf       405424828 22-OCT-13 11.00.29.567 PM              121         34966.0669     5395.86777    28047.5075
b9ad7h2rvtxwf      3569562598 22-OCT-13 11.00.29.567 PM              310         194.172239     34.7419355    159.561652
b9ad7h2rvtxwf       405424828 23-OCT-13 12.00.49.580 AM              367         13515.5776     4255.88556    9348.67928
b9ad7h2rvtxwf       405424828 23-OCT-13 01.00.08.933 AM              198         10156.8853     4131.56566    6100.66929
b9ad7h2rvtxwf       405424828 23-OCT-13 02.00.28.515 AM              121         13047.2503     4077.27273    9055.64753
b9ad7h2rvtxwf       405424828 23-OCT-13 03.00.48.829 AM              106         14410.4077     4095.75472    10457.2538
b9ad7h2rvtxwf       405424828 23-OCT-13 04.00.08.426 AM              132         13294.6225     3334.62121    10180.9116
b9ad7h2rvtxwf       405424828 23-OCT-13 05.00.29.523 AM              408         13075.3841     3327.35294    9828.64507
b9ad7h2rvtxwf       405424828 23-OCT-13 06.00.51.458 AM             1321         13314.1561     3119.74262    10091.0076
b9ad7h2rvtxwf       405424828 23-OCT-13 07.00.13.248 AM             3023         15692.5471     3126.99636     12361.605
b9ad7h2rvtxwf       405424828 23-OCT-13 07.39.33.767 AM             1924         16933.1762     3159.12682      13704.74
b9ad7h2rvtxwf       405424828 23-OCT-13 07.41.17.993 AM              106         13657.3272     3446.88679    10062.0426

So, between 10 and 11 pm last night the new plan 405424828 started being used and it resulted in the query that normally runs for 133 milliseconds (.1 seconds) running instead for 10091 ms = 10 seconds.  Not good when the query is run over 1000 times per hour.

So, I copied the sqlt scripts from another database server and got into the utl directory and ran the following commands:

-- build script to load profile

@coe_xfr_sql_profile.sql b9ad7h2rvtxwf 3569562598

-- run generated script

@coe_xfr_sql_profile_b9ad7h2rvtxwf_3569562598.sql

Then the performance issues all went away because b9ad7h2rvtxwf went back to running in .1 seconds.  Here is a previous post related to using sqlt this way.

The thing that strikes me about this scenario is that it really isn’t very hard to use this method to resolve these kind of issues.  All you need to do is use the awr report and sqlstat.sql script to identify the sql_id and the good plan_hash_value and then you can force it to run this way.

– Bobby

Another simple script: zip.

This is like an AWR report where you see a difference in v$ view values over time.  But, it is for  one wait event over a single interval.  Simple but possibly useful.

drop table waitdiff;

create table waitdiff as
select * from v$system_event
where event='&&WAITNAME';

host sleep &&INTERVALSECONDS

select 
s.event,
(s.TOTAL_WAITS-d.TOTAL_WAITS) "Number of waits",
(s.TIME_WAITED_MICRO-d.TIME_WAITED_MICRO)/
(s.TOTAL_WAITS-d.TOTAL_WAITS) "Avg microseconds"
from
waitdiff d,
v$system_event s
where 
d.event=s.event and
(s.TOTAL_WAITS-d.TOTAL_WAITS) > 0;

WAITNAME is the wait event such as “log file sync”.  INTERVALSECONDS is how long you want to wait between checks of the waits – i.e. 60 for 60 seconds.

Slightly edited output:

EVENT                    Number of waits Avg microseconds
------------------------ --------------- ----------------
log file parallel write            11412       2642.81151

– Bobby

I’ve taken a script I use to show a particular wait event over time and parameterized it a bit to make it more general.

Here is a zip of the script: zip(updated).

This is the same sort of information you see in an AWR report but just for one event and over all of the snapshots you have in your AWR.

Here is the main query:

select sn.END_INTERVAL_TIME,
(after.total_waits-before.total_waits) "number of waits",
(after.time_waited_micro-before.time_waited_micro)/
(after.total_waits-before.total_waits) "ave microseconds",
before.event_name "wait name"
from DBA_HIST_SYSTEM_EVENT before, 
DBA_HIST_SYSTEM_EVENT after,
DBA_HIST_SNAPSHOT sn
where before.event_name='&&WAITNAME' and
after.event_name=before.event_name and
after.snap_id=before.snap_id+1 and
after.instance_number=1 and
before.instance_number=after.instance_number and
after.snap_id=sn.snap_id and
after.instance_number=sn.instance_number and
(after.total_waits-before.total_waits) > &&MINIMUMWAITS
order by after.snap_id;

Here is a description of the two variables:

WAITNAME = Wait event like “log file sync”.

MINIMUMWAITS = Least amount of waits per hour to show that hour’s events.  Sometimes it is helpful to remove the hours where there isn’t much activity.

Here is some output with WAITNAME=log file sync and MINIMUMWAITS=100000:

END_INTERVAL_TIME          number of waits ave microseconds
-------------------------- --------------- ----------------
08-SEP-13 04.00.24.598 AM           194356       802.426964
08-SEP-13 05.00.38.147 AM           301482       705.784296
08-SEP-13 07.00.05.089 AM           162397       2736.56333
08-SEP-13 08.00.19.046 AM           333388       2380.95826
08-SEP-13 09.00.33.324 AM           439911       2469.45262
08-SEP-13 10.00.47.515 AM           697083        2847.4531
08-SEP-13 11.00.01.544 AM           744137       3424.96033
08-SEP-13 12.00.15.859 PM           731348       4022.53643
08-SEP-13 01.00.30.117 PM           674319       3691.63971
08-SEP-13 02.00.44.221 PM           748557        3108.9068

You can use this to identify changes in a waits average time and use an AWR report to do a deeper dive on any interval where you see something different from what is normal.

– Bobby

I modified the example from my previous post to see if on Exadata I could denormalize two tables and get the same performance without an index on the denormalized table that I get with the index on the normalized ones.

Here is the zip: zip of example.

This is on an Exadata V2 with 11.2.0.2 BP20.

What is interesting is that with an index and normalized tables I get these elapsed times:

Elapsed: 00:00:00.09
Elapsed: 00:00:00.11
Elapsed: 00:00:00.09
Elapsed: 00:00:00.10
Elapsed: 00:00:00.09

With the single denormalized table I get these times:

Elapsed: 00:00:00.12
Elapsed: 00:00:00.11
Elapsed: 00:00:00.12
Elapsed: 00:00:00.11
Elapsed: 00:00:00.11

So these are the equivalent with no index.  Of course without the hint the normalized tables are much slower with the full scans and hash join:

Elapsed: 00:00:01.48
Elapsed: 00:00:01.59
Elapsed: 00:00:01.70
Elapsed: 00:00:01.41
Elapsed: 00:00:01.65

I’m really thinking about our OBIEE queries that run on Exadata.  They have a wide variety of queries that have conditions on dimension tables that limit the rows on a huge fact table.  What if the columns used in the conditions were copied into the fact table and then all the conditions were on that table?  I’m not sure if the OBIEE RPD can be changed in this way but it seems like it would be a great way of using the Exadata smart scans.  I’d love to hear from anyone who had used this approach or seen problems with it.

– Bobby

I was working on the example from an earlier blog post that showed how the optimizer could not correctly estimate the number of rows accessed on a table if the non-join condition was on a different table.  Number of rows = cardinality.  This example from the blog post mirrors a real situation we have where we have a small table joined to a large one and conditions on the small table resulting in incorrect cardinality estimates on the larger table.  Something like this:

select SUM(B.cost)
from DIVISION A,SALES B
where
a.DIVNUM=B.DIVNUM and
A.REGION=’North East’;

The optimizer has no idea how many sales rows are in the North East region because of the join.  Duh! It dawned on me that we just need to denormalize the two tables so that region is part of the sales table.  Like this:

select SUM(B.cost)
from SALES B
where
B.REGION=’North East’;

This seems simple, but the reasons are – at least to me – pretty cool and sophisticated.

To prove all this out I build a test case with the previous blog post as the first part of the script.  First here is the original schema:

create table DIVISION (DIVNAME VARCHAR2(2000),DIVNUM NUMBER);
create table SALES (DIVNUM NUMBER);
create index SALESINDEX on SALES(DIVNUM);

Next, here is the slow query that doesn’t use the index because of the cardinality estimate being way off:

SQL> select B.DIVNUM
  2  from DIVISION A,SALES B
  3  where
  4  a.DIVNUM=B.DIVNUM and
  5  A.DIVNAME='Mayberry';

    DIVNUM
----------
         2

Elapsed: 00:00:00.11

Plan hash value: 480645376

-------------------------------------------------------
| Id  | Operation                  | Name     | Rows  |
-------------------------------------------------------
|   0 | SELECT STATEMENT           |          |       |
|*  1 |  HASH JOIN                 |          |   500K|
|*  2 |   TABLE ACCESS STORAGE FULL| DIVISION |     1 |
|   3 |   TABLE ACCESS STORAGE FULL| SALES    |  1000K|
-------------------------------------------------------

Note that it says it will access 1 million sales rows when it really will access 1.  It uses a full table scan on sales because it thinks we will be accessing a large percentage of the rows.

Here is the new denormalized schema with the two tables merged into one:

create table SALESWITHDIVNAME as
select d.divname,d.divnum
from
SALES s,
DIVISION d
where
s.divnum=d.divnum;

create index SWDNINDEX on SALESWITHDIVNAME(divname);

And here is the faster query which chooses an index:

SQL> select DIVNUM
  2  from SALESWITHDIVNAME
  3  where
  4  DIVNAME='Mayberry';

    DIVNUM
----------
         2

Elapsed: 00:00:00.00

Plan hash value: 447456343

----------------------------------------------------------------
| Id  | Operation                   | Name             | Rows  |
----------------------------------------------------------------
|   0 | SELECT STATEMENT            |                  |       |
|   1 |  TABLE ACCESS BY INDEX ROWID| SALESWITHDIVNAME |     1 |
|*  2 |   INDEX RANGE SCAN          | SWDNINDEX        |     1 |
----------------------------------------------------------------

Notice that the optimizer knows that the query will only access 1 row in the SALESWITHDIVNAME table and so it chooses an index range scan which is more efficient than a full scan when accessing a small percentage of rows from a table.

This may seem simplistic, but the profound fact is that the optimizer can not know which div_num is associated with the DIVNAME=’Mayberry’ condition in the two table query.  It uses the column statistics on DIVISION.DIVNAME to figure out that only one DIVISION row meets the condition.  But, since it doesn’t know that DIVNAME=’Mayberry’ translates into DIVNUM=2 it can’t use the histogram on SALES.DIVNUM to figure out that only one row will be retrieved from SALES.  But, if you merge the two tables together then the histogram on SALESWITHDIVNAME.DIVNAME tells the optimizer it only will access one row and so it should use the index instead of a full scan.

So, this is getting me thinking about the benefits of denormalizing the tables.  Also, maybe if you smash your small tables into your large one you can use multi-column histograms on the various columns you added as well.  In our case we have small division and date dimension tables and a large sales fact table.  What if the query was something like this:

select SUM(cost)
from SALES
where
REGION='North East' and
Quarter='2013Q1';

You might have a multi-column histogram on region and quarter.  You couldn’t have this if the query was normalized like this:

select SUM(cost)
from SALES S,
TIME T,
DIVISION D 
where
D.REGION='North East' and
T.Quarter='2013Q1'and
D.DIVNUM=S.DIVNUM and
T.sdate=s.sdate;

You can’t have a histogram across the three tables but you can across the columns of the one denormalized table.

– Bobby