db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Brett Bergquist (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (DERBY-6858) Apache Derby simple update statement performance becomes 1500% worse when adding one byte to a column
Date Sun, 21 Feb 2016 13:37:18 GMT

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

Brett Bergquist edited comment on DERBY-6858 at 2/21/16 1:36 PM:
-----------------------------------------------------------------

Another datapoint.  I downloaded the repro and ran it in the slow case.  I then uses SquirrelSQL
to connect to the database and played around a bit.  I found that the statement

update ChildUpdate set parentName = 'Parent 1' where parentName = 'Parent 2';

causes the long run time (around 11 seconds on my Macbook Pro) yet if I then do:

update ChildUpdate set parentName = 'Parent 2' where parentName = 'Parent 1';

this takes about 0.2 seconds.   This is repeatable in that running the first statement setting
"Parent 1" is always about 11 seconds and running the second always is about 0.2 seconds.


Here are the statement plans for the slow execution and fast execution.  We can see that the
fast execution did a table scan and the slow execution used the foreign key index on PARENTNAME

This is the long execution statement plan:

Statement Name: 
	null
Statement Text: 
	update ChildUpdate set parentName = 'Parent 1' where parentName = 'Parent 2'
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: -1456061222976
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : 2016-02-21 08:27:02.976
End Execution Timestamp : 2016-02-21 08:27:13.433
Statement Execution Plan Text: 
Update ResultSet using row locking:
deferred: true
Rows updated = 2500
Indexes updated = 1
Execute Time = -1456061222989
	Normalize ResultSet:
	Number of opens = 1
	Rows seen = 2500
		constructor time (milliseconds) = 0
		open time (milliseconds) = 0
		next time (milliseconds) = 12
		close time (milliseconds) = 1
		optimizer estimated row count: 958.00
		optimizer estimated cost: 438.64
	Source result set:
		Project-Restrict ResultSet (3):
		Number of opens = 1
		Rows seen = 2500
		Rows filtered = 0
		restriction = false
		projection = true
			constructor time (milliseconds) = 0
			open time (milliseconds) = 0
			next time (milliseconds) = 11
			close time (milliseconds) = 1
			restriction time (milliseconds) = 0
			projection time (milliseconds) = 0
			optimizer estimated row count: 958.00
			optimizer estimated cost: 438.64
		Source result set:
			Project-Restrict ResultSet (2):
			Number of opens = 1
			Rows seen = 2500
			Rows filtered = 0
			restriction = false
			projection = true
				constructor time (milliseconds) = 0
				open time (milliseconds) = 0
				next time (milliseconds) = 11
				close time (milliseconds) = 1
				restriction time (milliseconds) = 0
				projection time (milliseconds) = 0
				optimizer estimated row count: 958.00
				optimizer estimated cost: 438.64
			Source result set:
				Index Scan ResultSet for CHILDUPDATE using constraint SQL160220224740821 at read committed
isolation level using exclusive row locking chosen by the optimizer
				Number of opens = 1
				Rows seen = 2500
				Rows filtered = 0
				Fetch Size = 1
					constructor time (milliseconds) = 0
					open time (milliseconds) = 0
					next time (milliseconds) = 11
					close time (milliseconds) = 1
					next time in milliseconds/row = 0

				scan information:
					Bit set of columns fetched={0, 1}
					Number of columns fetched=2
					Number of deleted rows visited=0
					Number of pages visited=19
					Number of rows qualified=2500
					Number of rows visited=2500
					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: 958.00
					optimizer estimated cost: 438.64




This is the fast execution statement plan

Statement Name: 
	null
Statement Text: 
	update ChildUpdate set parentName = 'Parent 2' where parentName = 'Parent 1'
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: -1456061363407
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : 2016-02-21 08:29:23.407
End Execution Timestamp : 2016-02-21 08:29:23.546
Statement Execution Plan Text: 
Update ResultSet using row locking:
deferred: false
Rows updated = 2500
Indexes updated = 1
Execute Time = -1456061363420
	Normalize ResultSet:
	Number of opens = 1
	Rows seen = 2500
		constructor time (milliseconds) = 0
		open time (milliseconds) = 0
		next time (milliseconds) = 13
		close time (milliseconds) = 0
		optimizer estimated row count: 250.60
		optimizer estimated cost: 844.70
	Source result set:
		Project-Restrict ResultSet (2):
		Number of opens = 1
		Rows seen = 2500
		Rows filtered = 0
		restriction = false
		projection = true
			constructor time (milliseconds) = 0
			open time (milliseconds) = 0
			next time (milliseconds) = 13
			close time (milliseconds) = 0
			restriction time (milliseconds) = 0
			projection time (milliseconds) = 2
			optimizer estimated row count: 250.60
			optimizer estimated cost: 844.70
		Source result set:
			Table Scan ResultSet for CHILDUPDATE at read committed isolation level using exclusive
row locking chosen by the optimizer
			Number of opens = 1
			Rows seen = 2500
			Rows filtered = 0
			Fetch Size = 1
				constructor time (milliseconds) = 0
				open time (milliseconds) = 0
				next time (milliseconds) = 8
				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 pages visited=31
				Number of rows qualified=2500
				Number of rows visited=2500
				Scan type=heap
				start position:
					null
				stop position:
					null
				qualifiers:
					Column[0][0] Id: 0
					Operator: =
					Ordered nulls: false
					Unknown return value: false
					Negate comparison result: false
				optimizer estimated row count: 250.60
				optimizer estimated cost: 844.70



was (Author: bbergquist):
Another datapoint.  I downloaded the repro and ran it in the slow case.  I then uses SquirrelSQL
to connect to the database and played around a bit.  I found that the statement

update ChildUpdate set parentName = 'Parent 1' where parentName = 'Parent 2';

causes the long run time (around 11 seconds on my Macbook Pro) yet if I then do:

update ChildUpdate set parentName = 'Parent 2' where parentName = 'Parent 1';

this takes about 0.2 seconds.   This is repeatable in that running the first statement setting
"Parent 1" is always about 11 seconds and running the second always is about 0.2 seconds.


Here are the statement plans for the slow execution and fast execution.  We can see that the
fast execution did a table scan and the slow execution used the foreign key index on PARENTNAME



> Apache Derby simple update statement performance becomes 1500% worse when adding one
byte to a column
> -----------------------------------------------------------------------------------------------------
>
>                 Key: DERBY-6858
>                 URL: https://issues.apache.org/jira/browse/DERBY-6858
>             Project: Derby
>          Issue Type: Bug
>    Affects Versions: 10.11.1.1, 10.12.1.1
>         Environment: windows 7 64 bit
>            Reporter: somebody
>            Priority: Blocker
>         Attachments: repro.java, repro.java, repro.java
>
>
> I have 2 tables as follows:
> ParentUpdate
> name varchar(255)
> value int not null
> primary key: name
> ChildUpdate
> parentName varchar(255)
> name varchar(255)
> value int
> data varchar(1000)
> primary key: name foreign key: parentName to ParentUpdate.name
> When I run the statement "update ChildUpdate set parentName = 'Parent 2' where parentName
= 'Parent 1'" with 2500 records in the ChildUpdate table and 1 record in the ParentUpdate
table with only a single byte difference in data size in the ChildUpdate table, the performance
decreases by 15 times.
> When the ChildUpdate data column has exactly 14 bytes of the same character the runtime
of the above query is about 500 milliseconds. When I add one more byte to the data column
of ChildUpdate the performance all of a sudden becomes about 7500 milliseconds.
> If i then decrease the data size back to 14 from 15 it's fast again. When i put it back
to 15 it's slow again. This is reproducible every time.
> Can you please help me figure out how to get the same fast performance without such seemingly
random behaviour.
> The query plans are below for both cases.
>         projection = true
>             constructor time (milliseconds) = 0
>             open time (milliseconds) = 0
>             next time (milliseconds) = 16
>             close time (milliseconds) = 16
>             restriction time (milliseconds) = 0
>             projection time (milliseconds) = 0
>             optimizer estimated row count: 51.50
>             optimizer estimated cost: 796.12
>         Source result set:
>             Table Scan ResultSet for CHILDUPDATE at read committed isolation level using
exclusive row locking chosen by the optimizer
>             Number of opens = 1
>             Rows seen = 2500
>             Rows filtered = 0
>             Fetch Size = 1
>                 constructor time (milliseconds) = 0
>                 open time (milliseconds) = 15
>                 next time (milliseconds) = 16
>                 close time (milliseconds) = 16
>                 next time in milliseconds/row = 0
>             scan information:
>                 Bit set of columns fetched={0, 1}
>                 Number of columns fetched=2
>                 Number of pages visited=41
>                 Number of rows qualified=2500
>                 Number of rows visited=2500
>                 Scan type=heap
>                 start position:
>                     null
>                 stop position:
>                     null
>                 qualifiers:
>                     Column[0][0] Id: 0
>                     Operator: =
>                     Ordered nulls: false
>                     Unknown return value: false
>                     Negate comparison result: false
>                 optimizer estimated row count: 51.50
>                 optimizer estimated cost: 796.12
> total time: ~500 milliseconds
> and the slow version
>    Statement Name: 
>     null
> Statement Text: 
>     update ChildUpdate set parentName = 'Parent 2' where parentName = 'Parent 1'
> Parse Time: 0
> Bind Time: 0
> Optimize Time: 0
> Generate Time: 0
> Compile Time: 0
> Execute Time: -1453199485700
> Begin Compilation Timestamp : 2016-01-19 05:31:25.684
> End Compilation Timestamp : 2016-01-19 05:31:25.684
> Begin Execution Timestamp : 2016-01-19 05:31:25.7
> End Execution Timestamp : 2016-01-19 05:31:33.141
> Statement Execution Plan Text: 
> Update ResultSet using row locking:
> deferred: true
> Rows updated = 2500
> Indexes updated = 2
> Execute Time = -1453199485747
>     Normalize ResultSet:
>     Number of opens = 1
>     Rows seen = 2500
>         constructor time (milliseconds) = 0
>         open time (milliseconds) = 0
>         next time (milliseconds) = 47
>         close time (milliseconds) = 0
>         optimizer estimated row count: 51.50
>         optimizer estimated cost: 810.94
>     Source result set:
>         Project-Restrict ResultSet (3):
>         Number of opens = 1
>         Rows seen = 2500
>         Rows filtered = 0
>         restriction = false
>         projection = true
>             constructor time (milliseconds) = 0
>             open time (milliseconds) = 0
>             next time (milliseconds) = 32
>             close time (milliseconds) = 0
>             restriction time (milliseconds) = 0
>             projection time (milliseconds) = 0
>             optimizer estimated row count: 51.50
>             optimizer estimated cost: 810.94
>         Source result set:
>             Project-Restrict ResultSet (2):
>             Number of opens = 1
>             Rows seen = 2500
>             Rows filtered = 0
>             restriction = false
>             projection = true
>                 constructor time (milliseconds) = 0
>                 open time (milliseconds) = 0
>                 next time (milliseconds) = 32
>                 close time (milliseconds) = 0
>                 restriction time (milliseconds) = 0
>                 projection time (milliseconds) = 0
>                 optimizer estimated row count: 51.50
>                 optimizer estimated cost: 810.94
>             Source result set:
>                 Index Scan ResultSet for CHILDUPDATE using index TESTINDEX at read committed
isolation level using exclusive row locking chosen by the optimizer
>                 Number of opens = 1
>                 Rows seen = 2500
>                 Rows filtered = 0
>                 Fetch Size = 1
>                     constructor time (milliseconds) = 0
>                     open time (milliseconds) = 0
>                     next time (milliseconds) = 32
>                     close time (milliseconds) = 0
>                     next time in milliseconds/row = 0
>                 scan information:
>                     Bit set of columns fetched={0, 1, 2}
>                     Number of columns fetched=3
>                     Number of deleted rows visited=0
>                     Number of pages visited=42
>                     Number of rows qualified=2500
>                     Number of rows visited=2500
>                     Scan type=btree
>                     Tree height=2
>                     start position:
>                         None
>                     stop position:
>                         None
>                     qualifiers:
>                         Column[0][0] Id: 1
>                         Operator: =
>                         Ordered nulls: false
>                         Unknown return value: false
>                         Negate comparison result: false
>                     optimizer estimated row count: 51.50
>                     optimizer estimated cost: 810.94
> total time: ~7 seconds 500 milliseconds
> please also see post:
> http://stackoverflow.com/questions/34874762/apache-derby-simple-update-statement-performance-becomes-1500-worse-when-adding



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message