Making sense of direct path reads during primary key lookups

I recently made an interesting observation while monitoring database performance on an Oracle Enterprise Edition system. While looking at some ASH data (for which you must be licensed appropriately!) I came across direct path reads attributed to a select statement performing a primary key lookup. At first, this didn’t make much sense to me, but it’s actually intended behaviour and not a bug.

In this post I’m reproducing what I observed. I am using Oracle 18.4.0 for this experiment running on my Linux lab environment. The hardware uses 1s8c16t with 64 GB of memory.

Direct Path Reads are multi-block reads you often find in decision support systems when a query is going over large amounts of data. They are un-buffered, as in they use the reading session’s private memory, not the buffer cache. Not exactly what you would expect with a primary key lookup if the index was used. It should be more like this tkprof’d SQL trace:

SQL ID: b5dxjj3wm4yz8 Plan Hash: 4043159647
select *
from
orders where order_id = 100

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 378 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 0 382 0 1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 82
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY INDEX ROWID ORDERS (cr=4 pr=0 pw=0 time=32 us starts=1 cost=3 size=95 card=1)
1 1 1 INDEX UNIQUE SCAN ORDER_PK (cr=3 pr=0 pw=0 time=22 us starts=1 cost=2 size=0 card=1)(object id 81853)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL Net message to client 2 0.00 0.00
SQL Net message from client 2 11.40 11.40

No physical I/O anywhere to be seen.

During my original investigation I noticed that direct path reads were attributed to a table containing a CLOB column. The query was something along the lines of “select * from table where primaryKeyColumn = :bindVariable”. The primaryKeyColumn was defined as a number. This should be easy to recreate.

The test case

Based on the Swingbench “ORDERS” table I created a new table using the following DDL:

CREATE TABLE martin.orders_clob (
    order_id                  NUMBER(12,0)
        NOT NULL ENABLE,
    order_clob                CLOB
        NOT NULL ENABLE,
    order_date                TIMESTAMP(6) WITH LOCAL TIME ZONE
        NOT NULL ENABLE,
    order_mode                VARCHAR2(8 BYTE),
    customer_id               NUMBER(12,0)
        NOT NULL ENABLE,
    order_status              NUMBER(2,0),
    order_total               NUMBER(8,2),
    sales_rep_id              NUMBER(6,0),
    promotion_id              NUMBER(6,0),
    warehouse_id              NUMBER(6,0),
    delivery_type             VARCHAR2(15 BYTE),
    cost_of_delivery          NUMBER(6,0),
    wait_till_all_available   VARCHAR2(15 BYTE),
    delivery_address_id       NUMBER(12,0),
    customer_class            VARCHAR2(30 BYTE),
    card_id                   NUMBER(12,0),
    invoice_address_id        NUMBER(12,0),
    constraint pk_orders_clob primary key ( order_id )
) tablespace bigfile_tbs
lob ( order_clob ) store as securefile (enable storage in row);

Please note that the clob is stored in row.

Next I inserted a large number of rows into the table, based again on soe.orders:

INSERT/*+ enable_parallel_dml append parallel(4) */ INTO martin.orders_clob
    SELECT /*+ parallel(4) */
        order_id,
        case
          when mod(rownum,10) = 0 then rpad('X',5000,'Y')
          else rpad('Y', 50, 'Z') 
        end,
        order_date,
        order_mode,
        customer_id,
        order_status,
        order_total,
        sales_rep_id,
        promotion_id,
        warehouse_id,
        delivery_type,
        cost_of_delivery,
        wait_till_all_available,
        delivery_address_id,
        customer_class,
        card_id,
        invoice_address_id
    FROM
        soe.orders
    WHERE    
        ROWNUM <= 1E6;

The case statement ensures that every 10th row has a lob exceeding the size limit of an inline LOB. Apparently that’s 4000 bytes minus a little bit of overhead. As a result the LOB data should be stored outside the table.

Load!

I am now generating some load against the system, being careful not to overload my lab system. I limited myself to 8 sessions:

SQL> select count(*) from v$session where username = 'MARTIN' and program like 'JDBC%';

  COUNT(*)
----------
         8

After a few minutes I can see these direct path reads show up. This is really easy if you have the right tools – I use Tanel Poder’s scripts a lot. One particularly useful script is ashtop.sql (remember the license thing again!) that you can see here:

SQL> @ashtop sql_id,event,session_state username='MARTIN' "to_date('19.12.2018 15:35:00', 'dd.mm.yyyy hh24:mi:ss')" "to_date('19.12.2018 15:45:00','dd.mm.yyyy hh24:mi:ss')"

    Total
  Seconds     AAS %This   SQL_ID        EVENT                                    SESSION FIRST_SEEN          LAST_SEEN           DIST_SQLEXEC_SEEN
--------- ------- ------- ------------- ---------------------------------------- ------- ------------------- ------------------- -----------------
     1380     2.3   74% | 7hth4y8d9h7q8                                          ON CPU  2018-12-19 15:35:02 2018-12-19 15:44:58              1232
      225      .4   12% |                                                        ON CPU  2018-12-19 15:35:04 2018-12-19 15:44:59                 2
      175      .3    9% | 7hth4y8d9h7q8 library cache: mutex X                   WAITING 2018-12-19 15:35:15 2018-12-19 15:44:49               175
       65      .1    3% | 7hth4y8d9h7q8 direct path read                         WAITING 2018-12-19 15:35:25 2018-12-19 15:44:41                65
        8      .0    0% | 7hth4y8d9h7q8 SQL*Net more data to client              WAITING 2018-12-19 15:38:52 2018-12-19 15:44:29                 8
        3      .0    0% | 7hth4y8d9h7q8 cursor: pin S                            WAITING 2018-12-19 15:36:59 2018-12-19 15:42:08                 1
        3      .0    0% |               cursor: pin S                            WAITING 2018-12-19 15:35:57 2018-12-19 15:42:08                 1

7 rows selected.

I’ll also show you the execution plan to confirm I’m not actually performing an unintentional full table scan:

SQL> select * from dbms_xplan.display_cursor('7hth4y8d9h7q8');

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------
SQL_ID  7hth4y8d9h7q8, child number 0
-------------------------------------
select /* CLOB */ * from martin.orders_clob where order_id =
trunc(dbms_random.value(1,1000000))

Plan hash value: 3284193906

----------------------------------------------------------------------------------------------
| Id  | Operation                   | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                |       |       |     3 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| ORDERS_CLOB    |     1 |   227 |     3   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | PK_ORDERS_CLOB |     1 |       |     2   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

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

   2 - access("ORDER_ID"=TRUNC("DBMS_RANDOM"."VALUE"(1,1000000)))


20 rows selected.

I didn’t want to use Java’s random method generator, hence the call to dbms_random.value. So there you have it: direct path reads when performing index lookups.

Thanks and big shout out to Tanel Poder for his scripts, they are awesome.

Advertisements