Return-Path: X-Original-To: apmail-db-derby-dev-archive@www.apache.org Delivered-To: apmail-db-derby-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 12948E75B for ; Tue, 26 Feb 2013 22:40:13 +0000 (UTC) Received: (qmail 40749 invoked by uid 500); 26 Feb 2013 22:40:12 -0000 Delivered-To: apmail-db-derby-dev-archive@db.apache.org Received: (qmail 40734 invoked by uid 500); 26 Feb 2013 22:40:12 -0000 Mailing-List: contact derby-dev-help@db.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: Delivered-To: mailing list derby-dev@db.apache.org Received: (qmail 40726 invoked by uid 99); 26 Feb 2013 22:40:12 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 26 Feb 2013 22:40:12 +0000 Date: Tue, 26 Feb 2013 22:40:12 +0000 (UTC) From: "Tony Brusseau (JIRA)" To: derby-dev@db.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (DERBY-6093) dramatically worse query plan for prepared stamement vs calling directly MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 Tony Brusseau created DERBY-6093: ------------------------------------ Summary: dramatically worse query plan for prepared stamement vs calling directly Key: DERBY-6093 URL: https://issues.apache.org/jira/browse/DERBY-6093 Project: Derby Issue Type: Bug Components: Store Affects Versions: 10.9.1.0 Environment: Linux Reporter: Tony Brusseau If I run a count query given all the parameters directly, then the query executes in .05s, however, if I send it across as a prepared statement, then the query takes 40s to run (because is does a complete table scan on a table with 15m rows). The query looks like: SELECT COUNT(*) FROM KB.FORMULA_ENTRIES fe1, KB.FORMULA_ENTRIES fe2 WHERE (fe1.arg_0_term = 1407374883620920) AND (fe1.arg_num = 1) AND (fe1.arg_term = 1407374883574780) AND (fe1.formula_type = 0) AND (fe1.formula_id = fe2.formula_id) AND (fe2.arg_0_term = 1407374883620920) AND (fe2.arg_num = 2) AND (fe2.arg_term = 1407374883663337) AND (fe2.formula_type = 0) or the prepared version like: SELECT COUNT(*) FROM KB.FORMULA_ENTRIES fe1 , KB.FORMULA_ENTRIES fe2 WHERE (fe1.arg_0_term = ?) AND (fe1.arg_num = ?) AND (fe1.arg_term = ?) AND (fe1.formula_type = ?) AND (fe1.formula_id = fe2.formula_id) AND (fe2.arg_0_term = ?) AND (fe2.arg_num = ?) AND (fe2.arg_term = ?) AND (fe2.formula_type = ?) The table is defined as: DROP TABLE KB.FORMULA_ENTRIES; CREATE TABLE KB.FORMULA_ENTRIES ( formula_entries_id BIGINT NOT NULL,) formula_id BIGINT NOT NULL, arg_0_term BIGINT NOT NULL, arg_term BIGINT NOT NULL, arg_num INTEGER NOT NULL, formula_type SMALLINT NOT NULL ); ALTER TABLE kb.formula_entries ADD CONSTRAINT kb_formula_entries_pk PRIMARY KEY (formula_entries_id); ALTER TABLE kb.formula_entries ADD CONSTRAINT kb_fomula_entries_formula_id_fk FOREIGN KEY (formula_id) REFERENCES kb.formula_term (term_id) ON DELETE CASCADE; CREATE INDEX kb_formula_entries_formula_term_type ON kb.formula_entries (arg_term, formula_type); CREATE INDEX kb_formula_entries_formula_term_arg0_type ON kb.formula_entries (arg_term, arg_0_term, formula_type); CREATE INDEX kb_formula_entries_formula_term_num_type ON kb.formula_entries (arg_term, arg_num, formula_type); CREATE INDEX kb_formula_entries_formula_term_arg0_num_type ON kb.formula_entries (arg_term, arg_0_term, arg_num, formula_type); The good query plan looks (when *not* sent as a prepared statements) looks like: Tue Feb 26 16:15:21 CST 2013 Thread[DRDAConnThread_5,5,main] (XID = 40971291), (SESSIONID = 7), SELECT COUNT(*) FROM KB.FORMULA_ENTRIES fe1, KB.FORMULA_ENTRIES fe2 WHERE (fe1.arg_0_term = 1407374883620920) AND (fe1.arg_num = 1) AND (fe1.arg_term = 1407374883574780) AND (fe1.formula_type = 0) AND (fe1.formula_id = fe2.formula_id) AND (fe2.arg_0_term = 1407374883620920) AND (fe2.arg_num = 2) AND (fe2.arg_term = 1407374883663337) AND (fe2.formula_type = 0) ******* Project-Restrict ResultSet (10): 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: 7184.99 Source result set: Scalar Aggregate ResultSet: Number of opens = 1 Rows input = 3863 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.00 optimizer estimated cost: 7184.99 Index Key Optimization = false Source result set: Project-Restrict ResultSet (9): Number of opens = 1 Rows seen = 3863 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: 0.00 optimizer estimated cost: 7184.99 Source result set: Nested Loop Join ResultSet: Number of opens = 1 Rows seen from the left = 3863 Rows seen from the right = 3863 Rows filtered = 0 Rows returned = 3863 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.00 optimizer estimated cost: 7184.99 Left result set: Project-Restrict ResultSet (5): Number of opens = 1 Rows seen = 3865 Rows filtered = 2 restriction = true 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: 35.89 optimizer estimated cost: 6785.98 Source result set: Index Row to Base Row ResultSet for FORMULA_ENTRIES: Number of opens = 1 Rows seen = 3865 Columns accessed from heap = {1, 2, 3, 4, 5} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 35.89 optimizer estimated cost: 6785.98 Index Scan ResultSet for FORMULA_ENTRIES using index KB_FORMULA_ENTRIES_FORMULA_TERM_TYPE at read committed isolation level using instantaneous share row locking chosen by the optimizer Number of opens = 1 Rows seen = 3865 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=3 Number of deleted rows visited=0 Number of pages visited=7 Number of rows qualified=3865 Number of rows visited=3866 Scan type=btree Tree height=3 start position: >= on first 2 column(s). Ordered null semantics on the following columns: 0 1 stop position: > on first 2 column(s). Ordered null semantics on the following columns: 0 1 qualifiers: None optimizer estimated row count: 35.89 optimizer estimated cost: 6785.98 Right result set: Project-Restrict ResultSet (8): Number of opens = 3863 Rows seen = 15452 Rows filtered = 11589 restriction = true 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: 0.00 optimizer estimated cost: 399.01 Source result set: Index Row to Base Row ResultSet for FORMULA_ENTRIES: Number of opens = 3863 Rows seen = 15452 Columns accessed from heap = {1, 2, 3, 4, 5} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.00 optimizer estimated cost: 399.01 Index Scan ResultSet for FORMULA_ENTRIES using constraint KB_FOMULA_ENTRIES_FORMULA_ID_FK at read committed isolation level using instantaneous share row locking chosen by the optimizer Number of opens = 3863 Rows seen = 15452 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=11606 Number of rows qualified=15452 Number of rows visited=19315 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: None optimizer estimated row count: 0.00 optimizer estimated cost: 399.01 The bad query plan looks (when sent as a prepared statements) looks like: Tue Feb 26 16:09:35 CST 2013 Thread[DRDAConnThread_4,5,main] (XID = 40971265), (SESSIONID = 5), SELECT COUNT(*) FROM KB.FORMULA_ENTRIES fe1 , KB.FORMULA_ENTRIES fe2 WHERE (fe1.arg_0_term = ?) AND (fe1.arg_num = ?) AND (fe1.arg_term = ?) AND (fe1.formula_type = ?) AND (fe1.formula_id = fe2.formula_id) AND (fe2.arg_0_term = ?) AND (fe2.arg_num = ?) AND (fe2.arg_term = ?) AND (fe2.formula_type = ?) ******* Project-Restrict ResultSet (9): 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: 43.36 Source result set: Scalar Aggregate ResultSet: Number of opens = 1 Rows input = 3863 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.00 optimizer estimated cost: 43.36 Index Key Optimization = false Source result set: Project-Restrict ResultSet (8): Number of opens = 1 Rows seen = 3863 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: 0.00 optimizer estimated cost: 43.36 Source result set: Nested Loop Join ResultSet: Number of opens = 1 Rows seen from the left = 3863 Rows seen from the right = 3863 Rows filtered = 0 Rows returned = 3863 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.00 optimizer estimated cost: 43.36 Left result set: Index Row to Base Row ResultSet for FORMULA_ENTRIES: Number of opens = 1 Rows seen = 3863 Columns accessed from heap = {1, 2, 3, 4, 5} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 2.98 optimizer estimated cost: 10.89 Index Scan ResultSet for FORMULA_ENTRIES using index KB_FORMULA_ENTRIES_FORMULA_TERM_ARG0_NUM_TYPE at read committed isolation level using instantaneous share row locking chosen by the optimizer Number of opens = 1 Rows seen = 3863 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=5 Number of deleted rows visited=0 Number of pages visited=8 Number of rows qualified=3863 Number of rows visited=3864 Scan type=btree Tree height=3 start position: >= on first 4 column(s). Ordered null semantics on the following columns: stop position: > on first 4 column(s). Ordered null semantics on the following columns: qualifiers: None optimizer estimated row count: 2.98 optimizer estimated cost: 10.89 Right result set: Project-Restrict ResultSet (7): Number of opens = 3863 Rows seen = 14922769 Rows filtered = 14918906 restriction = true 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: 0.00 optimizer estimated cost: 32.47 Source result set: Index Row to Base Row ResultSet for FORMULA_ENTRIES: Number of opens = 3863 Rows seen = 14922769 Columns accessed from heap = {1, 2, 3, 4, 5} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.00 optimizer estimated cost: 32.47 Index Scan ResultSet for FORMULA_ENTRIES using index KB_FORMULA_ENTRIES_FORMULA_TERM_ARG0_NUM_TYPE at read committed isolation level using instantaneous share row locking chosen by the optimizer Number of opens = 3863 Rows seen = 14922769 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=5 Number of deleted rows visited=0 Number of pages visited=34767 Number of rows qualified=14922769 Number of rows visited=14926632 Scan type=btree Tree height=3 start position: >= on first 4 column(s). Ordered null semantics on the following columns: stop position: > on first 4 column(s). Ordered null semantics on the following columns: qualifiers: None optimizer estimated row count: 0.00 optimizer estimated cost: 32.47 -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira