db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bryan Pendleton (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DERBY-6858) Apache Derby simple update statement performance becomes 1500% worse when adding one byte to a column
Date Wed, 27 Jan 2016 02:32:40 GMT

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

Bryan Pendleton commented on DERBY-6858:
----------------------------------------

I can confirm your findings with your updated 'repro.java'. Here are my runs,
first "slow", then "fast":

Updating ChildUpdate ran from 1453859182456 to 1453859247610, which is a total of 65154 milliseconds
...
Updating ChildUpdate ran from 1453861130670 to 1453861133419, which is a total of 2749 milliseconds

So "fast" was 30x faster than "slow".

Hopefully, now that we have a clean standalone reproduction, we can really dig into
this behavior and try to understand what is going on.

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