Thursday, September 17, 2009

Mailbox: “How to optimize this query when table is large?”

I received a mail seeking advice on tuning a query executing on a table with 4 million records. According to the information provided, this query is run very frequently. Here's the query:

select max(to_char(dt, 'YYYYMMDDHH24MISS')) 
from big_table;

Let's create a table and insert 4 Million records to reproduce the problem.

SQL> create table big_table(dt date);

Table created.

SQL> set timing on
SQL> begin
  2    for i in 1..365 loop
  3      insert into big_table
  4          select to_date('01-01-1980', 'dd-mm-yyyy') + level - 1
  5            from dual
  6            connect by level <= 11000;
  7    end loop;
  8    commit;
  9  end;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:09.86
SQL>
SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'BIG_TABLE');

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.51
SQL> select num_rows from user_tables where table_name = 'BIG_TABLE';

  NUM_ROWS
----------
   4020746

Elapsed: 00:00:00.10
SQL>

Enable SQL trace at the session-level and execute the problem query:

SQL> alter session set tracefile_identifier='BIG_TABLE';

Session altered.

Elapsed: 00:00:00.01
SQL> alter session set sql_trace = true;

Session altered.

Elapsed: 00:00:00.00
SQL> select max(to_char(dt, 'YYYYMMDDHH24MISS')) from big_table;

MAX(TO_CHAR(DT
--------------
20100211000000

Elapsed: 00:00:03.37
SQL>

The TKPROF output shows the following information:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.02          0          0          0           0
Execute      1      0.00       0.04          0          0          0           0
Fetch        2      3.85       3.86          0       7265          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      3.85       3.93          0       7265          0           1

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=7265 pr=0 pw=0 time=3868185 us)
4015000   TABLE ACCESS FULL BIG_TABLE (cr=7265 pr=0 pw=0 time=79 us)

Information from the trace:

Query Elapsed Time: 3.93 Sec
Time spent on CPU: 3.85 Sec
Consistent Gets: 7265
Table Access:  Full Table Scan

So, most of the time the query was on the CPU. 7265 consistent gets were performed to arrive at the maximum value. We can do two things to speedup this query are: 1) Apply TO_CHAR function after fetching the maximum value. 2) Create an index on STAT_CHG_DT column

Let's trace the modified query (before creating the index) and hope things get better:

SQL> alter session set tracefile_identifier='BIG_TABLE_MAX';

Session altered.

Elapsed: 00:00:00.01
SQL> alter session set sql_trace = true;

Session altered.

Elapsed: 00:00:00.00
SQL> select to_char( max(dt), 'YYYYMMDDHH24MISS') from big_table;

