db-derby-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From ganest <gan...@ced.tuc.gr>
Subject Re: Performance Tuning Problem ?
Date Mon, 25 May 2009 08:50:22 GMT

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 <ganest@ced.tuc.gr> 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.


Mime
View raw message