[
https://issues.apache.org/jira/browse/DERBY-3714?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12603367#action_12603367
]
Michael Gerz commented on DERBY-3714:
-------------------------------------
Bad-performance query plan (for the simplified query above):
----------------------------------------------------------------
Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.1.3
- (648739): instance a816c00e-011a-67ed-c85e-0000000ceb90
on database directory XXX
Database Class Loader started - derby.database.classpath=''
2008-06-08 11:27:12.406 GMT Thread[main,5,main] (XID = 3462628), (SESSIONID =
0), select
logevent0_.clazz_ as clazz_ from (
select
nullif('x','x') as RECEIVER,
TEST_RUN_ID,
2 as clazz_ from USER_LOG_EVENT
union all select
RECEIVER,
TEST_RUN_ID,
4 as clazz_ from DATA_FLOW_LOG_EVENT )
logevent0_ where logevent0_.TEST_RUN_ID=16188523 ******* Project-Restrict
ResultSet (9):
Number of opens = 1
Rows seen = 33
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: 225417,00
optimizer estimated cost: 53055,62
Source result set:
Project-Restrict ResultSet (8):
Number of opens = 1
Rows seen = 225338
Rows filtered = 225305
restriction = true
projection = false
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: 225417,00
optimizer estimated cost: 53055,62
Source result set:
Union ResultSet:
Number of opens = 1
Rows seen from the left = 225313
Rows seen from the right = 25
Rows returned = 225338
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 225417,00
optimizer estimated cost: 53055,62
Left result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 225313
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 225417,00
optimizer estimated cost: 53055,62
Source result set:
Project-Restrict ResultSet (3):
Number of opens = 1
Rows seen = 225313
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:
225318,00
optimizer estimated cost:
52493,51
Source result set:
Index Scan ResultSet for USER_LOG_EVENT
using constraint FK64B9199FD4311151AB41192233BF62B at read committed isolation
level using share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 225313
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=1450
Number of rows qualified=225313
Number of rows visited=225313
Scan type=btree
Tree height=3
start position:
None
stop position:
None
qualifiers:
None
optimizer estimated row count:
225318,00
optimizer estimated cost:
52493,51
Right result set:
Project-Restrict ResultSet (7):
Number of opens = 1
Rows seen = 25
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: 99,00
optimizer estimated cost: 562,12
Source result set:
Index Row to Base Row ResultSet for
DATA_FLOW_LOG_EVENT:
Number of opens = 1
Rows seen = 25
Columns accessed from heap = {5}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
99,00
optimizer estimated cost:
562,12
Index Scan ResultSet for
DATA_FLOW_LOG_EVENT using constraint FK64B9199FD431115378EE903 at read
committed isolation level using share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 25
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=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=3
Number of rows qualified=25
Number of rows visited=26
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:
99,00
optimizer estimated cost:
562,12
> Significant performance degradation if Hibernate creates different order of
> attributes
> --------------------------------------------------------------------------------------
>
> Key: DERBY-3714
> URL: https://issues.apache.org/jira/browse/DERBY-3714
> Project: Derby
> Issue Type: Bug
> Components: Performance
> Affects Versions: 10.3.2.1, 10.4.1.3
> Environment: Windows XP with Java 6u5 (JavaDB de-installed!), various
> hardware (single + dual core processors)
> Reporter: Michael Gerz
> Priority: Critical
>
> In our project we use Derby 10.4.1.3 in combination with the latest Hibernate
> Core 3.2.6.
> When we migrated from Java 5 to 6, we noticed a huge performance hit.
> After thorough analysis, we managed to pin down the problem to the order of
> the attributes in a select statement created by Hibernate. The order seems to
> make a huge impact on the performance, which is really strange.
> A (very simplified) example of the problem is shown below. If more attributes
> and more joins are added, the performance difference increases:
> Bad Performance (5 result set entries in 3672ms) :
> =======================================
> select
> logevent0_.clazz_ as clazz_ from (
> select
> nullif('x','x') as RECEIVER,
> TEST_RUN_ID,
> 2 as clazz_ from USER_LOG_EVENT
> union all select
> RECEIVER,
> TEST_RUN_ID,
> 4 as clazz_ from DATA_FLOW_LOG_EVENT )
> logevent0_ where logevent0_.TEST_RUN_ID=?
> Good Performance (5 entries in 610ms) :
> =======================================
> select
> logevent0_.clazz_ as clazz_ from (
> select
> TEST_RUN_ID,
> nullif('x','x') as RECEIVER,
> 2 as clazz_ from USER_LOG_EVENT
> union all select
> TEST_RUN_ID,
> RECEIVER,
> 4 as clazz_ from DATA_FLOW_LOG_EVENT )
> logevent0_ where logevent0_.TEST_RUN_ID=?
> Table DATA_FLOW_LOG_EVENT has the attributes
> TEST_RUN_ID BIGINT,
> RECEIVER VARCHAR,...
> wheras table USER_LOG_EVENT does NOT have the attribute RECEIVER.
>
> As hibernate generates these select statements automatically, we are not able
> the change the order of the attributes.
> The real question is why there is such a difference in the execution speed,
> and how to avoid this problem. (The complete query takes about 1-2sec in the
> fast version, and more than 50sec in the slow version). This makes it
> impossible for us to use Derby+Hibernate with Java 6!
> Any ideas?
> Kind regards,
> Michael
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
