a case study of pagination, first_rows and hibernate

I want to share a bit of what I had been working on this week. During a quick check of one of our databases I came across a SQL in EM12c’s top activity section that drew my attention. And upon closer inspection I found more than this one that looked alike and were also pretty high up on the top SQL list. All of them did these pagination type queries from a java application using hibernate as an OR mapper to generate their SQL.

This is the (reduced and anonymized) statement I was looking at:

/*
select generatedAlias0
from Entity as generatedAlias0
where ( generatedAlias0.attribute01 is null ) and ( generatedAlias0.attribute02 in (1L, 1L) ) order by generatedAlias0.type asc, upper(generatedAlias0.name) asc */
SELECT
  /*+FIRST_ROWS */
  *
FROM
  (SELECT row_.*,
    rownum rownum_
  FROM
    (SELECT tableA0_.*,
      CASE
        WHEN tableB0_1_.id IS NOT NULL
        THEN 1
        WHEN tableC0_2_.id IS NOT NULL
        THEN 2 
        WHEN tableA0_.id IS NOT NULL
        THEN 0
      END AS clazz_
    FROM tableA tableA0_
    LEFT OUTER JOIN tableB tableB0_1_
    ON tableA0_.id=tableB0_1_.id
    LEFT OUTER JOIN tableC tableC0_2_
    ON tableA0_.id            =tableC0_2_.id
    WHERE (tableA0_.attributeA IS NULL)
    AND (tableA0_.attributeB  IN (1 , 1))
    ORDER BY tableA0_.type ASC,
      upper(tableA0_.name) ASC
    ) row_
  WHERE rownum <= :1
  )
WHERE rownum_ > :2

The query results in this execution plan:

------------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |                  |       |       |  5684 (100)|          |
|*  1 |  VIEW                             |                  |   150 |   398K|  5684   (1)| 00:01:09 |
|*  2 |   COUNT STOPKEY                   |                  |       |       |            |          |
|   3 |    VIEW                           |                  |  5714 |    14M|  5684   (1)| 00:01:09 |
|*  4 |     SORT ORDER BY STOPKEY         |                  |  5714 |   613K|  5684   (1)| 00:01:09 |
|   5 |      NESTED LOOPS OUTER           |                  |  5714 |   613K|  5683   (1)| 00:01:09 |
|   6 |       NESTED LOOPS OUTER          |                  |  5714 |   574K|   855   (1)| 00:00:11 |
|*  7 |        TABLE ACCESS BY INDEX ROWID| tableA           |  5714 |   552K|   855   (1)| 00:00:11 |
|*  8 |         INDEX RANGE SCAN          | tableA_attrA_IDX | 53149 |       |   106   (0)| 00:00:02 |
|*  9 |        INDEX UNIQUE SCAN          | TABLEC_PK        |     1 |     4 |     0   (0)|          |
|  10 |       TABLE ACCESS BY INDEX ROWID | TABLEB           |     1 |     7 |     1   (0)| 00:00:01 |
|* 11 |        INDEX UNIQUE SCAN          | TABLEB_PK        |     1 |       |     0   (0)|          |
------------------------------------------------------------------------------------------------------

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

   1 - filter("ROWNUM_">:2)
   2 - filter(ROWNUM<=:1)
   4 - filter(ROWNUM<=:1)
   7 - filter("TABLEA0_"."ATTRIBUTE01" IS NULL)
   8 - access("TABLEA0_"."ATTRIBUTE02"=1)
   9 - access("TABLEA0_"."ID"="TABLEC0_2_"."ID")
  11 - access("TABLEA0_"."ID"="TABLEB0_1_"."ID")

The expensive part here is the second (or outer) NL join in step 5. This will perform 5700+ index and table lookups on tableB which is not very big to begin with. I wanted to say 42 blocks but I looked it up and there were 80. The index tableB_PK is also rather small with a blevel of 1 but that means that each iteration of executing steps 10 and 11 above takes 3 buffer lookups or LIOs. Two for the index and one for the table. Multiply by the number of loops (5714) and you get 17142 (42 at last!) LIOs for that part of the query.
In this case a hash join and a full scan of tableB with 80 blocks might have been more appropriate. But with the FIRST_ROWS hint the CBO will not even consider that an option since it basically forces nested loop joins. But we have to get all the rows from that join first and then sort it later. Only after sorting can the stopkey kick in. So even if we really only want to fetch one row, we have to evaluate the whole join first, then sort.

This is what the current documentation has to say about FIRST_ROWS

FIRST_ROWS is available for backward compatibility and plan stability; use FIRST_ROWS_n instead.

FIRST_ROWS tells your DB to pretend it is still in the 80s and forget about all the goodness and improvements in the CBO. Which now supports the FIRST_ROWS_N or FIRST_ROWS(n) hints to indicate that we only want to fetch a subset of the resultset. But we still leave it up to the CBO to determine the best plan given the amount of rows we want to fetch. This will not always favour nested loops like the old hint. And in addition to that, when the CBO sees a query with ... where rownum <= :1, it will add a FIRST_ROWS(n) hint for us. Read more about this from Jonathan Lewis.

So getting rid of the FIRST_ROWS hint seemed like a good idea and sure enough, here is the execution plan for that:

-------------------------------------------------------------------------------------------
| Id  | Operation                | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT         |                |       |       |   150 (100)|          |
|*  1 |  VIEW                    |                |  5714 |    14M|   150   (2)| 00:00:02 |
|*  2 |   COUNT STOPKEY          |                |       |       |            |          |
|   3 |    VIEW                  |                |  5714 |    14M|   150   (2)| 00:00:02 |
|*  4 |     SORT ORDER BY STOPKEY|                |  5714 |   613K|   150   (2)| 00:00:02 |
|*  5 |      HASH JOIN OUTER     |                |  5714 |   613K|   149   (2)| 00:00:02 |
|   6 |       NESTED LOOPS OUTER |                |  5714 |   574K|   132   (1)| 00:00:02 |
|*  7 |        TABLE ACCESS FULL | TABLEA         |  5714 |   552K|   132   (1)| 00:00:02 |
|*  8 |        INDEX UNIQUE SCAN | TABLEC_PK      |     1 |     4 |     0   (0)|          |
|   9 |       TABLE ACCESS FULL  | TABLEB         | 44893 |   306K|    16   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------

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

   1 - filter("ROWNUM_">TO_NUMBER(:2))
   2 - filter(ROWNUM<=TO_NUMBER(:1))
   4 - filter(ROWNUM<=TO_NUMBER(:1))
   5 - access("TABLEA0_"."ID"="TABLEB0_1_"."ID")
   7 - filter(("TABLEA0_"."ATTRIVUTE01" IS NULL AND "TABLEA_"."ATTRIBUTE02"=1))
   8 - access("TABLEA0_"."ID"="TABLEC0_2_"."ID")

Even though this hash join involves two full scans, it works out much better than the NL we saw earlier. This is not always the case but that is exactly what the CBO is good at: cost both options and choose the one that is better. And the performance benefit was also immediately visible in execution time, not just cost. Looking at dba_hist_sqlstat confirmed a 25% speedup of the new plan versus the old one. So how do we get rid of this hint in our production SQL?

Add SQL profiles

One "solution" to this could be to add a SQL profile to the sql_id. A SQL profile adds some extra statistics to a SQL which can help, but that is not even the primary reason why we want it. One of the sideeffects of a sql with a profile attached is that all user-provided hints are being ignored. Which is exactly what we want in this case.

SQL Profiles are enabled through the SQL tuning advisor which has a great frontent in Enterprise Manager. But I don't like taking screenshots too much, so here is how you can run a tuning advisor job against a single sql_id and accept the suggested profile. Check out oracle-base if you are interested more in the syntax and other options.

SQL> set serveroutput on
DECLARE
  l_sql_tune_task_id  VARCHAR2(100);
BEGIN
  l_sql_tune_task_id := DBMS_SQLTUNE.create_tuning_task (
                          sql_id      => 'b35bss47r2nqa',
                          scope       => DBMS_SQLTUNE.scope_comprehensive,
                          time_limit  => 60,
                          task_name   => 'b35bss47r2nqa_tuning_task',
                          description => 'Tuning task for statement b35bss47r2nqa.');
  DBMS_OUTPUT.put_line('l_sql_tune_task_id: ' || l_sql_tune_task_id);
END;
/

SQL> EXEC DBMS_SQLTUNE.execute_tuning_task(task_name => 'b35bss47r2nqa_tuning_task');

PL/SQL procedure successfully completed.

SET LONG 10000;
SET PAGESIZE 1000
SQL> SQL> SET LINESIZE 200
SQL>
SQL>
SQL> SELECT DBMS_SQLTUNE.report_tuning_task('b35bss47r2nqa_tuning_task') AS recommendations FROM dual;

[...]


----------------------------------
FINDINGS SECTION (1 finding)
-----------------------

1- SQL Profile Finding (see explain plans section below)
--------------------------------------------------------
  A potentially better execution plan was
 found for this statement.

  Recommendation (estimated benefit: 36.23%)
  ------------------------------------------
  - Consider accepting the recommended SQL
 profile.
    execute dbms_sqltune.accept_sql_profile(
     task_name => 'b35bss47r2nqa_tuning_task', 
     task_owner => 'SYS',
     replace => TRUE);
[...]

SQL> EXEC DBMS_SQLTUNE.accept_sql_profile(task_name => 'b35bss47r2nqa_tuning_task');

PL/SQL procedure successfully completed.

Find the proper root cause (between the app and hibernate)

The system had plenty more statements like this and adding profiles to each of them would have kept me or any other DBA busy for quite a while. And a profile is really more of a workaround than a real solution. So we also looked at fixing this in the application. The SQL in question was being generated by hibernate, so I looked at that first but could not find or reproduce the hint. After a lot of searching it turned out that a developer here had extended the oracle10g dialect of hibernate to include that hint. Nobody seems to be able to remember why, maybe they followed some internet advice blindly or maybe that setting really did help in one situation. I would take this as an example of why _not_ to make a blind change from the default, at least not without looking at the consequences and documenting why such a change was made for all SQLs like this.

FWIW this is the code that extended pagingSelect in the existing Oracle10gDialect (please don't try this at home):

StringBuffer pagingSelect = new StringBuffer(sql.length() + 120);
  if (hasOffset) {
    pagingSelect.append("select /*+FIRST_ROWS */ * from ( select row_.*, rownum rownum_ from ( ");
  } else {
    pagingSelect.append("select /*+FIRST_ROWS */ * from ( ");
}

I have a few more notes on this SQL but feel like this post is already long enough and might add them at a later time in extra posts.

Leave a Reply

Your email address will not be published. Required fields are marked *