Hi,
I haven't looked at this in detail, but can you please confirm that the
following is correct:
1) The query you run in alt. 2 is not identical to alt 1 - there's an
extra AND in the WHERE clause, making it an illegal query. Is this just
a copy-paste blurp?
2) The alt. 2 output of "Statement text" isn't the SELECT but rather a
CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1). Is this correct? If so
are you comparing the timing of a SELECT to a CALL? Or am I missing
something?
As Knut said, the optimizer sometimes does make bad decisions...
Cheers,
Thomas
DerbyNovice wrote:
PROBLEM STATEMENT
---------------------------------
ALTERNATIVE 1 uses a PreparedStatement with parameters.
ALTERNATIVE 2 mimics a Statement (and indeed a Statement returns the
same performance)
...
ALTERNATIVE 1 >
>1 ps = conn.prepareStatement("SELECT * From SA.UDEVENTDATA WHERE
DomainKeyId = ? AND CreationTime < ? AND Name > ? ");
< END 1
...
ALTERNATIVE 1 >
>1 ps.setString(3,(String)s2);
>1 ps.setString(1,"d46chez0v8cdg-c4m");
>1 ps.setString(2,"1200269947000");
>1
< END 1
ALTERNATIVE 2 >
>2 String sels = "SELECT * From SA.UDEVENTDATA WHERE AND
DomainKeyId = 'd46chez0v8cdg-c4m' AND CreationTime < 1200269947000 AND Name
'"+s2+"' ";
>2 ps = conn.prepareStatement(sels);
< END 2
startStat();
beginTiming_ = java.lang.System.currentTimeMillis ();
rs = ps.executeQuery();
endTiming_ = java.lang.System.currentTimeMillis ();
elapsed = endTiming_ - beginTiming_;
System.out.println( "?#?#? SimpleApp2.java at line: 235 Dbg-out
variable elapsed SELECT ["+elapsed+"]" );
count = 0;
beginTiming_ = java.lang.System.currentTimeMillis ();
while(rs.next())
{
//do something with the result set
for( int i= 1; i <= cols ; i++)
{
Object o = getData((String)vclass.elementAt(i-1),
rs,
i);
} /* end of for i */
count++;
}
endTiming_ = java.lang.System.currentTimeMillis ();
printStat();
elapsed = endTiming_ - beginTiming_;
System.out.println( "LOOP NO "+j );
System.out.println( "?#?#? SimpleApp2.java at line: 235 Dbg-out
variable elapsed NEXT ["+elapsed+"]" );
System.out.println("Counted "+count+" in resultset");
}
OUPUT WITH ALTERNATIVE 1
------------------------
LOOP NO 0
?#?#? SimpleApp2.java at line: 235 Dbg-out variable elapsed NEXT [3092]
Counted 8 in resultset
?#?#? SimpleApp2.java at line: 235 Dbg-out variable elapsed SELECT [41]
Query Plan: Statement Name:
null
Statement Text:
SELECT * From SA.UDEVENTDATA WHERE DomainKeyId = ? AND
CreationTime < ? AND Name > ?
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: 3069
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : 2008-04-07 15:50:06.788
End Execution Timestamp : 2008-04-07 15:50:09.95
Statement Execution Plan Text:
Project-Restrict ResultSet (3):
Number of opens = 1
Rows seen = 46372
Rows filtered = 46364
restriction = true
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 1
next time (milliseconds) = 3068
close time (milliseconds) = 0
restriction time (milliseconds) = 117
projection time (milliseconds) = 0
optimizer estimated row count: 505.06
optimizer estimated cost: 56292.47
Source result set:
Index Row to Base Row ResultSet for UDEVENTDATA:
Number of opens = 1
Rows seen = 46372
Columns accessed from heap = {0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10,
11, 12, 13, 14, 15, 16, 17, 18, 19, 20}
constructor time (milliseconds) = 0
open time (milliseconds) = 1
next time (milliseconds) = 2751
close time (milliseconds) = 25
optimizer estimated row count: 505.06
optimizer estimated cost: 56292.47
Index Scan ResultSet for UDEVENTDATA using index
UDSOFTOBJECTDATA_DOMAINKEY_IDX_UDEVENTDATA at read committed isolation
level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 46372
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 3
next time (milliseconds) = 417
close time (milliseconds) = 25
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=1
Number of pages visited=424
Number of rows qualified=46372
Number of rows visited=46374
Scan type=btree
Tree height=3
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 505.06
optimizer estimated cost: 56292.47
OUPUT WITH ALTERNATIVE 2
------------------------
LOOP NO 0
?#?#? SimpleApp2.java at line: 235 Dbg-out variable elapsed NEXT [36]
Counted 8 in resultset
?#?#? SimpleApp2.java at line: 235 Dbg-out variable elapsed SELECT [0]
Query Plan: Statement Name:
null
Statement Text:
CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1)
Parse Time: 1
Bind Time: 0
Optimize Time: 0
Generate Time: 3
Compile Time: 4
Execute Time: -1207579584105
Begin Compilation Timestamp : 2008-04-07 15:46:24.1
End Compilation Timestamp : 2008-04-07 15:46:24.104
Begin Execution Timestamp : 2008-04-07 15:46:24.105
End Execution Timestamp : 2008-04-07 15:46:24.105
Statement Execution Plan Text:
null
QUESTION
--------
Why cannot the prepared statement figure out how to use the indices when
statements can, i.e. that domainkey should not be scanned ?
How can you make the prepared statement use the same execution plan as
the statement so as to return the same type of performance?
The problem seems to be Derby specific as MSQL returns adequate
performance for ALT 1.
Thanks in advance,
--
Thomas Nielsen
