Hi all,
In an attempt to investigate the problem I mentioned in my previous post, I
run additional tests and some interesting and weird results were appeared.
May be someone who has good knowledge of Derby's internal operation can give
some explanation. Any suggestion is welcomed. I describe what I have done:
Fresh Start of ij to ensure that no cache is used:
java -Dderby.language.maxMemoryPerTable=128
-Dderby.storage.pageCacheSize=4000 -Xms256m -Xmx256m -jar
$DERBY_HOME/lib/derbyrun.jar ij
prepare ps1 as 'select count(*) from ganest1.big inner join ganest1.bigref
on ganest1.big.id=ganest1.bigref.bigid and ganest1.big.id > 4000000 and
ganest1.big.id < 4100000';
ELAPSED TIME = 334 milliseconds
ij> execute ps1;
1
-----------
10128
1 row selected
ELAPSED TIME = 440 milliseconds
>From the query plan we can see that a nested loop join strategy is used and
it
opens 10128 index scans on the inner table. The situation looks similar to
the one
I described in my previous post, but the execution time is quite
satisfactory!
(milliseconds vs 20 seconds see below)
I attach the query plan at the end of the post. (in my previous post I
attached the DDL for the whole test)
After that I run the query (after restarting ij in an attempt to prevent
cache usage...):
prepare ps3 as 'select count(*) from ganest1.big where ganest1.big.name
like ''abc%'' ';
ij> ELAPSED TIME = 208 milliseconds
ij> execute ps3;
1
-----------
2540
1 row selected
ELAPSED TIME = 148 milliseconds
Again quite satisfactory time !!
And the problematic query:
prepare ps2 as 'select count(*) from ganest1.big inner join ganest1.bigref
on ganest1.big.id=ganest1.bigref.bigid and ganest1.big.name like ''abc%'' ';
ELAPSED TIME = 51 milliseconds
ij> execute ps2;
1
-----------
258
1 row selected
ELAPSED TIME = 18072 milliseconds
It takes 18 seconds !! ( I attach again the query plan)
=============== Query Plans ==============================
Statement Name:
null
Statement Text:
select count(*) from ganest1.big inner join ganest1.bigref on
ganest1.big.id=ganest1.bigref.bigid and ganest1.big.id > 4000000 and
ganest1.big.id < 4100000
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:
Project-Restrict ResultSet (6):
Number of opens = 1
Rows seen = 1
Rows filtered = 0
restriction = false
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: 1.00
optimizer estimated cost: 49737.71
Source result set:
Scalar Aggregate ResultSet:
Number of opens = 1
Rows input = 10128
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 10126.00
optimizer estimated cost: 49737.71
Index Key Optimization = false
Source result set:
Project-Restrict ResultSet (5):
Number of opens = 1
Rows seen = 10128
Rows filtered = 0
restriction = false
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: 10126.00
optimizer estimated cost: 49737.71
Source result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 10128
Rows seen from the right = 10128
Rows filtered = 0
Rows returned = 10128
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 10126.00
optimizer estimated cost: 49737.71
Left result set:
Index Scan ResultSet for BIGREF using
constraint SQL090522104305131 at
read committed isolation level using instantaneous share row locking chosen
by the optimizer
Number of opens = 1
Rows seen = 10128
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={0}
Number of columns fetched=1
Number of deleted rows visited=0
Number of pages visited=9
Number of rows qualified=10128
Number of rows visited=10129
Scan type=btree
Tree height=-1
start position:
> on first 1 column(s).
Ordered null semantics on the following columns:
0
stop position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
0
qualifiers:
None
optimizer estimated row count:
10126.00
optimizer estimated cost:
1998.68
Right result set:
Index Scan ResultSet for BIG using constraint
SQL090522104249720 at read
committed isolation level using share row locking chosen by the optimizer
Number of opens = 10128
Rows seen = 10128
Rows filtered = 0
Fetch Size = 1
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={0}
Number of columns fetched=1
Number of deleted rows visited=0
Number of pages visited=30384
Number of rows qualified=10128
Number of rows visited=10128
Scan type=btree
Tree height=3
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
0
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
0
qualifiers:
Column[0][0] Id: 0
Operator: <
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
Column[0][1] Id: 0
Operator: <=
Ordered nulls: false
Unknown return value: true
Negate comparison result: true
optimizer estimated row count:
10126.00
optimizer estimated cost:
47739.03
================================ query plan of the problematic query
===============
Statement Name:
null
Statement Text:
select count(*) from ganest1.big inner join ganest1.bigref on
ganest1.big.id=ganest1.bigref.bigid and ganest1.big.name like 'abc%'
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:
Project-Restrict ResultSet (7):
Number of opens = 1
Rows seen = 1
Rows filtered = 0
restriction = false
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: 1.00
optimizer estimated cost: 14540.85
Source result set:
Scalar Aggregate ResultSet:
Number of opens = 1
Rows input = 258
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 2662.25
optimizer estimated cost: 14540.85
Index Key Optimization = false
Source result set:
Project-Restrict ResultSet (6):
Number of opens = 1
Rows seen = 258
Rows filtered = 0
restriction = false
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: 2662.25
optimizer estimated cost: 14540.85
Source result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 2540
Rows seen from the right = 258
Rows filtered = 0
Rows returned = 258
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 2662.25
optimizer estimated cost: 14540.85
Left result set:
Index Row to Base Row ResultSet for BIG:
Number of opens = 1
Rows seen = 2540
Columns accessed from heap = {0, 2}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
2533.00
optimizer estimated cost:
6034.08
Index Scan ResultSet for BIG using
index BIGNAME1 at read committed
isolation level using instantaneous share row locking chosen by the
optimizer
Number of opens = 1
Rows seen = 2540
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=2
Number of deleted rows visited=0
Number of pages visited=10
Number of rows qualified=2540
Number of rows visited=2541
Scan type=btree
Tree height=-1
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
0
stop position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
0
qualifiers:
None
optimizer estimated row count:
2533.00
optimizer estimated cost:
6034.08
Right result set:
Index Scan ResultSet for BIGREF using
constraint SQL090522104305131 at
read committed isolation level using instantaneous share row locking chosen
by the optimizer
Number of opens = 2540
Rows seen = 258
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={0}
Number of columns fetched=1
Number of deleted rows visited=0
Number of pages visited=5081
Number of rows qualified=258
Number of rows visited=2798
Scan type=btree
Tree height=2
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
0
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
0
qualifiers:
None
optimizer estimated row count:
2662.25
optimizer estimated cost:
8506.77
==================================end of query plan
=============================
Knut Anders Hatlen wrote:
>
> ganest <[email protected]> writes:
>
>> I am executing using ij tool (java
>> -Dderby.language.maxMemoryPerTable=4096
>> -Xms256m -Xmx256m -jar $DERBY_HOME/lib/derbyrun.jar ij)
>> the following query: (I read about derby.language.maxMemoryPerTable in
>> this
>> mailing list)
>>
>> select count(*) from big inner join bigref on big.id=bigref.bigid and
>> big.name like '0ff%';
>>
>> The result is: 258 and it takes more than 20 seconds to be executed.
>> Using
>> mysql with the same
>> configuration the result is produced in milliseconds.
>
> For the record, I ran the code you provided on my machine, using only
> the default settings for Derby and the JVM, and I see that the query
> takes less than 150 ms:
>
> ij> elapsedtime on;
> ij> select count(*) from big inner join bigref on big.id=bigref.bigid and
> big.name like '0ff%';
> 1
> -----------
> 255
>
> 1 row selected
> ELAPSED TIME = 133 milliseconds
>
> This is with head of the Derby 10.5 branch, OpenSolaris 2009.06 snv_111a
> X86, and
>
> java version "1.6.0_13"
> Java(TM) SE Runtime Environment (build 1.6.0_13-b03)
> Java HotSpot(TM) Server VM (build 11.3-b02, mixed mode)
>
> The runtime statistics on my machine are almost identical to the ones
> you provided (some small differences in page count and row count due to
> the randomness of the code that populates the tables).
>
> --
> Knut Anders
>
>
-----
George Anestis
--
View this message in context:
http://www.nabble.com/Performance-Tuning-Problem---tp23652098p23703523.html
Sent from the Apache Derby Users mailing list archive at Nabble.com.
