Timing an ALL_ROWS query

articles: 

The Problem

A common complaint in SQL is that "it runs in 5 seconds in SQL*Plus, but takes hours in Production. Why?"

The reason is because SQL*Plus and most GUI SQL tools display rows as soon as they are fetched. In this way, you can SELECT * FROM big_big_table and it will display the first 20 or so rows in the table in a fraction of a second, then go back for more. The SQL is not really finishing in seconds; if you timed how long it took to retrieve every row, you'd see that it takes just as long as in Production.

Bad solutions

Scroll the results

Easy fixed right? Just fetch all of the rows and time that! No, that will over-estimate the time.

SQL*Plus scrolls the results over the screen; the speed at which it can do this is limited by the speed at which your PC can render the scrolling text (which is invariably slower than the database and network can supply the results).

If you are using a GUI, it will want to buffer all the results in memory so that they can be displayed in an attractive grid. This too will slow things down.

COUNT(*)

Some people change the SQL to perform SELECT COUNT(*) instead of the selected columns. The problem is that if you do not SELECT the columns, Oracle does not need to go to the table; it can resolve a COUNT(*) from indexes alone. A different plan means different timing.

And it doesn't help to just wrap the entire query like this: SELECT COUNT(*) FROM ( SELECT col1, col2, ... ). The optimizer is wise to that; if a selected column in an inline view is not referenced in the outer-query, the CBO will ignore it.

ORDER BY 1

If you sort the results, Oracle will identify all the rows before it returns the first one. Then you just need to time how long it takes to return the first row. This works - kind of - but it is slower because you have to perform an additional sort on the data. For large data volumes, this time could be considerable.

Better Solutions

SET TERMOUT OFF

This used to be my favourite. In SQL*Plus you can hide the results from the screen using SET TERMOUT OFF. You are still timing the disk activity to spool the data to a file; this can be mitigated in Unix by spooling to /dev/null. Even if you do this, the data is still coming across the network to SQL*Plus; this will not be an accurate comparison to a PL/SQL program that processes the data internally.

SET AUTOTRACE TRACEONLY

In SQL*Plus, you can hide the results of the SQL with Autotrace:

SET AUTOTRACE TRACEONLY

SELECT ...

This is a pretty good method, but it is not much help for users of GUIs. Also, the server sends the results back to SQL*Plus, SQL*Plus just doesn't collect them. I don't know whether there is a cost associated with this.

SELECT MAX(..), MAX(..), ...

Wrap each of the selected columns in a MAX() function. This gives a very reliable result, but is a bit tedious if you have selected a lot of columns.

The Top Performer

My favourite method - I just discovered it: wrap the SQL in SELECT * FROM ( .... ) WHERE ROWNUM > 1. Since ROWNUM is applied as the rows are projected, there must always be a first row returned. WHERE ROWNUM > 1 causes the first row not to be displayed, making the second row the new first row, which is then not displayed, and so on. In this way, every row gets rejected.

Note that this is different to a constant false predicate like WHERE 1=0. Constant predicates are run before the data is accessed, not after; so the SQL would return immediately.

Check it out:

SQL> select count(*) from ef_actl_rev;

  COUNT(*)
----------
   2889477

Elapsed: 00:00:01.23


SQL> select * from ef_actl_rev where rownum > 1;

no rows selected

Elapsed: 00:00:03.15


SQL> select * from ef_actl_rev where 1=0;

no rows selected

Elapsed: 00:00:00.01

I only just discovered this method myself, so I can't guarantee that it does not affect the execution plan - preliminary testing is promising though.

Comments

cbruhn2's picture

Hi rleishman,

I read your article with greate interest.
I tried the following with autotrace:

14:40:37 SQL> select * from mytab where rownum > 1 ;

no rows selected

Elapsed: 00:00:00.04

Execution Plan
----------------------------------------------------------
Plan hash value: 1019882195

----------------------------------------------------------------------------------------------
| Id  | Operation            | Name  | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |       |  8001 |   109K|    10   (0)| 00:00:01 |       |       |
|   1 |  COUNT               |       |       |       |            |          |       |       |
|*  2 |   FILTER             |       |       |       |            |          |       |       |
|   3 |    PARTITION LIST ALL|       |  8001 |   109K|    10   (0)| 00:00:01 |     1 |     3 |
|   4 |     TABLE ACCESS FULL| MYTAB |  8001 |   109K|    10   (0)| 00:00:01 |     1 |     3 |
----------------------------------------------------------------------------------------------

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

   2 - filter(ROWNUM>1)


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

14:40:51 SQL> select * from mytab ;

8001 rows selected.

Elapsed: 00:00:00.26

Execution Plan
----------------------------------------------------------
Plan hash value: 1885567542

--------------------------------------------------------------------------------------------
| Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |       |  8001 |   109K|    10   (0)| 00:00:01 |       |       |
|   1 |  PARTITION LIST ALL|       |  8001 |   109K|    10   (0)| 00:00:01 |     1 |     3 |
|   2 |   TABLE ACCESS FULL| MYTAB |  8001 |   109K|    10   (0)| 00:00:01 |     1 |     3 |
--------------------------------------------------------------------------------------------


Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        577  consistent gets
          0  physical reads
          0  redo size
     132953  bytes sent via SQL*Net to client
       6248  bytes received via SQL*Net from client
        535  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
       8001  rows processed

14:41:02 SQL>


As far as I can see there is at big difference, in almost everything. This is also reflected in your own data. Your selece count(*) returns 2899477 but the rownum>1 doesn't return a single row.
Maybe I'm missing your point (wouldn't be first time I missed something :-) but that is not your fault.
Is your point that it's difficult to implement some timing in a GUI?

Best regards.
Carl Bruhn.

my setup

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod
PL/SQL Release 10.2.0.1.0 - Production
CORE    10.2.0.1.0      Production
TNS for Linux: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production

The whole point is to benchmark the SQL WITHOUT returning buckets of data across the network. Returning Gigs of data is just not feasible for really large SQLs.

Here's another example:

SQL> select * from ed_proj_map where rownum > 1;

no rows selected

Elapsed: 00:00:00.13

SQL> set autotrace traceonly statistics
SQL> select * from ed_proj_map;

297975 rows selected.

Elapsed: 00:00:49.45

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
      20577  consistent gets
        751  physical reads
          0  redo size
   11486383  bytes sent via SQL*Net to client
     219012  bytes received via SQL*Net from client
      19866  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
     297975  rows processed

This shows that ROWNUM>1 had sub-second response, but AUTOTRACE took 50 seconds. This leads us to believe that ROWNUM>1 did not do any work. But lets look at TK*Prof (I was running SQL*Trace as well):

select *
from
 ed_proj_map where rownum > 1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.17       0.16        751        752          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.17       0.16        751        752          0           0

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 23

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  COUNT  (cr=752 pr=751 pw=0 time=164361 us)
      0   FILTER  (cr=752 pr=751 pw=0 time=164354 us)
 297975    TABLE ACCESS FULL ED_PROJ_MAP (cr=752 pr=751 pw=0 time=302618 us)

********************************************************************************

select *
from
 ed_proj_map


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch    19866      0.58       0.67        751      20577          0      297975
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    19868      0.58       0.67        751      20577          0      297975

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 23

Rows     Row Source Operation
-------  ---------------------------------------------------
 297975  TABLE ACCESS FULL OBJ#(151802) (cr=20577 pr=751 pw=0 time=299767 us)

The above shows that Oracle read the same number of rows from the table both with and without the ROWNUM>1, and they both took about the same about of time to do so. But why did the AUTOTRACE example take 49 seconds? ROWNUM>1 is doing all the data retrieval work, but not the data delivery which appears to be 95+% of the job.

The problem I had not previously noticed - but was highlighted in your AUTOTRACE and my SQL*Trace above, is that although ROWNUM>1 reads the same number of rows, the Consistent Gets ("query" in TkProf) is markedly different. I can't make sense of this.

As a third comparison, I wrote a PL/SQL wrapper to fetch the rows without returning them to the SQL*Plus client. Here is the trace:

declare
        cursor c1 is select * from ed_proj_map;
        type c1_tbl_typ is table of c1%rowtype;
        c1_tbl c1_tbl_typ;
begin
        open c1;
        loop
                fetch c1 bulk collect into c1_tbl limit 1000;
                exit when c1%notfound;
        end loop;
        close c1;
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.05       0.02          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.05       0.02          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 23
********************************************************************************

SELECT *
FROM
 ED_PROJ_MAP


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      298      0.74       1.09        751       1047          0      297975
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      300      0.75       1.09        751       1047          0      297975

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 23     (recursive depth: 1)

Interestingly, though not identical - this seems to be more comparable to the ROWNUM>1 example. This seems logical since - like ROWNUM>1 - the rows are not delivered to the client.

As another comparison, I ran the raw query from SQL*Plus, spooling the data to /dev/null (not displaying on the screen):

select *
from
 ed_proj_map


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch    19866      0.74       0.74        751      20577          0      297975
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    19868      0.74       0.74        751      20577          0      297975

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 23

