[
https://issues.apache.org/jira/browse/DERBY-3714?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12603360#action_12603360
]
Michael Gerz commented on DERBY-3714:
-------------------------------------
Query plan for bad-performance query (Java 6). Have fun!
2008-06-08 10:41:00.781 GMT Thread[RMI TCP Connection(3)-192.168.1.33,5,RMI
Runtime] (XID = 3462556), (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 nullif('x','x') as RECEIVER, TIME_SENT, SEVERITY, nullif('2000-1-1
00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, SENDER, MESSAGE,
TEST_RUN_ID, nullif('x','x') as SERIALIZED_CONTENT, INDEX_SENT, nullif(0,0) as
INDEX_RECEIVED, nullif('x','x') as ACTION_REQUEST, nullif('x','x') as
ACTION_REPLY, 2 as clazz_ from USER_LOG_EVENT union all select nullif('x','x')
as RECEIVER, TIME_SENT, SEVERITY, nullif('2000-1-1 00:00:00','2000-1-1
00:00:00') as TIME_RECEIVED, ID, SENDER, MESSAGE, TEST_RUN_ID, nullif('x','x')
as SERIALIZED_CONTENT, INDEX_SENT, nullif(0,0) as INDEX_RECEIVED,
nullif('x','x') as ACTION_REQUEST, nullif('x','x') as ACTION_REPLY, 3 as clazz_
from DEVEL_LOG_EVENT union all select nullif('x','x') as RECEIVER, TIME_SENT,
nullif('x','x') as SEVERITY, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as
TIME_RECEIVED, ID, SENDER, nullif('x','x') as MESSAGE, TEST_RUN_ID,
nullif('x','x') as SERIALIZED_CONTENT, INDEX_SENT, nullif(0,0) as
INDEX_RECEIVED, ACTION_REQUEST, nullif('x','x') as ACTION_REPLY, 6 as clazz_
from ACTION_REQUEST_LOG_EVENT union all select nullif('x','x') as RECEIVER,
TIME_SENT, nullif('x','x') as SEVERITY, nullif('2000-1-1 00:00:00','2000-1-1
00:00:00') as TIME_RECEIVED, ID, SENDER, nullif('x','x') as MESSAGE,
TEST_RUN_ID, nullif('x','x') as SERIALIZED_CONTENT, INDEX_SENT, nullif(0,0) as
INDEX_RECEIVED, nullif('x','x') as ACTION_REQUEST, ACTION_REPLY, 7 as clazz_
from ACTION_REPLY_LOG_EVENT union all select RECEIVER, TIME_SENT,
nullif('x','x') as SEVERITY, TIME_RECEIVED, ID, SENDER, nullif('x','x') as
MESSAGE, TEST_RUN_ID, SERIALIZED_CONTENT, INDEX_SENT, INDEX_RECEIVED,
nullif('x','x') as ACTION_REQUEST, nullif('x','x') as ACTION_REPLY, 4 as clazz_
from DATA_FLOW_LOG_EVENT ) logevent0_ where logevent0_.TEST_RUN_ID=? *******
Project-Restrict ResultSet (22):
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: 1112389,00
optimizer estimated cost: 4047453,42
Source result set:
Project-Restrict ResultSet (21):
Number of opens = 1
Rows seen = 1112364
Rows filtered = 1112358
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: 1112389,00
optimizer estimated cost: 4047453,42
Source result set:
Union ResultSet:
Number of opens = 1
Rows seen from the left = 271467
Rows seen from the right = 840897
Rows returned = 1112364
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1112389,00
optimizer estimated cost: 4047453,42
Left result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 271467
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1112389,00
optimizer estimated cost: 4047453,42
Source result set:
Union ResultSet:
Number of opens = 1
Rows seen from the left = 270962
Rows seen from the right = 505
Rows returned = 271467
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
271487,00
optimizer estimated cost:
288473,90
Left result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 270962
constructor time (milliseconds)
= 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
271487,00
optimizer estimated cost:
288473,90
Source result set:
Union ResultSet:
Number of opens = 1
Rows seen from the left = 228943
Rows seen from the right = 42019
Rows returned = 270962
constructor time
(milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer estimated row
count: 270977,00
optimizer estimated
cost: 287878,82
Left result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 228943
constructor
time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 270977,00
optimizer
estimated cost: 287878,82
Source result set:
Union ResultSet:
Number of opens
= 1
Rows seen from
the left = 225313
Rows seen from
the right = 3630
Rows returned =
228943
constructor time (milliseconds) = 0
open
time (milliseconds) = 0
next
time (milliseconds) = 0
close
time (milliseconds) = 0
optimizer estimated row count: 228953,00
optimizer estimated cost: 250730,46
Left result set:
Project-Restrict ResultSet (6):
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: 243799,96
Source
result set:
Table Scan ResultSet for USER_LOG_EVENT 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=All
Number of columns fetched=7
Number of pages visited=1634
Number of rows qualified=225313
Number of rows visited=225313
Scan type=heap
start position:
null
stop position:
null
qualifiers:
None
optimizer estimated row count: 225318,00
optimizer estimated cost: 243799,96
Right result
set:
Project-Restrict ResultSet (8):
Number
of opens = 1
Rows
seen = 3630
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: 3635,00
optimizer estimated cost: 6930,50
Source
result set:
Table Scan ResultSet for DEVEL_LOG_EVENT at read committed isolation level
using share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 3630
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=7
Number of pages visited=46
Number of rows qualified=3630
Number of rows visited=3630
Scan type=heap
start position:
null
stop position:
null
qualifiers:
None
optimizer estimated row count: 3635,00
optimizer estimated cost: 6930,50
Right result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 42019
constructor
time (milliseconds) = 0
open time
(milliseconds) = 0
next time
(milliseconds) = 0
close time
(milliseconds) = 0
optimizer
estimated row count: 270977,00
optimizer
estimated cost: 287878,82
Source result set:
Project-Restrict ResultSet (11):
Number of opens
= 1
Rows seen =
42019
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: 42024,00
optimizer estimated cost: 37148,36
Source result
set:
Table
Scan ResultSet for ACTION_REQUEST_LOG_EVENT at read committed isolation level
using share row locking chosen by the optimizer
Number
of opens = 1
Rows
seen = 42019
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=6
Number of pages visited=243
Number of rows qualified=42019
Number of rows visited=42019
Scan type=heap
start position:
null
stop position:
null
qualifiers:
None
optimizer estimated row count: 42024,00
optimizer estimated cost: 37148,36
Right result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 505
constructor time (milliseconds)
= 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count:
271487,00
optimizer estimated cost:
288473,90
Source result set:
Project-Restrict ResultSet (15):
Number of opens = 1
Rows seen = 505
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: 510,00
optimizer estimated
cost: 595,08
Source result set:
Table Scan ResultSet
for ACTION_REPLY_LOG_EVENT at read committed isolation level using share row
locking chosen by the optimizer
Number of opens = 1
Rows seen = 505
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=6
Number of pages
visited=4
Number of rows
qualified=505
Number of rows
visited=505
Scan type=heap
start position:
null stop position:
null qualifiers:
None
optimizer
estimated row count: 510,00
optimizer
estimated cost: 595,08
Right result set:
Normalize ResultSet:
Number of opens = 1
Rows seen = 840897
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 1112389,00
optimizer estimated cost: 4047453,42
Source result set:
Project-Restrict ResultSet (19):
Number of opens = 1
Rows seen = 840897
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:
840902,00
optimizer estimated cost:
3758979,52
Source result set:
Table Scan ResultSet for
DATA_FLOW_LOG_EVENT at read committed isolation level using share row locking
chosen by the optimizer
Number of opens = 1
Rows seen = 840897
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=9
Number of pages visited=140486
Number of rows qualified=840897
Number of rows visited=840897
Scan type=heap
start position:
null stop position:
null qualifiers:
None
optimizer estimated row count:
840902,00
optimizer estimated cost:
3758979,52
> 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.
