Performance

One of my close frind told me, they had a problem in their Oracle database- a SELECT statement is quicker, but a DELETE sleeps.  Infact he was pointing to a big issue, normally developers tends to forget, I don’t want to kill the curiosity, so I will say the problem later.  Here is my test case, what was the issue and the solution.

So, I have created a simple test table – TEST – just copy from DBA_OBJECTS.  Also, created a primary key on OBJECT_ID

SQL> create table test as select * from dba_objects;

Table created.

SQL> alter table test add constraint pk_OBJECT_ID  primary key (OBJECT_ID);

Table altered.

I did some more setup, but to get the real problem feel, I am not disclosing what I did!

Since I have a Primary Key Index on OBJECT_ID columns, my SELECT work very well, with just 3 consistent gets and with in 0.01 second. 

 SQL> select object_name from test where object_id=5;

OBJECT_NAME
———————–
CLU$

Elapsed: 00:00:00.01

Execution Plan
———————————————————-
Plan hash value: 1799415411

——————————————————————————————–
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
——————————————————————————————–
|   0 | SELECT STATEMENT            |              |     1 |    79 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| TEST         |     1 |    79 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | PK_OBJECT_ID |     1 |       |     1   (0)| 00:00:01 |
——————————————————————————————–

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

   2 – access(“OBJECT_ID”=5)
Statistics
———————————————————-
          0  recursive calls
          0  db block gets
          3  consistent gets
          0  physical reads
          0  redo size
        531  bytes sent via SQL*Net to client
        523  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

 

Then I used the same WHERE predicate to delete a single row from the TEST table.   And the result was shocking.

SQL> delete from test where object_id=5;

1 row deleted.

Elapsed: 00:00:10.92

Execution Plan
———————————————————-
Plan hash value: 14352436

———————————————————————————–
| Id  | Operation          | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
———————————————————————————–
|   0 | DELETE STATEMENT   |              |     1 |    13 |     1   (0)| 00:00:01 |
|   1 |  DELETE            | TEST         |       |       |            |          |
|*  2 |   INDEX UNIQUE SCAN| PK_OBJECT_ID |     1 |    13 |     1   (0)| 00:00:01 |
———————————————————————————–

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

   2 – access(“OBJECT_ID”=5)
Statistics
———————————————————-
          7  recursive calls
          7  db block gets
      33238  consistent gets
      21769  physical reads
        632  redo size
        846  bytes sent via SQL*Net to client
        790  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
          1  rows processed

Woops..  it took 10.92 seconds to delete a single row which was selected in just 0.01 seconds!  More over it took  7  db block gets,   33238  consistent gets and   21769  physical reads – something is terribly wrong.  What is wrong here, why is using so much time and resource to DELETE a single row, but the SELECT is within the expectations.  Come on let us trace the session and what oracle is doing delete this single row.

SQL> ALTER SESSION SET events ‘10046 trace name context forever, level 12′;

Session altered.

Elapsed: 00:00:00.02

SQL> select object_id from user_objects where object_name=’TEST’;

 OBJECT_ID
———-
     80652

Here are the few lines from the trace file,

EXEC #13:c=10000,e=12528,p=0,cr=169,cu=0,mis=1,r=0,dep=1,og=1,plh=227838953,tim=4586869551879
WAIT #13: nam=’db file scattered read’ ela= 10622 file#=6 block#=1765 blocks=27 obj#=80653 tim=4586869563070
WAIT #13: nam=’db file scattered read’ ela= 9038 file#=8 block#=1826 blocks=30 obj#=80653 tim=4586869573782
WAIT #13: nam=’db file scattered read’ ela= 277 file#=6 block#=1794 blocks=2 obj#=80653 tim=4586869575544
WAIT #13: nam=’db file scattered read’ ela= 1205 file#=6 block#=1797 blocks=27 obj#=80653 tim=4586869577255
WAIT #13: nam=’db file scattered read’ ela= 1371 file#=8 block#=1857 blocks=31 obj#=80653 tim=4586869579934
WAIT #13: nam=’db file scattered read’ ela= 8163 file#=6 block#=1824 blocks=32 obj#=80653 tim=4586869589755
WAIT #13: nam=’db file scattered read’ ela= 1377 file#=8 block#=1889 blocks=31 obj#=80653 tim=4586869592877
WAIT #13: nam=’db file scattered read’ ela= 7503 file#=6 block#=1856 blocks=32 obj#=80653 tim=4586869602136
WAIT #13: nam=’db file scattered read’ ela= 1374 file#=8 block#=1921 blocks=31 obj#=80653 tim=4586869605252
WAIT #13: nam=’db file scattered read’ ela= 1436 file#=6 block#=1888 blocks=32 obj#=80653 tim=4586869608360
WAIT #13: nam=’db file scattered read’ ela= 1396 file#=8 block#=1953 blocks=31 obj#=80653 tim=4586869611309
WAIT #13: nam=’db file scattered read’ ela= 1593 file#=6 block#=1920 blocks=32 obj#=80653 tim=4586869615515
WAIT #13: nam=’db file scattered read’ ela= 8612 file#=8 block#=1985 blocks=31 obj#=80653 tim=4586869625656
WAIT #13: nam=’db file scattered read’ ela= 1487 file#=6 block#=1952 blocks=32 obj#=80653 tim=4586869628729
WAIT #13: nam=’db file scattered read’ ela= 1439 file#=8 block#=2017 blocks=31 obj#=80653 tim=4586869631720
WAIT #13: nam=’db file scattered read’ ela= 1624 file#=6 block#=1984 blocks=32 obj#=80653 tim=4586869635012
WAIT #13: nam=’db file scattered read’ ela= 587 file#=8 block#=2049 blocks=10 obj#=80653 tim=4586869637070
WAIT #13: nam=’db file scattered read’ ela= 929 file#=8 block#=2060 blocks=20 obj#=80653 tim=4586869638597
WAIT #13: nam=’db file scattered read’ ela= 1439 file#=6 block#=2016 blocks=32 obj#=80653 tim=4586869641197
WAIT #13: nam=’db file scattered read’ ela= 1445 file#=8 block#=2081 blocks=31 obj#=80653 tim=4586869644364
WAIT #13: nam=’db file scattered read’ ela= 1507 file#=6 block#=2048 blocks=32 obj#=80653 tim=4586869647575
WAIT #13: nam=’db file scattered read’ ela= 1416 file#=8 block#=2113 blocks=31 obj#=80653 tim=4586869650470
WAIT #13: nam=’db file scattered read’ ela= 1492 file#=6 block#=2080 blocks=32 obj#=80653 tim=4586869653393
WAIT #13: nam=’db file scattered read’ ela= 1470 file#=8 block#=2145 blocks=31 obj#=80653 tim=4586869656561
WAIT #13: nam=’db file scattered read’ ela= 1441 file#=6 block#=2112 blocks=32 obj#=80653 tim=4586869659818

