[
https://issues.apache.org/jira/browse/DERBY-3714?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12603361#action_12603361
]
Michael Gerz commented on DERBY-3714:
-------------------------------------
Good-performance query plan (Java 5):
2008-06-08 10:47:29.656 GMT Thread[RMI TCP Connection(2)-192.168.1.33,5,RMI
Runtime] (XID = 3462592), (SESSIONID = 0), select logevent0_.ID as ID7_,
logevent0_.INDEX_SENT as INDEX2_7_, logevent0_.TEST_RUN_ID as TEST3_7_,
logevent0_.SENDER as SENDER7_, logevent0_.TIME_SENT as TIME5_7_,
logevent0_.MESSAGE as MESSAGE8_, logevent0_.SEVERITY as SEVERITY8_,
logevent0_.SERIALIZED_CONTENT as SERIALIZED1_11_, logevent0_.RECEIVER as
RECEIVER11_, logevent0_.TIME_RECEIVED as TIME3_11_, logevent0_.INDEX_RECEIVED
as INDEX4_11_, logevent0_.ACTION_REQUEST as ACTION1_13_,
logevent0_.ACTION_REPLY as ACTION1_14_, logevent0_.clazz_ as clazz_ from (
select TEST_RUN_ID, SENDER, MESSAGE, SEVERITY, nullif('x','x') as
SERIALIZED_CONTENT, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as
TIME_RECEIVED, ID, nullif('x','x') as ACTION_REQUEST, TIME_SENT,
nullif('x','x') as ACTION_REPLY, nullif('x','x') as RECEIVER, nullif(0,0) as
INDEX_RECEIVED, INDEX_SENT, 2 as clazz_ from USER_LOG_EVENT union all select
TEST_RUN_ID, SENDER, MESSAGE, SEVERITY, nullif('x','x') as SERIALIZED_CONTENT,
nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID,
nullif('x','x') as ACTION_REQUEST, TIME_SENT, nullif('x','x') as ACTION_REPLY,
nullif('x','x') as RECEIVER, nullif(0,0) as INDEX_RECEIVED, INDEX_SENT, 3 as
clazz_ from DEVEL_LOG_EVENT union all select TEST_RUN_ID, SENDER,
nullif('x','x') as MESSAGE, nullif('x','x') as SEVERITY, nullif('x','x') as
SERIALIZED_CONTENT, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as
TIME_RECEIVED, ID, ACTION_REQUEST, TIME_SENT, nullif('x','x') as ACTION_REPLY,
nullif('x','x') as RECEIVER, nullif(0,0) as INDEX_RECEIVED, INDEX_SENT, 6 as
clazz_ from ACTION_REQUEST_LOG_EVENT union all select TEST_RUN_ID, SENDER,
nullif('x','x') as MESSAGE, nullif('x','x') as SEVERITY, nullif('x','x') as
SERIALIZED_CONTENT, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as
TIME_RECEIVED, ID, nullif('x','x') as ACTION_REQUEST, TIME_SENT, ACTION_REPLY,
nullif('x','x') as RECEIVER, nullif(0,0) as INDEX_RECEIVED, INDEX_SENT, 7 as
clazz_ from ACTION_REPLY_LOG_EVENT union all select TEST_RUN_ID, SENDER,
nullif('x','x') as MESSAGE, nullif('x','x') as SEVERITY, SERIALIZED_CONTENT,
TIME_RECEIVED, ID, nullif('x','x') as ACTION_REQUEST, TIME_SENT,
nullif('x','x') as ACTION_REPLY, RECEIVER, INDEX_RECEIVED, INDEX_SENT, 4 as
clazz_ from DATA_FLOW_LOG_EVENT ) logevent0_ where logevent0_.TEST_RUN_ID=?
******* Project-Restrict ResultSet (27):
Number of opens = 1
Rows seen = 6
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: 109,81
optimizer estimated cost: 564,97
Source result set:
Project-Restrict ResultSet (26):
Number of opens = 1
Rows seen = 6
Rows filtered = 0
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: 109,81
optimizer estimated cost: 564,97
Source result set:
Union ResultSet:
Number of opens = 1
Rows seen from the left = 6
Rows seen from the right = 0
Rows returned = 6
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 109,81
optimizer estimated cost: 564,97
Left result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 6
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 109,81
optimizer estimated cost: 564,97
Source result set:
Union ResultSet:
Number of opens = 1
Rows seen from the left = 5
Rows seen from the right = 1
Rows returned = 6
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
28,86
optimizer estimated cost:
94,85
Left result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 5
constructor time (milliseconds)
= 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
28,86
optimizer estimated cost:
94,85
Source result set:
Union ResultSet:
Number of opens = 1
Rows seen from the left = 2
Rows seen from the right = 3
Rows returned = 5
constructor time
(milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer estimated row
count: 27,48
optimizer estimated
cost: 87,79
Left result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 2
constructor
time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 27,48
optimizer
estimated cost: 87,79
Source result set:
Union ResultSet:
Number of opens
= 1
Rows seen from
the left = 2
Rows seen from
the right = 0
Rows returned =
2
constructor time (milliseconds) = 0
open
time (milliseconds) = 0
next
time (milliseconds) = 0
close
time (milliseconds) = 0
optimizer estimated row count: 23,56
optimizer estimated cost: 73,32
Left result set:
Project-Restrict ResultSet (7):
Number
of opens = 1
Rows
seen = 2
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: 20,88
optimizer estimated cost: 60,78
Source
result set:
Index Row to Base Row ResultSet for USER_LOG_EVENT:
Number of opens = 1
Rows seen = 2
Columns accessed from heap = {0, 1, 3, 4, 5, 6}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 20,88
optimizer estimated cost: 60,78
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 = 2
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=2
Number of rows visited=3
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: 20,88
optimizer estimated cost: 60,78
Right result
set:
Project-Restrict ResultSet (10):
Number
of opens = 1
Rows
seen = 0
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: 2,68
optimizer estimated cost: 12,54
Source
result set:
Index Row to Base Row ResultSet for DEVEL_LOG_EVENT:
Number of opens = 1
Rows seen = 0
Columns accessed from heap = {0, 1, 3, 4, 5, 6}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 2,68
optimizer estimated cost: 12,54
Index Scan ResultSet for DEVEL_LOG_EVENT using constraint
FK64B9199FD4311151AB4119231D4787C at read committed isolation level using share
row locking chosen by the optimizer
Number of opens = 1
Rows seen = 0
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=2
Number of rows qualified=0
Number of rows visited=1
Scan type=btree
Tree height=2
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: 2,68
optimizer estimated cost: 12,54
Right result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 3
constructor
time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 27,48
optimizer
estimated cost: 87,79
Source result set:
Project-Restrict ResultSet (14):
Number of opens
= 1
Rows seen = 3
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: 3,92
optimizer estimated cost: 14,47
Source result
set:
Index
Row to Base Row ResultSet for ACTION_REQUEST_LOG_EVENT:
Number
of opens = 1
Rows
seen = 3
Columns
accessed from heap = {0, 1, 3, 4, 5}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 3,92
optimizer estimated cost: 14,47
Index Scan ResultSet for ACTION_REQUEST_LOG_EVENT using constraint
FK64B9199FD431115B413BAD6F8960E06 at read committed isolation level using share
row locking chosen by the optimizer
Number of opens = 1
Rows seen = 3
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=3
Number of rows visited=4
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: 3,92
optimizer estimated cost: 14,47
Right result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 1
constructor time (milliseconds)
= 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
28,86
optimizer estimated cost:
94,85
Source result set:
Project-Restrict ResultSet (19):
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,38
optimizer estimated
cost: 7,05
Source result set:
Index Row to Base Row
ResultSet for ACTION_REPLY_LOG_EVENT:
Number of opens = 1
Rows seen = 1
Columns accessed from
heap = {0, 1, 3, 4, 5}
constructor
time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 1,38
optimizer
estimated cost: 7,05
Index Scan
ResultSet for ACTION_REPLY_LOG_EVENT using constraint
FK64B9199FD431115B413BAD656CF5661 at read committed isolation level using share
row locking chosen by the optimizer
Number of opens
= 1
Rows seen = 1
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=2
Number
of rows qualified=1
Number
of rows visited=2
Scan
type=btree
Tree
height=2
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: 1,38
optimizer estimated cost: 7,05
Right result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 109,81
optimizer estimated cost: 564,97
Source result set:
Project-Restrict ResultSet (24):
Number of opens = 1
Rows seen = 0
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:
80,95
optimizer estimated cost:
470,12
Source result set:
Index Row to Base Row ResultSet for
DATA_FLOW_LOG_EVENT:
Number of opens = 1
Rows seen = 0
Columns accessed from heap = {0, 1, 3,
4, 5, 6, 7, 8}
constructor time (milliseconds)
= 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
80,95
optimizer estimated cost:
470,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 = 0
Rows filtered = 0
Fetch Size = 1
constructor time
(milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 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=0
Number of rows visited=1
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: 80,95
optimizer estimated
cost: 470,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.
