db-derby-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Thomas Nielsen <Thomas.Niel...@Sun.COM>
Subject Re: Statement/PreparedStatement performance difference and problem
Date Tue, 08 Apr 2008 09:39:23 GMT
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

Mime
View raw message