TO_CHAR(MAX(DT
--------------
20100211000000

Elapsed: 00:00:00.84
SQL> alter session set sql_trace =false;

Session altered.

Elapsed: 00:00:00.00
SQL>

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.67       0.67          0       7265          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.68       0.69          0       7265          0           1

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=7265 pr=0 pw=0 time=671191 us)
4015000   TABLE ACCESS FULL BIG_TABLE (cr=7265 pr=0 pw=0 time=61 us)

Fantastic! The CPU usage has drastically come down and the query is no more a burden for the poor CPU. However, to arrive at the maximum value, Oracle still has to perform 7265 consistent gets. This seems to be still high.

How did it affect:

In the original query, TO_CHAR function was applied on all the 4 Million rows and then a maximum value was selected among them. But after interchanging positions of TO_CHAR and MAX functions, database had to do a little less job. MAX function fetched the maximum value from the 4 Million records table and later database applied TO_CHAR function against the maximum value. So, we got rid of 4 Million - 1 TO_CHAR transformations and this saved CPU time.

To further enhance the query, we will create an index on "DT" column and trace it again:

SQL> create index t_idx on big_table(dt);

Index created.

Elapsed: 00:00:44.39
SQL> alter session set tracefile_identifier='BIG_TABLE_IDX';

Session altered.

Elapsed: 00:00:00.17
SQL> alter session set sql_trace = true;

Session altered.

Elapsed: 00:00:00.03
SQL> select to_char( max(dt), 'YYYYMMDDHH24MISS') from big_table;

TO_CHAR(MAX(DT
--------------
20100211000000

Elapsed: 00:00:00.04
SQL> alter session set sql_trace =false;

Session altered.

Elapsed: 00:00:00.01

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        2      0.00       0.01          2          3          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.01          2          3          0           1


Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=3 pr=2 pw=0 time=14415 us)
      1   INDEX FULL SCAN (MIN/MAX) T_IDX (cr=3 pr=2 pw=0 time=14394 us)(object id 93231)

The index brings a huge huge difference. Everything seems to be under control. The consistent gets are reported as "3" compared to "7265", also CPU and Elapsed times are near zero. So, this query performs 2421 times better than the previous queries.

How did it affect:

After creating an index, instead of doing a Full Table Scan the optimizer went with "INDEX FULL SCAN (MIN/MAX)" operation.

Oracle will access the requested data by applying a shortcut to reach to the leaf index block. It will first hit the root block, follows the right most intermediate branch blocks, finally hitting the rightmost leaf block to get to the maximum value.

Tuesday, July 14, 2009

Who says Full Table Scans are Evil?

Recently, I had a developer complaining that a query which normally runs very fast is now taking huge amount of time to complete.

Following is the culprit query and its execution plan:

SELECT  DISTINCT SUBSTR(A.MF_NO,4) MF_NO,
 B.SRT_SEQ,
 SUBSTR(B.MAIN_CODE,1,6) MAIN_CODE
  FROM  DETAIL_TBL A,
        MASTER_TBL B    
  WHERE A.MRF_ID   = B.MRF_ID    
    AND A.MRF_CODE = B.MRF_CODE    
    AND TRIM(SUBSTR(A.MF_NO,4)) IN (SELECT LPAD(MF_NO,4,0) 
                                     FROM REMOTE_TBL@RMLINK 
                                    WHERE USER_LEVEL = 'RO'  
                                      AND STATUS_CODE <> 'D');

Execution Plan
----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name                  | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |IN-OUT|
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                       |       |       |  6646 (100)|          |        |      |
|   1 |  HASH UNIQUE                 |                       |     1 |    62 |  6646   (2)| 00:01:34 |        |      |
|   2 |   TABLE ACCESS BY INDEX ROWID| MASTER_TBL            |     1 |    30 |     5   (0)| 00:00:01 |        |      |
|   3 |    NESTED LOOPS              |                       |     1 |    62 |  6645   (2)| 00:01:34 |        |      |
|*  4 |     HASH JOIN                |                       |     1 |    32 |  6640   (2)| 00:01:33 |        |      |
|   5 |      REMOTE                  | REMOTE_TBL            |     1 |    12 |    24   (0)| 00:00:01 |  REMDB | R->S |
|   6 |      TABLE ACCESS FULL       | DETAIL_TBL            |  4159K|    79M|  6589   (2)| 00:01:33 |        |      |
|*  7 |     INDEX RANGE SCAN         | SYS_C0011692          |     3 |       |     2   (0)| 00:00:01 |        |      |
----------------------------------------------------------------------------------------------------------------------

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

   4 - access(TRIM(SUBSTR("A"."MF_NO",:SYS_B_3))=LPAD("MF_NO",:SYS_B_4,TO_CHAR(:SYS_B_5)))
   7 - access("A"."MRF_ID"="B"."MRF_ID" AND "A"."MRF_CODE"="B"."MRF_CODE")

Using AWR SQL report (awrsqrpt.sql) for the time when the query was performing better shows that a Full Table Scan was performed on the MASTER_TBL.

Execution Plan
----------------------------------------------------------
Plan hash value: 1931109479

----------------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name                  | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | Inst   |IN-OUT|
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |                       |  2919K|   172M|       | 42564   (2)| 00:09:56 |        |      |
|   1 |  HASH UNIQUE         |                       |  2919K|   172M|   424M| 42564   (2)| 00:09:56 |        |      |
|*  2 |   HASH JOIN          |                       |  2919K|   172M|    11M| 15147   (2)| 00:03:33 |        |      |
|   3 |    TABLE ACCESS FULL | MASTER_TBL            |   289K|  8494K|       |  5590   (2)| 00:01:19 |        |      |
|*  4 |    HASH JOIN         |                       |  1225K|    37M|       |  6833   (2)| 00:01:36 |        |      |
|   5 |     REMOTE           | REMOTE_TBL            |    29 |   348 |       |    24   (0)| 00:00:01 |  REMDB | R->S |
|   6 |     TABLE ACCESS FULL| DETAIL_TBL            |  4191K|    79M|       |  6781   (2)| 00:01:35 |        |      |
----------------------------------------------------------------------------------------------------------------------

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

   2 - access("A"."MRF_ID"="B"."MRF_ID" AND "A"."MRF_CODE"="B"."MRF_CODE")
   4 - access(TRIM(SUBSTR("A"."MF_NO",4))=LPAD("MF_NO",4,'0'))

When we add a Full Table Scan (FTS) hint on the MASTER_TBL, the same query ran in less than 20 seconds. We can modify the query to include FTS hint as it is a home grown application.

SELECT  /*+ FULL(A) */ DISTINCT SUBSTR(A.MF_NO,4) MF_NO,
 B.SRT_SEQ,
 SUBSTR(B.MAIN_CODE,1,6) MAIN_CODE
  FROM  DETAIL_TBL A,
        MASTER_TBL B    
  WHERE A.MRF_ID   = B.MRF_ID    
    AND A.MRF_CODE = B.MRF_CODE    
    AND TRIM(SUBSTR(A.MF_NO,4)) IN (SELECT LPAD(MF_NO,4,0) 
                                     FROM REMOTE_TBL@RMLINK 
                                    WHERE USER_LEVEL = 'RO'  
                                      AND STATUS_CODE <> 'D');


Execution Plan
----------------------------------------------------------
Plan hash value: 1931109479

----------------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name                  | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | Inst   |IN-OUT|
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |                       |  2919K|   172M|       | 42564   (2)| 00:09:56 |        |      |
|   1 |  HASH UNIQUE         |                       |  2919K|   172M|   424M| 42564   (2)| 00:09:56 |        |      |
|*  2 |   HASH JOIN          |                       |  2919K|   172M|    11M| 15147   (2)| 00:03:33 |        |      |
|   3 |    TABLE ACCESS FULL | MASTER_TBL            |   289K|  8494K|       |  5590   (2)| 00:01:19 |        |      |
|*  4 |    HASH JOIN         |                       |  1225K|    37M|       |  6833   (2)| 00:01:36 |        |      |
|   5 |     REMOTE           | REMOTE_TBL            |    29 |   348 |       |    24   (0)| 00:00:01 |  REMDB | R->S |
|   6 |     TABLE ACCESS FULL| DETAIL_TBL            |  4191K|    79M|       |  6781   (2)| 00:01:35 |        |      |
----------------------------------------------------------------------------------------------------------------------

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

   2 - access("A"."MRF_ID"="B"."MRF_ID" AND "A"."MRF_CODE"="B"."MRF_CODE")
   4 - access(TRIM(SUBSTR("A"."MF_NO",4))=LPAD("MF_NO",4,'0'))

This worked as an emergency painkiller before the routine lab tests are performed and an appropriate action is decided.

In the bad execution plan, to access the master table (MASTER_TBL), optimizer is doing an index range scan (“SYS_C0011692”) and the cardinality reported is “3”. This is where the real problem is hiding. Drilling into the tables, columns and indexes for both the tables revealed this information:

Table Name: MASTER_TBL
Primary Key: MRF_ID, MRF_CODE, ORDNO
Num Rows: 287,456

Table Name: CHILD_TBL
Primary Key: MRF_ID, MRF_CODE, ORDNO
Num Rows: 4,159,964

Oops… there are nearly 300,000 records in the MASTER_TBL, but the execution plan indicates a cardinality of merely 3. So, there is something’s serious wrong somewhere. First suspect is table and index statistics. As suspected, statistics on MASTER_TBL were botched up. These were the steps performed on the MASTER_TBL:

1) Data was cleaned 2) Initial data load was run 3) Statistics were collected 4) Remaining major chunk of the data loaded

After collecting fresh statistics on the MASTER_TBL things got back on track. Also, data belonging to columns “MRF_ID” & “MRF_CODE” is evenly spread across all the used blocks in MASTER_TBL & CHILD_TBL tables. Moreover, there is no limiting condition on these columns which could encourage optimizer to go with an index access path. So, it would make no sense for the optimizer to go with an index access path.