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.