db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Michael Gerz (JIRA)" <j...@apache.org>
Subject [jira] Commented: (DERBY-3714) Significant performance degradation if Hibernate creates different order of attributes
Date Sun, 08 Jun 2008 10:51:45 GMT

    [ 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.


Mime
View raw message