[
https://issues.apache.org/jira/browse/DERBY-6858?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15155674#comment-15155674
]
Bryan Pendleton commented on DERBY-6858:
----------------------------------------
I had no experience with Derby, either, when I started developing on it. What I
had was:
- general knowledge about database systems, and about Java
- an application I had written using Derby, which was having a problem
- a desire to get that problem fixed.
When I started working on Derby, it was already more than a decade old, and many
of the original developers had long since moved on to other things. But the
community
helped me track down the problem that was bugging me, suggested things I could
try
to understand what was going wrong, and after a while we fixed that problem.
And I found I was interested in Derby, and stayed involved in it, and eventually
became a committer and developer.
So really, all you need to get started in helping us fix this problem is
aptitude and desire,
both of which you certainly have.
My basic stumbling block is that I don't have a real theory. What I know is
that:
a) this behavior has been present a LONG time, and
b) it is somehow related to the database page size
But that isn't much to go on, and it hasn't lead to many good guesses about why
changing the page size makes such a difference. (If other developers had such
guesses, they would have chimed in by now.)
Since the behavior is so clearly reproducible, my overall approach is going to
be to try to gather more information about what's "different" between the slow
and fast runs:
- CPU time?
- IO behaviors?
- memory usage?
It's either running different code for the two different page sizes, or it's
running
the same code, but that code is behaving QUITE differently. I suspect it's the
latter.
I suspect we'll have to instrument parts of Derby to collect data about what
Derby's doing when it processes your query, and that instrumentation will
have to be refined and iterated over multiple experiments until it reveals the
core underlying reason that the page size is having such an affect on the
performance.
That process takes time, and I haven't found that time yet.
But there's absolutely no reason you can't contribute to that process. You can
build custom versions of Derby with instrumentation, you can run different
experiments, you can collect and share your experiments with the community,
and we can work together to try to break this down and find out the answer.
A good start would be to focus on the stacktrace that I captured on 27-Jan,
perhaps
capturing some additional stacktraces yourself, and look at some of the
methods that are visible in that stacktrace, and see what sort of loops and
algorithms they contain, and plant some instrumentation into that code to see
if we can gather some data about whether the behavior of that code is different
in the two cases.
> 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)
