A recent thread on the Oracle developer community database forum raised a fairly typical question with a little twist. The basic question is “why is this (very simple) query slow on one system when it’s much faster on another?” The little twist was that the original posting told use that “Streams Replication” was in place to replicate the data between the two systems.
To make life easy for remote trouble-shooters the poster had supplied (for each system) the output from SQL Monitor when running the query, the autotrace output (which shows the predicate section that SQL Monitor doesn’t report), and the session statistics for the query run, plus some statistics about the single table in the query, the index used in the plan, and the column on which that index was based.
Here, with a little cosmetic editing (and a query that has clearly been camouflaged by the OP), is the information supplied for the faster database, where the query took about 30 seconds to complete.
SELECT c1, c2, c3, c4, c5, c6, c7, c8..
FROM TAB1
WHERE STS IN ( 'A', 'B')
AND cnt < '4'
AND dt < sysdate
and rownum <=1;
Sql_monitor and stats from DB1
******************************
Global Information
------------------------------
STS : DONE (ALL ROWS)
Instance ID : 1
Execution Started : 08/17/2018 08:31:22
First Refresh Time : 08/17/2018 08:31:22
Last Refresh Time : 08/17/2018 08:31:53
Duration : 31s
Program : sqlplus.exe
Fetch Calls : 1
Global Stats
===============================================================================
| Elapsed | Cpu | IO | Concurrency | Fetch | Buffer | Read | Read |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls | Gets | Reqs | Bytes |
===============================================================================
| 33 | 3.00 | 30 | 0.08 | 1 | 102K | 38571 | 301MB |
===============================================================================
SQL Plan Monitoring Details (Plan Hash Value=715774357)
======================================================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | (%) | (# samples) |
======================================================================================================================================================================================
| 0 | SELECT STATEMENT | | | | 1 | +31 | 1 | 1 | | | | |
| 1 | COUNT STOPKEY | | | | 1 | +31 | 1 | 1 | | | | |
| 2 | INLIST ITERATOR | | | | 1 | +31 | 1 | 1 | | | | |
| 3 | TABLE ACCESS BY INDEX ROWID | TAB1 | 114K | 33399 | 32 | +0 | 2 | 1 | 38377 | 300MB | 96.77 | Cpu (1) |
| | | | | | | | | | | | | db file sequential read (16) |
| | | | | | | | | | | | | read by other session (13) |
| 4 | INDEX RANGE SCAN | TAB1_STS_IDX | 115K | 723 | 30 | +2 | 2 | 118K | 194 | 2MB | 3.23 | read by other session (1) |
======================================================================================================================================================================================
---------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 1847 | 33399 (1)| 00:03:14 |
|* 1 | COUNT STOPKEY | | | | | |
| 2 | INLIST ITERATOR | | | | | |
|* 3 | TABLE ACCESS BY INDEX ROWID| TAB1 | 114K| 201M| 33399 (1)| 00:03:14 |
|* 4 | INDEX RANGE SCAN | TAB1_STS_IDX | 114K| | 723 (1)| 00:00:05 |
---------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(ROWNUM<=1)
3 - filter("cnt"<'4' AND "dt"<SYSDATE@!)
4 - access("STS"='A' OR "STS"='B')
Table stats
-----------
table_name num_rows blocks empty_blocks chain_cnt avg_row_len
TAB1 79,654,925 22,416,917 0 0 1,847
column_stats(STS)
------------------
table_name column_name num_distinct num_nulls density avg_col_len
TAB1 STS 5 0 6.2049E-9 2
Index_stats(on STS)
-------------------
index_name leaf_blocks distinct_keys avg_leaf_blocks_per_key avg_data_blocks_per_key clustering_factor num_rows
TAB1_STS_IDX 487,939 5 97,587 4,458,874 22,294,372 78,308,939
Session stats
-------------
process last non-idle time 1,534,508,966
session connect time 1,534,508,966
logical read bytes from cache 839,663,616
cell physical IO interconnect bytes 316,055,552
physical read bytes 316,055,552
physical read total bytes 316,055,552
file io wait time 17,044,083
session pga memory 8,643,880
session pga memory max 8,643,880
temp space allocated (bytes) 4,194,304
session uga memory 1,755,696
session uga memory max 1,755,696
buffer is pinned count 135,743
table fetch by rowid 117,519
non-idle wait count 107,301
session logical reads 102,500
consistent gets 102,450
consistent gets from cache 102,448
no work - consistent read gets 102,368
buffer is not pinned count 101,741
free buffer inspected 43,458
free buffer requested 38,592
physical read total IO requests 38,581
physical read IO requests 38,581
physical reads 38,581
physical reads cache 38,579
hot buffers moved to head of LRU 37,258
bytes sent via SQL*Net to client 7,370
bytes received via SQL*Net from client 6,869
redo size 5,536
undo change vector size 4,432
DB time 3,166
non-idle wait time 2,962
user I/O wait time 2,954
table fetch continued row 2,423
And here’s the equivalent information from the slower database where the query took more than 9 times as long (4 minutes 42 seconds) to complete.
Global Information
------------------------------
STS : DONE (ALL ROWS)
Instance ID : 1
Execution Started : 08/17/2018 08:21:47
First Refresh Time : 08/17/2018 08:21:47
Last Refresh Time : 08/17/2018 08:26:29
Duration : 282s
Module/Action : SQL*Plus/-
Program : sqlplus.exe
Fetch Calls : 1
Global Stats
================================================================
| Elapsed | Cpu | IO | Fetch | Buffer | Read | Read |
| Time(s) | Time(s) | Waits(s) | Calls | Gets | Reqs | Bytes |
================================================================
| 287 | 8.76 | 278 | 1 | 110K | 110K | 858MB |
================================================================
SQL Plan Monitoring Details (Plan Hash Value=715774357)
======================================================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | (%) | (# samples) |
======================================================================================================================================================================================
| 0 | SELECT STATEMENT | | | | 1 | +282 | 1 | 1 | | | | |
| 1 | COUNT STOPKEY | | | | 1 | +282 | 1 | 1 | | | | |
| 2 | INLIST ITERATOR | | | | 1 | +282 | 1 | 1 | | | | |
| 3 | TABLE ACCESS BY INDEX ROWID | TAB1 | 142K | 40211 | 282 | +1 | 2 | 1 | 109K | 854MB | 100.00 | db file sequential read (277) |
| 4 | INDEX RANGE SCAN | TAB1_STS_IDX | 142K | 892 | 280 | +3 | 2 | 118K | 491 | 4MB | | |
======================================================================================================================================================================================
Execution Plan (autotrace)
---------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 1847 | 40211 (1)| 00:08:03 |
|* 1 | COUNT STOPKEY | | | | | |
| 2 | INLIST ITERATOR | | | | | |
|* 3 | TABLE ACCESS BY INDEX ROWID| TAB1 | 141K| 249M| 40211 (1)| 00:08:03 |
|* 4 | INDEX RANGE SCAN | TAB1_STS_IDX | 141K| | 892 (1)| 00:00:11 |
---------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(ROWNUM<=1)
3 - filter("cnt"<'4' AND "dt"<SYSDATE@!)
4 - access("STS"='A' OR "STS"='B')
Table stats
-----------
table_name num_rows blocks empty_blocks chain_cnt avg_row_len
TAB1 79,447,350 22,318,667 710 537,597 1,847
column_stats(STS)
-----------------
table_name column_name num_distinct num_nulls density avg_col_len
TAB1 STS 5 0 6.1789E-9 2
Index_stats(on STS)
-------------------
index_name leaf_blocks distinct_keys avg_leaf_blocks_per_key avg_data_blocks_per_key clustering_factor num_rows
TAB1_STS_IDX 493,152 5 98,630 4,382,625 21,913,127 79,106,263
Session Stats
-------------
process last non-idle time 1,534,508,200
session connect time 1,534,508,200
logical read bytes from cache 903,790,592
physical read total bytes 899,629,056
cell physical IO interconnect bytes 899,629,056
physical read bytes 899,629,056
file io wait time 277,881,742
session pga memory 8,586,744
session pga memory max 8,586,744
temp space allocated (bytes) 4,194,304
session uga memory max 1,690,184
session uga memory 1,690,184
buffer is pinned count 129,148
table fetch by rowid 117,521
session logical reads 110,326
consistent gets 110,276
consistent gets from cache 110,276
no work - consistent read gets 110,071
non-idle wait count 109,879
free buffer requested 109,830
physical read IO requests 109,818
physical reads cache 109,818
physical reads 109,818
physical read total IO requests 109,818
buffer is not pinned count 109,577
free buffer inspected 70,740
hot buffers moved to head of LRU 31,910
DB time 28,203
non-idle wait time 27,788
user I/O wait time 27,788
dirty buffers inspected 19,067
bytes sent via SQL*Net to client 14,927
bytes received via SQL*Net from client 10,607
redo size 5,440
undo change vector size 4,432
table fetch continued row 3,660
There are all sorts of noteworthy details in these two sets of information – some of the “how to see what’s in front of you” type, some of the “be careful, Oracle can deceive you” type. So I’m going to walk though the output picking up a number of background thoughts before commenting on the answer to the basic question.
We’ll start with the object statistics, then we’ll look at the SQL Monitor plan to see if we can determine where the extra time was spent, then we’ll try to work out what else the plan might be telling us about the code and data, then we’ll summarise my observations to make a claim about the difference in behaviour.
Object statistics
The table has 79M rows with average length of 1,847 bytes, using 22M blocks. With an 8KB block size and that average row size we would expect to see about 3 rows per block, and that’s fairly consistent with the value of rows / blocks. We don’t know what the sample size was for this stats collection, but it might have been a “small” sample size rather than the the 100% you would get from using auto_sample_size, so that might also explain some discrepancy between the two different views on the figures.
We note that the secondary system reports a chain_cnt in excess of 500,000 rows. The only (unhacked) way that this figure could be set would be through a call to analyze statistics, and once the figure is there it won’t go away unless you use the analyze command again to delete statistics. We don’t know the history of how and when the figure got there so it doesn’t guarantee that there are any chained or migrated rows, nor does the zero in the table stats on the primary system guarantee that it doesn’t have any chained or migrated rows – all it tells us is that at some time someone used the wrong command to gather stats and there were some (less than 1%) migrated or chained rows in the table at the time. (The optimizer will use this figure in its arithmetic if it is set, by the way, so it may affect some of the cost calculations – but not by a huge amount.)
The column sts reports 5 distinct values, no nulls, and a density of 6.2e-9 which is roughly half of 1/79M: so we have a frequency histogram on the column (in the absence of a histogram the density would be 1/5, and it’s reasonable to assume that the number of buckets was either the default or set to something larger than 5). We were told that the system was running 11.2.0.4 – so we have to be a little suspicious about the accuracy of this histogram since it will have been sampled with a very small sample if the stats collection had used auto_sample_size. (12c will use a specially optimized 100% sample for frequency and top-N histograms when using auto_sample_size)
The index on sts has a clustering_factor of around 22M which is similar to the number of blocks in the table – and that’s not too surprising if there are are only a very small number of distinct values in the column – especially when the presence of the histogram suggest that there’s a skew in the data distribution. (There’s more to come on that point.) The number of leaf blocks is about 500,000 (being lazy about arithmetic) – just as a side note this suggests the index is running in a fairly inefficient state (and probably hasn’t been created with the compress keyword).
Doing a rough estimate of the index arithmetic : the avg_col_len for sts is 2, so the space required for each index entry will be 13 bytes (2 for the column, 7 for the rowid content, 2 for the row header, 2 for the row directory entry). Take off the block overhead, and assume the index is running at a “typical” 70% space usage per leaf block and you might expect 5,600 bytes used per leaf block for current index data and that works out to about 430 index entries per leaf block. With 79M rows in the table that should lead to 79M/430 leaf blocks – i.e. roughly 184,000 leaf blocks, not 493,000 leaf blocks. However it’s not unusual to see an index with extremely repetitive values operating at something like 50% utilisation, which would bring our estimate to about 310 rows per leaf block and 255,000 leaf blocks – which is still off by a factor of nearly 2 compared to what we’ve actually got. Again, of course, we have to be a little bit cautious about these statistics – we don’t know the sample size, and Oracle uses a surprisingly small number of blocks to sample the stats for an index.
Where’s the time.
The SQL Monitor gives us a very clear report of where most of the time went – almost all of it was spent in I/O waits, and almost all of the wait time was in the “table access by index rowid” opration in both cases; but the primary system did 38,377 read requests while the secondary did 109,000 read requests in that line of the plan. It is significant, though, that quite a lot (40%) of the ASH samples for that operation on the primary system were for “read by other session” rather than “db file sequential read”: in other words some other session(s) were doing a lot of work to pull the data we wanted into the buffer cache at the same time. Apart from the fact that a wait for “read by other session” often means we spend less time waiting than if we’d had to do the read ourselves, the presence of this wait suggests that other sessions may be “pre-caching” data for us so that we end up having to read far fewer blocks than would otherwise be the case.
It’s important to note at the same time that the difference in Buffer Gets for the two systems was small – 102K vs. 110K – and the “Rows (actual)” was the same in both cases – 118K entries returned by the index range scan. Both systems did similar amounts of “logical” work, to process similar amounts of data; the difference was the fraction of the work that required a buffer get to turn into a disc read or a “wait for other read”.
We might want to pick up a few more numbers to corroborate the view that the only significant difference was in the volume of data cached and not some more esoteric reason. Some of the session statistics should help.
DB1: table fetch by rowid 117,519
DB2: table fetch by rowid 117,521
DB1: undo change vector size 4,432
DB2: undo change vector size 4,432
DB1: redo size 5,536
DB2: redo size 5,440
DB1: session logical reads 102,500
DB2: session logical reads 110,326
DB1: no work - consistent read gets 102,368
DB2: no work - consistent read gets 110,071
DB1: table fetch continued row 2,423
DB2: table fetch continued row 3,660
The number of rows fetched by rowid is virtually identical and we have done (virtually) no work that generates undo or redo – such as delayed block cleanout; there are no statistics shown for “%undo record applied” so we probably haven’t done very much work to get a read consistent view of the data though we can’t be sure that the OP simply failed to copy that stat into list supplied (but then the similarity of “session logical reads” to “no work – consistent read gets” confirms the hypothesis that we didn’t do any (significant) work on visiting undo blocks.
We do see a few percent increase in the number of buffer gets (“session logical reads”) – but this may reflect the fact that the actual pattern of data in one table is slightly different from the pattern in the other – thanks to ASSM the process id of the process that inserts a row into a table can affect (within a small range, usually) the block into which the row is inserted; but at 102,000 / 110,000 buffer gets to visit 117,500 rows in the table we can see that there must be some table blocks that hold two (or more) rows that are identified as consecutive in the index – leading to some row visits being achieved through a buffer pin and without a fresh buffer get. You’ll note that this argument is consistent with the small variation in clustering_factor (not that we entirely trust those figures) for the two indexes – the system with the lower clustering_factor for the index has done fewer buffer gets to acquire the same number of rows from the table – by definition that means (assuming default setup) that there are more cases where “the next table row” is in the same block as the current row.
The final figure I’ve shown is the “table fetch continued rows”: according to the table stats (which we don’t necessarily trust completely) 500K out of 79M rows are chained/migrated which is roughly 0.6%. We know that we’re visiting about 117K table rows so might expect (on average) roughly the same percentage migrated/chained viz: 0.6% of 117K = 743, so there’s a little anomaly there (or an error in our assumption about “average” behaviour. It’s worth noting, though, that a “continued fetch” would have to do an extra buffer visit (and maybe an extra physical read). You might wonder, of course, how there could be any chained or migrated rows when the average row length is 1,847 bytes but in a follow-up post the OP did say there were 3 BLOB columns in the table, which can cause havoc with interpreting stats for all sorts of reasons. We don’t have any information about the table structure – particularly whether the columns in the query appear before or after the BLOB columns in the table definition – and we don’t know what processing takes place (for example, maybe the 3rd BLOB is only updated after the sts column has been changed to a value other than A or B which would help to explain why we shouldn’t be using the 0.6% calculation above as a table-wide average), so we’re not in a position to say why any of the continued fetches appear but there are several guesses we could make and they’re all easy to check.
Plan observations
If we examine row estimates we see that it 114K for the faster plan and 141K for the slower plan (with a closely corresponding variation in cost). The difference in estimates simply tells us that the histogram gathering was probably a small sample size and subject to a lot of variation. The scale of the estimates tells us that the A and B rows are probably rare – call it 125K out of 79M rows, about 0.16% of the total rows in the table, so it would not be surprising to see consecutive samples for the histogram producing significant variations in estimates.
The other interesting thing we can note in the SQL Monitor plan is that the Starts column for the index range scan / table access operations in both plans shows the value 2: this means that there are no “A” rows that match the other predicates: Oracle has run the “A” iteration to completion then started the “B” iteration and found a row on the second iteration. Is this a coincidence, or should it always happen, or is it only fairly likely to happen; is it possible to find times when there are no suitable “B” rows but plenty of suitable “A” rows. The final predicate in the query is “rownum <= 1” – so the query is picking one row with no explicit strategy for choosing a specific row when there are multiple appropriate rows, does this mean that we could optimizer the query by rewriting it as a “union all” that searched for B rows first and A rows second ? We just don’t know enough about the processing.
In passing, we can’t get Oracle to search the B rows first by changing the order of the in-list. If you have a predicate like “where sts in ({list of literal values})” the optimizer will sort the list to eliminate duplicates before rewriting the predicate as a list of disjuncts, and then (if the path uses an iterator) iterate through the list in the resulting order.
In the absence of information about the way in which the data is processed we can only say that we need to avoid visiting the table so frequently. To do this we will need to add one or both of the columns from the other predicates to the index – this might double the size of the index, but eliminate 95% of the potential I/O. For example if we discover that A and B rows are initially created “into the future” and this query is looking for a row whose “time has come” so that it can be processed and changed to an X row (say) then there may only ever be a tiny number of rows where the “sts = A and the dt < sysdate” and an index on (sts, dt) would be a perfect solution (especially if it were compressed on at least the first column).
The OP has declared a reluctance to add an index to the table – but there are two points to go with this indexing strategy. Since we know there’s a frequency histogram and the A and B rows appear to be rare values – what benefit is there in having an index that covers the other values (unless 2 of the remaining 3 are also rare). How about creating a function-based index that represents only the rare values and modifying this code to use that index – e.g.
create index t1_id on t1 (
case sts when 'A' then sts when 'B' then sts end,
case sts when 'A' then dt when 'B' then dt end
) compress 1
;
select *
from t1
where case sts when 'A' then sts when 'B' then sts end in ('A','B')
and case sts when 'A' then dt when 'B' then dt end < sysdate
and cnt < '4'
and rownum <= 1
/
You might be able to replace a huge index (79M rows worth) with this small one (120K rows worth) unless there’s too much other code in the system that has to be adjusted or the sts column is actually the target of a referential integrity constraint; at worst you could add this index knowing that it’s generally not going to consume much in the way of extra space or processing resources and is going to save you a lot of work for this query.
Summary
The execution plan from SQL Monitor points very strongly to the fast system benefiting from having a lot of the relevant data cached and constantly being reloaded into the cache by other sessions while the slow system has to acquire almost all of its data by real phyiscal reads. Most of the reads address the table so engineering an index that is low-cost and (fairly) high precision is the most significant strategy for reducing the workload and time on the slow system.
The fact that all the potential A rows fail to match the full predicate set suggests that there MAY be some aspect of the processing that means it would be more efficient to check for B rows before checking for A rows.
Given the massive skew in the data distribution a function-based index that hides all the non-popular values (or even all the values that are not of interest to this query) may be the most cost-effective way of adding a very effective index to the table with minimal resource requirements.
And finally
It’s taken me more than 4 hours to write this note after spending about 10 minutes reading through the information supplied by the OP and identifying and cross-checking details. A small fraction of the 4+ hours was spent creating a little model to check something I had to say about in-lists, the rest of it was trying to write up a coherent description covering all the details.
That’s it for today, but I may have missed a couple of points that I noticed as I read the OP’s posting; and I will want to do a little cosmetic work on this article and check grammar and spelling over the next couple of days.
<h3<Update (already)
Shortly after I posted this blog note the owner of the question reported the following as the distribution of values for the sts column:
STS COUNT(*)
---- ----------
A 6
E 126
D 866
C 80212368
B 117631
Two things stand out about these figures – first it’s an ideal example of a case where it would be nice avoid having index entries for the 80 million ‘C’ rows. Depending on the coding and testing costs, the supportability of the application and the possible side effects this could be done with a function-based index, or by introducing a virtual column that hides the ‘C’s behing a NULL, or by changing the code to use NULL instead of ‘C’.
Secondly – I made a comment about rewriting the code to query the B’s before the A’s. But we saw that Oracle worked through about 117,000 rows before returning a result: so the fitures above tell us that it must have worked through almost all the B’s and the handful of A’s was just a tiny little blip before it got to the B iteration – so there’s no point in making that change.
My suggestion for the function-based index above could be modified in two ways, of course – add two more “when”s to each “case” to capture the D and E rows, or take the opposite viewpoint and create an index on expressions like: “case sts when ‘C’ then to_char(null) else sts end”. The benefit of the latter approach is that you don’t have to modify the index definition (and rebuild the index) if a new legal value for sts appears.
