On 09/02/2021 18:05, Rick Hillegas wrote:
As Bryan points out, please consult the Tuning Guide for information
on how to view your query plan. In any event, your descending index
is not a covering index. That is, it does not contain all of the
columns in your query. That may be what forces the optimizer to
choose a full table scan.
From "Tuning Derby"
(https://db.apache.org/derby/docs/10.8/tuning/ctunoptimz56859.html):
Usually, sorting requires an extra step to put the data into the right
order. This extra step can be avoided for data that are already in the
right order. For example, if a single-table query has an ORDER BY on a
single column, and there is an index on that column, sorting can be
avoided if Derby uses the index as the access path.
This seems to be my situation: I am selecting from (a view into) a
single table with an ORDER BY on a single column, and there is an
index on that column.
The timing I reported earlier (using your suggested nested query)
prompted me to investigate further. I executed it with runtime
statistics enabled, and below is what was reported. I cannot make head
nor tail of what is happening here, but it looks incredibly complicated.
Statement Name:
null
Statement Text:
SELECT time as t_time,
facility,event,details,name,username,sector,item
FROM system_log
WHERE id IN
(
SELECT id
FROM system_log
ORDER BY time DESC
NULLS LAST
FETCH NEXT 20 ROWS ONLY
)
ORDER BY t_time
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: 0
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : null
End Execution Timestamp : null
Statement Execution Plan Text:
Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 20
Number of reads from hash table = 20
Number of writes to hash table = 20
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 261251.00
optimizer estimated cost: 268953.12
Source result set:
Sort ResultSet:
Number of opens = 1
Rows input = 20
Rows returned = 20
Eliminate duplicates = false
In sorted order = false
Sort information:
Number of merge runs=1
Number of rows input=20
Number of rows output=20
Size of merge runs=[14]
Sort type=external
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 261251.00
optimizer estimated cost: 268953.12
Source result set:
Attached subqueries:
Begin Subquery Number 0
Any ResultSet (Attached to 2):
Number of opens = 261296
Rows seen = 261296
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 68252085001.00
optimizer estimated cost: 70264271553.12
Source result set:
Project-Restrict ResultSet (7):
Number of opens = 261296
Rows seen = 5225730
Rows filtered = 5225710
restriction = true
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 68252085001.00
optimizer estimated cost: 70264271553.12
Source result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 4964453
Rows seen from the right = 261277
Rows returned = 5225730
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 20.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 4703175
Rows seen from the right = 261278
Rows returned = 4964453
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 19.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 4441896
Rows seen from the right = 261279
Rows returned = 4703175
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 18.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 4180616
Rows seen from the right = 261280
Rows returned = 4441896
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 17.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 3919335
Rows seen from the right = 261281
Rows returned = 4180616
constructor time
(milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
16.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 3658053
Rows seen from the right = 261282
Rows returned = 3919335
constructor time
(milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row
count: 15.00
optimizer estimated cost:
0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left =
3396770
Rows seen from the right =
261283
Rows returned = 3658053
constructor time
(milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer estimated
row count: 14.00
optimizer estimated
cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the
left = 3135486
Rows seen from the
right = 261284
Rows returned = 3396770
constructor time
(milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 13.00
optimizer
estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens =
261296
Rows seen from the
left = 2874201
Rows seen from the
right = 261285
Rows returned =
3135486
constructor time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 12.00
optimizer
estimated cost: 0.00
Left result set:
Union ResultSet:
Number of
opens = 261296
Rows seen from
the left = 2612915
Rows seen from
the right = 261286
Rows returned
= 2874201
constructor time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer estimated row count: 11.00
optimizer estimated cost: 0.00
Left result set:
Union
ResultSet:
Number of
opens = 261296
Rows seen
from the left = 2351628
Rows seen
from the right = 261287
Rows
returned = 2612915
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 10.00
optimizer estimated cost: 0.00
Left
result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 2090340
Rows seen from the right = 261288
Rows returned = 2351628
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 9.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 1829051
Rows seen from the right = 261289
Rows returned = 2090340
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 8.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 1567761
Rows seen from the right = 261290
Rows returned = 1829051
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 7.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 1306470
Rows seen from the right = 261291
Rows returned = 1567761
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 6.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 1045178
Rows seen from the right = 261292
Rows returned = 1306470
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 5.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 783885
Rows seen from the right = 261293
Rows returned = 1045178
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 4.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 522591
Rows seen from the right = 261294
Rows returned = 783885
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 3.00
optimizer estimated cost: 0.00
Left result set:
Union ResultSet:
Number of opens = 261296
Rows seen from the left = 261296
Rows seen from the right = 261295
Rows returned = 522591
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 2.00
optimizer estimated cost: 0.00
Left result set:
Row ResultSet:
Number of opens = 261296
Rows returned = 261296
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261295
Rows returned = 261295
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261294
Rows returned = 261294
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261293
Rows returned = 261293
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261292
Rows returned = 261292
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261291
Rows returned = 261291
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261290
Rows returned = 261290
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261289
Rows returned = 261289
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261288
Rows returned = 261288
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right
result set:
Row ResultSet:
Number of opens = 261287
Rows returned = 261287
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row
ResultSet:
Number of
opens = 261286
Rows
returned = 261286
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of
opens = 261285
Rows returned
= 261285
constructor time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens =
261284
Rows returned =
261284
constructor time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 1.00
optimizer
estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261283
Rows returned = 261283
constructor time
(milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 1.00
optimizer
estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261282
Rows returned = 261282
constructor time
(milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer estimated
row count: 1.00
optimizer estimated
cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261281
Rows returned = 261281
constructor time
(milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row
count: 1.00
optimizer estimated cost:
0.00
Right result set:
Row ResultSet:
Number of opens = 261280
Rows returned = 261280
constructor time
(milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261279
Rows returned = 261279
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261278
Rows returned = 261278
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
Right result set:
Row ResultSet:
Number of opens = 261277
Rows returned = 261277
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1.00
optimizer estimated cost: 0.00
End Subquery Number 0
Project-Restrict ResultSet (2):
Number of opens = 1
Rows seen = 261296
Rows filtered = 261276
restriction = true
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 261251.00
optimizer estimated cost: 268953.12
Source result set:
Table Scan ResultSet for SYSTEM_LOG at read uncommitted
isolation level using share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 261296
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=9
Number of pages visited=1791
Number of rows qualified=261296
Number of rows visited=261482
Scan type=heap
start position:
null
stop position:
null
qualifiers:
None
optimizer estimated row count: 261251.00
optimizer estimated cost: 268953.12
