Why are all blocks read from disk for every execution

A colleague complained that a query was much slower in QA compared to PROD even if it had the same plan and returned the same amount of rows. QA took around 12 seconds and in PROd 2 seconds. He also noticed much more physical reads on the QA system.

My colleague showed me an autotrace output of statistics that looked like this

PROD: Statistics                             QA: Statistics 
--------------------------------------------------------------------------------------------------------
 1 recursive calls                                  1 recursive calls 
 0 db block gets                                    0 db block gets 
 57105 consistent gets                          57094 consistent gets 
 0 physical reads                               56767 physical reads 
 0 redo size                                        0 redo size 
 24096167 bytes sent via SQL*Net to client   24096167 bytes sent via SQL*Net to client 
 200800 bytes received via SQL*Net from client 200800 bytes received via SQL*Net from client
 18209 SQL*Net roundtrips to/from client        18209 SQL*Net roundtrips to/from client 
 1 sorts (memory)                                   1 sorts (memory) 
 0 sorts (disk)                                     0 sorts (disk) 
 273115 rows processed                         273115 rows processed

We discussed that QA had almost all blocks read from disk for every execution, even if it was executed several times in a row. It was expected that after the first execution the blocks should be read from the buffer cache. That’s the way it was done in production, statistics in prod showed physical reads = 0.

So I ran the query in both environment and compared the plans

Plan hash value: 3622568521

--------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation        | Name                 | Starts | E-Rows |E-Bytes|E-Temp | Cost (%CPU)| A-Rows | A-Time    | Buffers | OMem | 1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT  |                      |      1 |        |       |       | 31526 (100)|    273K|00:00:01.59 | 57105 |       |      |          |
| 1 | SORT ORDER BY     |                      |      1 |    281K|    35M|    44M|   31526 (1)|    273K|00:00:01.59 | 57105 |    37M| 2182K|   33M (0)|
|* 2 | HASH JOIN        |                      |      1 |    281K|    35M|  3064K|   23240 (1)|    273K|00:00:01.34 | 57105 |  3935K| 2624K| 4518K (0)|
|* 3 | INDEX RANGE SCAN | IU_TRAINEXT_ID_JDOID |      1 |  57041 |  2395K|       |      25 (0)|  54623 |00:00:00.02 |   315 |       |      |          |
|* 4 | TABLE ACCESS FULL| OPARAMETER           |      1 |   1567K|   133M|       |   15576 (1)|   1560K|00:00:00.80 | 56790 |       |      |          |
--------------------------------------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

 1 - SEL$1
 3 - SEL$1 / T0@SEL$1
 4 - SEL$1 / T1@SEL$1

Peeked Binds (identified by position):
--------------------------------------

 1 - (VARCHAR2(30), CSID=178): 'T15_141214%'

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

 2 - access("T0"."JDOID"="T1"."OPARAMETERIZEDRESOURCE_JDOID")
 3 - access("T0"."ID" LIKE :V1)
     filter("T0"."ID" LIKE :V1)
 4 - filter("T1"."OPARAMETERIZEDRESOURCE_JDOID" IS NOT NULL)

 

And for QA system

Plan hash value: 3622568521

-----------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation       | Name                 | Starts | E-Rows |E-Bytes|E-Temp | Cost (%CPU)| A-Rows | A-Time    | Buffers | Reads | OMem | 1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT  |                      |     1 |        |       |       | 31205 (100)|    273K|00:00:12.73 |  57094 | 56767 |      |      |          |
| 1 | SORT ORDER BY     |                      |     1 |    270K|    34M|    43M|   31205 (1)|    273K|00:00:12.73 |  57094 | 56767 |   37M| 2182K|   33M (0)|
|* 2 | HASH JOIN        |                      |     1 |    270K|    34M|  2944K|   23219 (1)|    273K|00:00:12.49 |  57094 | 56767 | 3935K| 2624K| 3583K (0)|
|* 3 | INDEX RANGE SCAN | IU_TRAINEXT_ID_JDOID |     1 |  54765 |  2299K|       |      25 (0)|  54623 |00:00:00.01 |    315 | 0     |      |      |          |
|* 4 | TABLE ACCESS FULL| OPARAMETER           |     1 |   1564K|   132M|       |   15576 (1)|   1558K|00:00:12.01 |  56779 | 56767 |      |      |          |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

 1 - SEL$1
 3 - SEL$1 / T0@SEL$1
 4 - SEL$1 / T1@SEL$1

Peeked Binds (identified by position):
--------------------------------------

 1 - (VARCHAR2(30), CSID=178): 'T15_141214%'

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

 2 - access("T0"."JDOID"="T1"."OPARAMETERIZEDRESOURCE_JDOID")
 3 - access("T0"."ID" LIKE :V1)
     filter("T0"."ID" LIKE :V1)
 4 - filter("T1"."OPARAMETERIZEDRESOURCE_JDOID" IS NOT NULL)

If we compare the two executions we have the same Plan hash value: 3622568521, which means the execution plan is the same and we can also see that by reading it.

One thing that we have in the QA statistics that we don’t have in PROD is a column named READS. Reads means physical reads, reading blocks from disks. This complies with the statistics that was given in the beginning. We can see that in QA the TABLE ACCESS FULL  of the the table OPARAMETER reads all blocks from disk. Which it don’t do in PROD.

Why do we see these differences, oracle has changed behavior of how we handle serial access to a table. Read: Higher ‘direct path read’ Waits in 11g when Compared to 10g (Doc ID 793845.1)

In the Note it states that

“In 10g, serial table scans for “large” tables go through the buffer cache (by default).

In 11g, there has a been a change in the rules that choose between using ‘direct path reads’ and reads through the buffer cache for serial (i.e. non-parallel) table scans. This decision is based on the size of the table, buffer cache size, and various other statistics. Since Direct path reads are faster than scattered reads and have less impact on other processes because they avoid latches, it is likely that they will be chosen for such reads in 11g and above.

The choice can vary over time for the same tables, for example, when using Automatic Shared Memory Management (ASMM) with the buffer cache low limit set low when compared to the normal workload requirements (and usually after startup). 11g might choose to do serial direct path read scans for large tables that do not fit in the SGA. When ASMM increases the buffer cache due to increased demand, 11g might then change to go through the buffer cache for these same large tables.”

 

So there are several parameters involved in the decision if we should use the buffer cache or not. In our case the size of the tables are similar. What about the buffer cache ?

PROD>select * from v$sga;                 AQ> select * from v$sga; 
 
NAME VALUE NAME VALUE 
-------------------- -------------------- -------------------- ---------------- 
Fixed Size                      2,268,952 Fixed Size                  2,269,872 
Variable Size               5,100,273,896 Variable Size           4,831,841,616 
Database Buffers           58,518,929,408 Database Buffers        3,506,438,144 
Redo Buffers                  114,561,024 Redo Buffers               10,600,448

Comparing the two buffer cache sizes for PROD and QA it is a huge difference between PROD and QA. Looking in the Database Performance Tuning Guide we can see when we consider to use the cache.

Table Size Size Criteria Caching
Small Number of blocks < 20 or 2% of total cached blocks, whichever is larger If STATISTICS_LEVEL is se to TYPICAL or higher, then Oracle Database decides whether to cache a table depending on the table scan history. The database caches the table only if a future table scan is likely to find the cached blocks. If STATISTICS_LEVEL is set to BASIC, then the table is not cached.
Medium Larger than a small table, but < 10% of total cached blocks Oracle Database decides whether to cache a table based on its table scan and workload history. It caches the table only if a future table scan is likely to find the cached blocks.
Large > 10% of total cached blocks Not cached

What about our tables

PROD> select blocks from dba_tables where table_name='OPARAMETER';

 BLOCKS
----------
 57147

QA> select blocks from dba_tables where table_name='OPARAMETER';

 BLOCKS
----------
 57147

So the tables are similar in size.
If we use this information in the QA system, I would say that the table is referenced as a big table and therefore never cached, while in PROD it would be a medium table and therefore cached since it is likely that future reads will find them in the cache.

The beahavior is expected and per design, if we want QA to behave the same as PROD we need to increase the memory for QA.

Read also this:

What’s The Difference Between Direct Path Reads And DB File Scattered Reads?

The Mystery Surrounding Oracle DataBase 11g And Direct Reads

 

 

 

Advertisements

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