*** 2011-02-01 15:28:52.923
WAIT #13: nam=’db file scattered read’ ela= 1359 file#=8 block#=2177 blocks=31 obj#=80653 tim=4586869662971
WAIT #13: nam=’db file scattered read’ ela= 3668 file#=6 block#=2144 blocks=32 obj#=80653 tim=4586869668316
WAIT #13: nam=’db file scattered read’ ela= 1406 file#=8 block#=2209 blocks=31 obj#=80653 tim=4586869671354
WAIT #13: nam=’db file scattered read’ ela= 7362 file#=6 block#=2176 blocks=32 obj#=80653 tim=4586869680557
WAIT #13: nam=’db file scattered read’ ela= 15286 file#=8 block#=2241 blocks=31 obj#=80653 tim=4586869697621
WAIT #13: nam=’db file scattered read’ ela= 61287 file#=6 block#=2208 blocks=32 obj#=80653 tim=4586869760522
WAIT #13: nam=’db file scattered read’ ela= 1440 file#=8 block#=2273 blocks=31 obj#=80653 tim=4586869763831
WAIT #13: nam=’db file scattered read’ ela= 1530 file#=6 block#=2240 blocks=32 obj#=80653 tim=4586869767102
WAIT #13: nam=’db file scattered read’ ela= 1365 file#=8 block#=2305 blocks=31 obj#=80653 tim=4586869770254
WAIT #13: nam=’db file scattered read’ ela= 3698 file#=6 block#=2272 blocks=32 obj#=80653 tim=4586869775635
WAIT #13: nam=’db file scattered read’ ela= 424 file#=8 block#=2337 blocks=7 obj#=80653 tim=4586869777649
WAIT #13: nam=’db file sequential read’ ela= 205 file#=8 block#=2345 blocks=1 obj#=80653 tim=4586869778316
WAIT #13: nam=’db file sequential read’ ela= 261 file#=8 block#=2347 blocks=1 obj#=80653 tim=4586869778790
WAIT #13: nam=’db file sequential read’ ela= 184 file#=8 block#=2349 blocks=1 obj#=80653 tim=4586869779174
WAIT #13: nam=’db file scattered read’ ela= 386 file#=8 block#=2351 blocks=7 obj#=80653 tim=4586869779771
WAIT #13: nam=’db file scattered read’ ela= 469 file#=8 block#=2359 blocks=9 obj#=80653 tim=4586869780707

That was more interesting to see in the trace file my update statement doing a Full Table Scan (FTS) on 80653 while TEST table obj# is 80652.

So, that is issue, I am DELETing a single from TEST, but 99.99% read is going to a different table TEST_CHILD.

SQL> select object_name from user_objects where object_id=80653;

OBJECT_NAME
—————–
TEST_CHILD

That means, the Forgien Key relationship between TEST and TEST_CHILD so that it is doing a validation before it is deleting from the parent table!  Oopps, that is the problem.

SQL> select R_CONSTRAINT_NAME,CONSTRAINT_NAME
from user_constraints where table_name=’TEST_CHILD’;

R_CONSTRAINT_NAME              CONSTRAINT_NAME
—————————— ——————————
PK_OBJECT_ID                   FK_OBJECT_ID

  

So, you need to make your validation faster, so that the DELETE will be fast.  So, let me create an index on this Forgien Key column on the child table.

SQL> create index i_object_id on test_child (object_id);

Index created.

Well, I will try my DELETE statement once again… wow, I got what I want now…

SQL> delete from test where object_id=5;

1 row deleted.

Elapsed: 00:00:00.05

Execution Plan
———————————————————-
Plan hash value: 14352436

———————————————————————————–
| Id  | Operation          | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
———————————————————————————–
|   0 | DELETE STATEMENT   |              |     1 |    13 |     1   (0)| 00:00:01 |
|   1 |  DELETE            | TEST         |       |       |            |          |
|*  2 |   INDEX UNIQUE SCAN| PK_OBJECT_ID |     1 |    13 |     1   (0)| 00:00:01 |
———————————————————————————–

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

   2 – access(“OBJECT_ID”=5)
Statistics
———————————————————-
          1  recursive calls
          7  db block gets
          2  consistent gets
          2  physical reads
        744  redo size
        846  bytes sent via SQL*Net to client
        790  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
          1  rows processed

The DELETE statement completed in 0.05 seconds  with 7  db block gets,  2  consistent gets, 2  physical reads.   

Now you know, the importance of indexing the FOREIGN KEY columns.

  1. No comments yet.
  1. No trackbacks yet.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: