Mailing-List: contact derby-user-help@db.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Derby Discussion" <derby-user@db.apache.org>
Received-SPF: pass (athena.apache.org: domain of lists@nabble.com designates
 216.139.236.158 as permitted sender)
Message-ID: <16537511.post@talk.nabble.com>
Date: Mon, 7 Apr 2008 08:34:34 -0700 (PDT)
From: DerbyNovice <clarsson@ureason.com>
To: derby-user@db.apache.org
Subject: Statement/PreparedStatement performance difference and problem
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Transfer-Encoding: 7bit


Why is the prepared statement slower than the  unprepared statement?


BACKGROUND
----------
DB as follows:

CREATE TABLE "SA"."UDEVENTDATA"
(
                                 "ID" VARCHAR(100) NOT NULL,
                                 "DOMAINKEYID" VARCHAR(100),
                                 "CREATIONTIME" BIGINT NOT NULL,
                                 "NAME" VARCHAR(32672),
                                *** AND MORE COLUMNS NOT USED IN THIS
EXAMPLE ****
 );

with indices :

CREATE INDEX "SA"."UDSOFTOBJECTDATA_CREATIONTIME_IDX_UDEVENTDATA" ON 
"SA"."UDEVENTDATA" ("CREATIONTIME");
CREATE INDEX "SA"."UDSOFTOBJECTDATA_DOMAINKEY_IDX_UDEVENTDATA" ON 
"SA"."UDEVENTDATA" ("DOMAINKEYID");
CREATE INDEX "SA"."UDSOFTOBJECTDATA_NAME_IDX_UDEVENTDATA" ON 
"SA"."UDEVENTDATA" ("NAME");

and runs as embedded.
DB contains 46000 records with the following properties

DOMAINKEY are 98% same.
NAMEs are all different.
CREATIONTIME 82% different.

PROBLEM STATEMENT
---------------------------------
ALTERNATIVE 1 uses a PreparedStatement with parameters.
ALTERNATIVE 2 mimics a Statement (and indeed a Statement returns the 
same performance)
PreparedStatements (ALTERNATIVE 1) are VERY SLOW because of table scans 
BUT Statements (ALTERNATIVE 2) are QUICK.
This can be seen in the NEXT and SELECT debug statements in the output
section.

JAVA CODE
---------
                Vector rsv containing Names from the table column NAME.

        PreparedStatement ps;

ALTERNATIVE 1 >
 >1        ps = conn.prepareStatement("SELECT * From SA.UDEVENTDATA  WHERE
DomainKeyId = ? AND CreationTime <  ? AND Name  > ? ");
< END 1
        zize = 10;
        beginTiming_ = java.lang.System.currentTimeMillis ();
        for( int j=0;j<zize;j++ )
            {
            String s2 = (String)rsv.elementAt(j) ;
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,


-- 
View this message in context: http://www.nabble.com/Statement-PreparedStatement-performance-difference-and-problem-tp16537511p16537511.html
Sent from the Apache Derby Users mailing list archive at Nabble.com.