You are viewing a plain text version of this content. The canonical link for it is here.
Posted to derby-dev@db.apache.org by "Chris Wilson (JIRA)" <ji...@apache.org> on 2011/01/13 18:15:46 UTC
[jira] Created: (DERBY-4971) Query runs 10 times more slowly with
optimizer turned ON
Query runs 10 times more slowly with optimizer turned ON
--------------------------------------------------------
Key: DERBY-4971
URL: https://issues.apache.org/jira/browse/DERBY-4971
Project: Derby
Issue Type: Bug
Components: SQL
Affects Versions: 10.7.1.1
Reporter: Chris Wilson
Derby takes 10 times as long to execute the attached query on the attached database when the optimizer is allowed to choose its own join order.
chris@fen-desktop2(tmp)$ cat ij
#!/bin/sh
DERBY_DIR=/home/chris/.m2/repository/org/apache/derby
DERBY_VER=10.7.1.1
DERBY_JAR=$DERBY_DIR/derby/$DERBY_VER/derby-$DERBY_VER.jar
TOOLS_JAR=$DERBY_DIR/derbytools/$DERBY_VER/derbytools-$DERBY_VER.jar
java -cp $DERBY_JAR:$TOOLS_JAR $OPTIONS org.apache.derby.tools.ij "$@"
chris@fen-desktop2(tmp)$ time ./ij optimizer-on.sql
ij version 10.7
ij> connect 'jdbc:derby:;databaseName=/tmp/rita.derby;user=rita';
ij> SELECT journey.transport_company AS journey_transport_provider, ...
1 row selected
ij> quit;
real 0m47.459s
user 0m47.067s
sys 0m0.344s
chris@fen-desktop2(tmp)$ time ./ij optimizer-off.sql
...
real 0m3.913s
user 0m4.100s
sys 0m0.148s
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (DERBY-4971) Query runs 10 times more slowly with
optimizer turned ON
Posted by "Chris Wilson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DERBY-4971?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12981707#action_12981707 ]
Chris Wilson commented on DERBY-4971:
-------------------------------------
Updating statistics resulted in a 20% improvement, but it's still 10 times slower:
chris@fen-desktop2(tmp)$ time ij optimizer-on.sql
...
real 0m40.485s
user 0m41.143s
sys 0m0.244s
> Query runs 10 times more slowly with optimizer turned ON
> --------------------------------------------------------
>
> Key: DERBY-4971
> URL: https://issues.apache.org/jira/browse/DERBY-4971
> Project: Derby
> Issue Type: Bug
> Components: SQL
> Affects Versions: 10.7.1.1
> Reporter: Chris Wilson
> Attachments: optimizer-off.sql, optimizer-on.sql, rita.derby.zip
>
>
> Derby takes 10 times as long to execute the attached query on the attached database when the optimizer is allowed to choose its own join order.
> chris@fen-desktop2(tmp)$ cat ij
> #!/bin/sh
> DERBY_DIR=/home/chris/.m2/repository/org/apache/derby
> DERBY_VER=10.7.1.1
> DERBY_JAR=$DERBY_DIR/derby/$DERBY_VER/derby-$DERBY_VER.jar
> TOOLS_JAR=$DERBY_DIR/derbytools/$DERBY_VER/derbytools-$DERBY_VER.jar
> java -cp $DERBY_JAR:$TOOLS_JAR $OPTIONS org.apache.derby.tools.ij "$@"
> chris@fen-desktop2(tmp)$ time ./ij optimizer-on.sql
> ij version 10.7
> ij> connect 'jdbc:derby:;databaseName=/tmp/rita.derby;user=rita';
> ij> SELECT journey.transport_company AS journey_transport_provider, ...
> 1 row selected
> ij> quit;
> real 0m47.459s
> user 0m47.067s
> sys 0m0.344s
> chris@fen-desktop2(tmp)$ time ./ij optimizer-off.sql
> ...
> real 0m3.913s
> user 0m4.100s
> sys 0m0.148s
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (DERBY-4971) Query runs 10 times more slowly with
optimizer turned ON
Posted by "Knut Anders Hatlen (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DERBY-4971?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12981763#action_12981763 ]
Knut Anders Hatlen commented on DERBY-4971:
-------------------------------------------
With 12 tables being joined, there are 12! == 479,001,600 possible join orders, so it's not completely unreasonable that it takes longer when the optimizer must pick the join order itself. There is a timeout mechanism to prevent the optimizer from spending a ridiculous amount of time trying to improve a plan that's most likely good enough, but because of bugs like DERBY-1905 it doesn't always work properly.
It may look like something similar to DERBY-1905 is what comes into play here. The cost estimates do indeed look inflated. The estimated cost for the chosen query plans is ~44 seconds, which fits well with the 45 seconds spent preparing the statement (the optimizer times out when it finds a plan whose estimated cost is smaller than the amount of time it took to find the plan). If the estimated cost had been closer to the actual cost (less than a second), the optimizer would probably have timed out and returned a plan much earlier.
> Query runs 10 times more slowly with optimizer turned ON
> --------------------------------------------------------
>
> Key: DERBY-4971
> URL: https://issues.apache.org/jira/browse/DERBY-4971
> Project: Derby
> Issue Type: Bug
> Components: SQL
> Affects Versions: 10.7.1.1
> Reporter: Chris Wilson
> Attachments: optimizer-off.sql, optimizer-on.sql, rita.derby.zip
>
>
> Derby takes 10 times as long to execute the attached query on the attached database when the optimizer is allowed to choose its own join order.
> chris@fen-desktop2(tmp)$ cat ij
> #!/bin/sh
> DERBY_DIR=/home/chris/.m2/repository/org/apache/derby
> DERBY_VER=10.7.1.1
> DERBY_JAR=$DERBY_DIR/derby/$DERBY_VER/derby-$DERBY_VER.jar
> TOOLS_JAR=$DERBY_DIR/derbytools/$DERBY_VER/derbytools-$DERBY_VER.jar
> java -cp $DERBY_JAR:$TOOLS_JAR $OPTIONS org.apache.derby.tools.ij "$@"
> chris@fen-desktop2(tmp)$ time ./ij optimizer-on.sql
> ij version 10.7
> ij> connect 'jdbc:derby:;databaseName=/tmp/rita.derby;user=rita';
> ij> SELECT journey.transport_company AS journey_transport_provider, ...
> 1 row selected
> ij> quit;
> real 0m47.459s
> user 0m47.067s
> sys 0m0.344s
> chris@fen-desktop2(tmp)$ time ./ij optimizer-off.sql
> ...
> real 0m3.913s
> user 0m4.100s
> sys 0m0.148s
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (DERBY-4971) Query runs 10 times more slowly with
optimizer turned ON
Posted by "Chris Wilson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DERBY-4971?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Chris Wilson updated DERBY-4971:
--------------------------------
Attachment: optimizer-off.sql
optimizer-on.sql
rita.derby.zip
Database and SQL script to reproduce.
> Query runs 10 times more slowly with optimizer turned ON
> --------------------------------------------------------
>
> Key: DERBY-4971
> URL: https://issues.apache.org/jira/browse/DERBY-4971
> Project: Derby
> Issue Type: Bug
> Components: SQL
> Affects Versions: 10.7.1.1
> Reporter: Chris Wilson
> Attachments: optimizer-off.sql, optimizer-on.sql, rita.derby.zip
>
>
> Derby takes 10 times as long to execute the attached query on the attached database when the optimizer is allowed to choose its own join order.
> chris@fen-desktop2(tmp)$ cat ij
> #!/bin/sh
> DERBY_DIR=/home/chris/.m2/repository/org/apache/derby
> DERBY_VER=10.7.1.1
> DERBY_JAR=$DERBY_DIR/derby/$DERBY_VER/derby-$DERBY_VER.jar
> TOOLS_JAR=$DERBY_DIR/derbytools/$DERBY_VER/derbytools-$DERBY_VER.jar
> java -cp $DERBY_JAR:$TOOLS_JAR $OPTIONS org.apache.derby.tools.ij "$@"
> chris@fen-desktop2(tmp)$ time ./ij optimizer-on.sql
> ij version 10.7
> ij> connect 'jdbc:derby:;databaseName=/tmp/rita.derby;user=rita';
> ij> SELECT journey.transport_company AS journey_transport_provider, ...
> 1 row selected
> ij> quit;
> real 0m47.459s
> user 0m47.067s
> sys 0m0.344s
> chris@fen-desktop2(tmp)$ time ./ij optimizer-off.sql
> ...
> real 0m3.913s
> user 0m4.100s
> sys 0m0.148s
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (DERBY-4971) Query runs 10 times more slowly with
optimizer turned ON
Posted by "Dag H. Wanvik (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DERBY-4971?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Dag H. Wanvik updated DERBY-4971:
---------------------------------
Urgency: Normal
Bug behavior facts: [Performance, Seen in production] (was: [Performance])
Labels: derby_triage10_8 (was: )
> Query runs 10 times more slowly with optimizer turned ON
> --------------------------------------------------------
>
> Key: DERBY-4971
> URL: https://issues.apache.org/jira/browse/DERBY-4971
> Project: Derby
> Issue Type: Bug
> Components: SQL
> Affects Versions: 10.7.1.1
> Reporter: Chris Wilson
> Labels: derby_triage10_8
> Attachments: optimizer-off.sql, optimizer-on.sql, rita.derby.zip
>
>
> Derby takes 10 times as long to execute the attached query on the attached database when the optimizer is allowed to choose its own join order.
> chris@fen-desktop2(tmp)$ cat ij
> #!/bin/sh
> DERBY_DIR=/home/chris/.m2/repository/org/apache/derby
> DERBY_VER=10.7.1.1
> DERBY_JAR=$DERBY_DIR/derby/$DERBY_VER/derby-$DERBY_VER.jar
> TOOLS_JAR=$DERBY_DIR/derbytools/$DERBY_VER/derbytools-$DERBY_VER.jar
> java -cp $DERBY_JAR:$TOOLS_JAR $OPTIONS org.apache.derby.tools.ij "$@"
> chris@fen-desktop2(tmp)$ time ./ij optimizer-on.sql
> ij version 10.7
> ij> connect 'jdbc:derby:;databaseName=/tmp/rita.derby;user=rita';
> ij> SELECT journey.transport_company AS journey_transport_provider, ...
> 1 row selected
> ij> quit;
> real 0m47.459s
> user 0m47.067s
> sys 0m0.344s
> chris@fen-desktop2(tmp)$ time ./ij optimizer-off.sql
> ...
> real 0m3.913s
> user 0m4.100s
> sys 0m0.148s
--
This message is automatically generated by JIRA.
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] Commented: (DERBY-4971) Query runs 10 times more slowly with
optimizer turned ON
Posted by "Knut Anders Hatlen (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DERBY-4971?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12981755#action_12981755 ]
Knut Anders Hatlen commented on DERBY-4971:
-------------------------------------------
It looks like the problem here is that the optimizer is slow, not that it picks a bad plan. Most of the time is spent preparing the statement. The time spent executing it (or re-executing an already prepared statement) is similar for the two:
When optimizer chooses join order:
ij version 10.7
ij> connect 'jdbc:derby:rita.derby;user=rita';
ij> elapsedtime on;
ij> prepare ps as '
SELECT journey.transport_company AS journey_transport_provider,
(...)
FROM
movement AS dispatched
(...)
ELAPSED TIME = 45034 milliseconds
ij> execute ps;
(...)
1 row selected
ELAPSED TIME = 2084 milliseconds
ij> execute ps;
(...)
1 row selected
ELAPSED TIME = 693 milliseconds
ij> execute ps;
(...)
1 row selected
ELAPSED TIME = 353 milliseconds
Fixed join order:
ij version 10.7
ij> connect 'jdbc:derby:rita.derby;user=rita';
ij> elapsedtime on;
ij> prepare ps as '
SELECT journey.transport_company AS journey_transport_provider,
(...)
FROM -- DERBY-PROPERTIES joinOrder = FIXED
movement AS dispatched
(...)
ELAPSED TIME = 3684 milliseconds
ij> execute ps;
(...)
1 row selected
ELAPSED TIME = 2325 milliseconds
ij> execute ps;
(...)
1 row selected
ELAPSED TIME = 485 milliseconds
ij> execute ps;
(...)
1 row selected
ELAPSED TIME = 380 milliseconds
(...)
1 row selected
ELAPSED TIME = 291 milliseconds
> Query runs 10 times more slowly with optimizer turned ON
> --------------------------------------------------------
>
> Key: DERBY-4971
> URL: https://issues.apache.org/jira/browse/DERBY-4971
> Project: Derby
> Issue Type: Bug
> Components: SQL
> Affects Versions: 10.7.1.1
> Reporter: Chris Wilson
> Attachments: optimizer-off.sql, optimizer-on.sql, rita.derby.zip
>
>
> Derby takes 10 times as long to execute the attached query on the attached database when the optimizer is allowed to choose its own join order.
> chris@fen-desktop2(tmp)$ cat ij
> #!/bin/sh
> DERBY_DIR=/home/chris/.m2/repository/org/apache/derby
> DERBY_VER=10.7.1.1
> DERBY_JAR=$DERBY_DIR/derby/$DERBY_VER/derby-$DERBY_VER.jar
> TOOLS_JAR=$DERBY_DIR/derbytools/$DERBY_VER/derbytools-$DERBY_VER.jar
> java -cp $DERBY_JAR:$TOOLS_JAR $OPTIONS org.apache.derby.tools.ij "$@"
> chris@fen-desktop2(tmp)$ time ./ij optimizer-on.sql
> ij version 10.7
> ij> connect 'jdbc:derby:;databaseName=/tmp/rita.derby;user=rita';
> ij> SELECT journey.transport_company AS journey_transport_provider, ...
> 1 row selected
> ij> quit;
> real 0m47.459s
> user 0m47.067s
> sys 0m0.344s
> chris@fen-desktop2(tmp)$ time ./ij optimizer-off.sql
> ...
> real 0m3.913s
> user 0m4.100s
> sys 0m0.148s
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (DERBY-4971) Query runs 10 times more slowly with
optimizer turned ON
Posted by "Dag H. Wanvik (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DERBY-4971?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12981470#action_12981470 ]
Dag H. Wanvik commented on DERBY-4971:
--------------------------------------
Does it make a difference if you update the statistics?
Cf. http://db.apache.org/derby/docs/10.7/ref/rrefupdatestatsproc.html
> Query runs 10 times more slowly with optimizer turned ON
> --------------------------------------------------------
>
> Key: DERBY-4971
> URL: https://issues.apache.org/jira/browse/DERBY-4971
> Project: Derby
> Issue Type: Bug
> Components: SQL
> Affects Versions: 10.7.1.1
> Reporter: Chris Wilson
> Attachments: optimizer-off.sql, optimizer-on.sql, rita.derby.zip
>
>
> Derby takes 10 times as long to execute the attached query on the attached database when the optimizer is allowed to choose its own join order.
> chris@fen-desktop2(tmp)$ cat ij
> #!/bin/sh
> DERBY_DIR=/home/chris/.m2/repository/org/apache/derby
> DERBY_VER=10.7.1.1
> DERBY_JAR=$DERBY_DIR/derby/$DERBY_VER/derby-$DERBY_VER.jar
> TOOLS_JAR=$DERBY_DIR/derbytools/$DERBY_VER/derbytools-$DERBY_VER.jar
> java -cp $DERBY_JAR:$TOOLS_JAR $OPTIONS org.apache.derby.tools.ij "$@"
> chris@fen-desktop2(tmp)$ time ./ij optimizer-on.sql
> ij version 10.7
> ij> connect 'jdbc:derby:;databaseName=/tmp/rita.derby;user=rita';
> ij> SELECT journey.transport_company AS journey_transport_provider, ...
> 1 row selected
> ij> quit;
> real 0m47.459s
> user 0m47.067s
> sys 0m0.344s
> chris@fen-desktop2(tmp)$ time ./ij optimizer-off.sql
> ...
> real 0m3.913s
> user 0m4.100s
> sys 0m0.148s
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.