Mailing-List: contact derby-dev-help@db.apache.org; run by ezmlm
Precedence: bulk
Reply-To: <derby-dev@db.apache.org>
Message-ID: <664304391.1212924945067.JavaMail.jira@brutus>
Date: Sun, 8 Jun 2008 04:35:45 -0700 (PDT)
From: "Michael Gerz (JIRA)" <jira@apache.org>
To: derby-dev@db.apache.org
Subject: [jira] Commented: (DERBY-3714) Significant performance degradation
 if Hibernate creates different order of attributes
In-Reply-To: <1309386363.1212831225165.JavaMail.jira@brutus>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit


    [ https://issues.apache.org/jira/browse/DERBY-3714?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12603368#action_12603368 ] 

Michael Gerz commented on DERBY-3714:
-------------------------------------

Good-performance query plan (for simplified query):

----------------------------------------------------------------
2008-06-08 11:31:19.406 GMT:
 Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.1.3 - (648739): instance a816c00e-011a-67f1-d490-0000000ceb90
on database directory XXX 

Database Class Loader started - derby.database.classpath=''
2008-06-08 11:31:52.328 GMT Thread[main,5,main] (XID = 3462637), (SESSIONID = 0), 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=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:          110,00
	optimizer estimated cost:          568,03

Source result set:
	Project-Restrict ResultSet (8):
	Number of opens = 1
	Rows seen = 33
	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:          110,00
		optimizer estimated cost:          568,03

	Source result set:
		Union ResultSet:
		Number of opens = 1
		Rows seen from the left = 8
		Rows seen from the right = 25
		Rows returned = 33
			constructor time (milliseconds) = 0
			open time (milliseconds) = 0
			next time (milliseconds) = 0
			close time (milliseconds) = 0
			optimizer estimated row count:          110,00
			optimizer estimated cost:          568,03

		Left result set:
			Normalize ResultSet:
			Number of opens = 1
			Rows seen = 8
				constructor time (milliseconds) = 0
				open time (milliseconds) = 0
				next time (milliseconds) = 0
				close time (milliseconds) = 0
				optimizer estimated row count:          110,00
				optimizer estimated cost:          568,03

			Source result set:
				Project-Restrict ResultSet (3):
				Number of opens = 1
				Rows seen = 8
				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:           11,00
					optimizer estimated cost:            5,91

				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 = 8
					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=3
						Number of rows qualified=8
						Number of rows visited=9
						Scan type=btree
						Tree height=3
						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:           11,00
						optimizer estimated cost:            5,91


		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.