Rows     Row Source Operation
-------  ---------------------------------------------------
 297975  TABLE ACCESS FULL OBJ#(151802) (cr=20577 pr=751 pw=0 time=601432 us)

The Consistent Gets / Query is back up to AUTOTRACE TRACEONLY levels, but like AUTOTRACE the query took about a minute to finish.

My findings:

  • ROWNUM>1 does all the work of retrieval without the overheads of delivery. This is desirable because when we compare the performance of two SQLs that deliver the same data, it is the retrieval speed we are trying to tune.
  • ROWNUM>1 is orders of magnitude faster to benchmark a query than AUTOTRACE TRACEONLY.
  • Returning rows to a host program (eg. SQL*Plus) involves some activity that increases Consistent Gets.

cbruhn2's picture

Hi rleishman,

I don't agree with you in your first finding

Quote:

1. ROWNUM>1 does all the work of retrieval without the overheads of delivery. This is desirable because when we compare the performance of two SQLs that deliver the same data, it is the retrieval speed we are trying to tune.

No it doesn't. When you do it with rownum > 1 you don't fetch a single row as stated in your own data from tkprof. Also if you look into the raw trace file you will experience lots of
FETCH #9:c=0,e=40,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,tim=1143996441721483
WAIT #9: nam='SQL*Net message from client' ela= 81 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1143996441721595
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1143996441721639
FETCH #9:c=0,e=41,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,tim=1143996441721666
WAIT #9: nam='SQL*Net message from client' ela= 80 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1143996441721778
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1143996441721822
FETCH #9:c=0,e=40,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,tim=1143996441721848
WAIT #9: nam='SQL*Net message from client' ela= 83 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1143996441722046
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1143996441722090
FETCH #9:c=0,e=41,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,tim=1143996441722118

Please notice the alternating fetch/wait. So there is a lot of fetches when you do not use rownum>1.
Quote:

2. ROWNUM>1 is orders of magnitude faster to benchmark a query than AUTOTRACE TRACEONLY.
3. Returning rows to a host program (eg. SQL*Plus) involves some activity that increases Consistent Gets.

That's because we don't fetch the actual rows and because we don't deliver. I would suspect that you have a rather large deal of waits in your trace file for SQL*Net messages (did you run with trace level +8?). I don't think elapsed time in your tkprof on the select with rownum > 1 is order of magnitudes smaller than without. (ela=0.16 ela=0.67) Also notice the time= is about the same.

Perhaps elapsed timing in tkprof is a better way of actually timing the statement if that's what's needed.
But if we are going to time the statement don't we want to know how long it actually takes including different layers of sql*net transport etc.
I mean if the client wants to know how long does it take to run statement XXX he wouldn't care if the it only takes 0.0001 sec. on the server if every times he runs it takes 30 min.

Best regards.
Carl Bruhn.

OK, I think we're talking about two different things. If you want to know how long it will take in Production to resolve a SQL and return the data either to the client or to a PL/SQL routine, ROWNUM>1 will not give you any idea of the REAL elapsed time including fetches. But speaking only for myself, I have never once wanted to do that. If I want to know how long a production program takes, I time it in Production.

My intention here - and I concede that I did not make it clear - is that when you have an under-performing SQL to tune, you want some means of determining how much faster your tuned version will be. All being equal, the tuned version will return the same data across the same network (or to the same PL/SQL program); what is different is the Explain Plan - the steps performed to retrieve the data.

By using ROWNUM>1 you can benchmark the old version, and compare that benchmark to the new version. This will give you an accurate picture of the likely tuning benefit.

Of course all of this is equally possible using any of the other methods I described in the article - including AUTOTRACE; but with the exception of the SELECT MAX() option, the exercise takes longer because of the fetches, which we are happy to do without because they are a constant.

I suppose it would have been clearer if I had worked through a tuning case-study showing an untuned SQL, its benchmark, a tuned benchmark, then the tuned SQL fetching. I may yet do that and tack it to the bottom with a note.

cbruhn2's picture

Hi rleishman,

thanks for your explanation.
Now your idea is clear to me, and I see different kinds of ways to exploit.
Just shows how difficult it can be to come across with a message/idea.
By the way.
Now I'm wondering when Oracle will improve the CBO so that when you state rownum>1 it will think.
"Ah.. so you don't want to see the result of my efforts. Then I will not do anything!!" :-)

best regards.
Carl Bruhn

Yeah, that's exactly the sort of thing the optimizer would do! Some think that's what happened to COUNT(*) FROM (inline view). I'm sceptical, but I don't have access to an old 7.3 or 8.0 (or even 8i for that matter) database to check.