Sunday, March 18, 2007

What do you mean "do less work".?

"dont go by time, look at actual work done (less is better)"
so what does that mean? how do we know how much work a SQL generates at server end?

the answer is AUTOTRACE..the feature comes in-built with SQL+ and all you have to do it turn it ON - when you need it.

SQL> SET AUTOTRACE ON EXP STAT
SQL> run your query (you will see query results followed by explain plan followed by some more junk info what we call it as "Statistics")

Yes, thats as simple as that.

when you are done.. Switch it off by
SQL> SET AUTOTRACE OFF
--

okay now, lets step into tuning world...

this blog is intended to explain ..how to see the workload of any SQL using Autotrace and how to interpret it and how to compare two different versions of SQL doing the same work and pick the best performant version..


I will be posting the scripts here..( most of my tests are done in my laptop database 10gR2 running on Windows)


step-1: Create a test table
----------------------------

DEMO@orcl>ed
Wrote file afiedt.buf

1 Create table test_table1 as
2 select cast(rownum as number(6)) id,
3 chr(65+mod(rownum,3)) code,
4 rpad(rownum,5,'x') data
5* from all_objects where rownum<99999
DEMO@orcl>/

Table created.

Notes: this table has abt 100K rows..
  1. id column is unique (Primary Key candidate)
  2. code column - is more like some status..contains 'A' or 'B' or 'C'
  3. data column - some junk data

step-2: Table is ready..so lets query
-------------------------------------
DEMO@orcl>set autotrace traceonly exp stat -- start tracing
DEMO@orcl>set timing on
-- shows timer
DEMO@orcl>select * from test_table1 where id=1000;

-- sample query..to retreive one row from that table with almost 100K rows


Elapsed: 00:00:00.17
-- thats the timer info..displayed in "Hour:Minutes:Seconds:subseconds" format


Execution Plan
----------------------------------------------------------
Plan hash value: 2372207557

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

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

1 - filter("ID"=1000)

Note
-----
- dynamic sampling used for this statement

** The explain plan shows a FULL TABLE SCAN on the table...**

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

-- and thats the stats info we wanted to display..
-- here is simple formula
total work = db block gets + consistent gets (the unit is Oracle blocks)

-- so for this sql -
we did 0+196= 196 block reads (lets call it ANSWER-A)


step-3: And why did Oracle read so many blocks to fetch you just 1 row (row with id=1000)
-------------------------------------------------------------------

the answer is simple..because we know we are asking for 1 row..but Oracle doesnt know how many rows the table has with id=1000..it could be 0 or 1 or many or even all 1000 rows..

so oracle did a full search from top to bottom of the table (aka full table scan) and found the matching rows..

lets help oracle by creating an index (and letting it know more about data inside the table)

DEMO@orcl>Create index test_table_uidx on test_table1(id)
2 tablespace users;

Index created.

Elapsed: 00:00:00.21

-- we created an index on id column

DEMO@orcl>begin

2 dbms_stats.gather_table_stats(ownname=>USER,
3 tabname=>'TEST_TABLE1',cascade=>TRUE);
4 end;
5 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.82

-- we gathered some stats on table and index..dont worry about this step now if you are a developer (because this is more of DBA job and you can always blame it on DBA :)..As a developer, I always enjoyed blaming it on my dbas and giving them hard time and letz maintain the same spirit here :) )


step-4: Okay, now Index is ready too..so whats the big difference?
------------------------------------------------------------------

DEMO@orcl>select * from test_table1 where id=1000;

-- rerunning the same query from step 2

Elapsed: 00:00:00.03

Execution Plan
----------------------------------------------------------
Plan hash value: 3929903905

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 12 | 2 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| TEST_TABLE1 | 1 | 12 | 2 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | TEST_TABLE_UIDX | 1 | | 1 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

-- hey, it shows it used the new index created

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

2 - access("ID"=1000)


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


-- so lets compute the work done now..
-- work done = 0+4 (blocks) = 4 Oracle blocks
(lets call it ANSWER-B)

--
now its a child game ..all we have to compare is ANSWER A to ANSWER-B and decide which is the best

196 block or 4 blocks? You decide !!! (yes, I am not good at Math :) )


so whats the final say here??
-----------------------------
two things..
- never go by time..check above ..we got answers in Step-2 and step -4 almost at the same time..both versions of sql took less than 1 second..and if you had simply gone by time factor, you wouldnt have even started to tune the sql in the first place (17 subseconds..is pretty darn good)..
- Next time anyone talks about SQL tuning, start asking how much work is done by SQL..
and does that sound like a layman's language? okay lets add some Oracle-touch to it and make it sound like a Pro's question.. How about asking " Well , how many LIOs does that SQL perform...?
"

LIOs = Logical I/Os = db block gets + consistent gets



Secret of SQL tuning: The more you focus on reducing LIOs , the faster you are becoming a smart Performance Tuner..and the good thing is, there are NOT many in the field who seem to know this little trick ..:)






2 comments:

daphne said...

Nice blog. Landed in your site searching for Oracle Tuning. If you are accepting new topics to write, can you blog about Explain plan?

Venkat said...

>>Nice blog
thanks..

>>can you blog about Explain plan?
sure, but actually I intend to answer to my current collegues first in posting something what they think would benefit the most first..not sure if "explain plan" is in their list..

Moreover explain plan stuff is well documented and I m not sure if I could write anymore interestingly or different about that..

but for sure, I will keep this in mind..and when/if I dont have any topics handy, sure will post one on this.

by the way, I hope you know Explain plan is dead now..and "dbms_xplan" is the thing which is alive now..

check out dbms_xplan package..so cool and neat..

appreciate your time & feedback
-Venkat