Return-Path: Delivered-To: apmail-db-derby-user-archive@www.apache.org Received: (qmail 91270 invoked from network); 25 May 2009 08:51:41 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 25 May 2009 08:51:41 -0000 Received: (qmail 15573 invoked by uid 500); 25 May 2009 08:50:54 -0000 Delivered-To: apmail-db-derby-user-archive@db.apache.org Received: (qmail 15534 invoked by uid 500); 25 May 2009 08:50:53 -0000 Mailing-List: contact derby-user-help@db.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: List-Id: Reply-To: "Derby Discussion" Delivered-To: mailing list derby-user@db.apache.org Received: (qmail 15521 invoked by uid 99); 25 May 2009 08:50:53 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 25 May 2009 08:50:53 +0000 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of lists@nabble.com designates 216.139.236.158 as permitted sender) Received: from [216.139.236.158] (HELO kuber.nabble.com) (216.139.236.158) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 25 May 2009 08:50:43 +0000 Received: from isper.nabble.com ([192.168.236.156]) by kuber.nabble.com with esmtp (Exim 4.63) (envelope-from ) id 1M8Vt0-0000zW-BJ for derby-user@db.apache.org; Mon, 25 May 2009 01:50:22 -0700 Message-ID: <23703523.post@talk.nabble.com> Date: Mon, 25 May 2009 01:50:22 -0700 (PDT) From: ganest To: derby-user@db.apache.org Subject: Re: Performance Tuning Problem ? In-Reply-To: MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit X-Nabble-From: ganest@ced.tuc.gr References: <23652098.post@talk.nabble.com> X-Virus-Checked: Checked by ClamAV on apache.org 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 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.