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:45:45 GMT

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


Mime
View raw message