Firebird

> Is there a way to get back the FB 2.0 commit speed? I tried setting
> DatabaseGrowthIncrement to zero but it did not help (expected I guess).
> Is there a setting for disabling the new double writing behavior of
> newly allocated pages? I would at least want to try that to see if it is
> causing the entire problem or just a part of it.

    You can create some table, fill it with few millions records to grow
database file and then drop it. This creates a lot of unused space and
you may make your test without file growth penalty.

Regards,
Vlad

PS you may create some kind of test for us to understand where the real problem.

> You can create some table, fill it with few millions records to grow
database 
> file and then drop it. This creates a lot of unused space and you may
make 
> your test without file growth penalty.

Thanks for the tip. I was thinking about this but then I noticed that
the problem occurs even when the database file is not growing at all. In
other words, I apparently have enough free pages in the database file --
new pages do not need to be allocated. I repeat operations such as 100 x
checkout and 100 x undo checkout. Checkout adds records, while undo
checkout effectively deletes the added records. The net size of the
database does not grow.

The database file is 190,416 KB and remains at this precise size during
the tests. Still, the commits of the checkout operations are much slower
than in FB 2.0. In "undo checkout", which is mostly deleting rows, there
does not seem to be any performance difference compared to FB 2.0.

I guess this means that the performance difference cannot be related to
the new database file preallocation system or to the "double writing"
issue(?). It must be something else? Are there any other commit-related
changes that could be suspected?

> PS you may create some kind of test for us to understand where the
real problem.

I will work on this, although it is laborous to create a sample that
would demonstrate the issue without our software. Before that, I will
try to do some performance profiling against the FB 2.1 DLL myself in
order to see what is taking the time.

Any tips on what I should be profiling and looking at inside commit?

Antti

----- Original Message ----- 
From: "Antti Nivala" <antti.nivala@...>
To: "For discussion among Firebird Developers" <firebird-devel@...>
Sent: Saturday, May 03, 2008 1:21 PM
Subject: Re: [Firebird-devel] FB 2.1 is 50% slower than FB 2.0 in commits


>> You can create some table, fill it with few millions records to grow
> database 
>> file and then drop it. This creates a lot of unused space and you may
> make 
>> your test without file growth penalty.
> 
> Thanks for the tip. I was thinking about this but then I noticed that
> the problem occurs even when the database file is not growing at all. In
> other words, I apparently have enough free pages in the database file --
> new pages do not need to be allocated. I repeat operations such as 100 x
> checkout and 100 x undo checkout. Checkout adds records, while undo
> checkout effectively deletes the added records. The net size of the
> database does not grow.
> 
> The database file is 190,416 KB and remains at this precise size during
> the tests. Still, the commits of the checkout operations are much slower
> than in FB 2.0. In "undo checkout", which is mostly deleting rows, there
> does not seem to be any performance difference compared to FB 2.0.
> 
> I guess this means that the performance difference cannot be related to
> the new database file preallocation system or to the "double writing"
> issue(?). It must be something else? Are there any other commit-related
> changes that could be suspected?
> 
>> PS you may create some kind of test for us to understand where the
> real problem.
> 
> I will work on this, although it is laborous to create a sample that
> would demonstrate the issue without our software. Before that, I will
> try to do some performance profiling against the FB 2.1 DLL myself in
> order to see what is taking the time.
> 
> Any tips on what I should be profiling and looking at inside commit?
> 
> Antti
> 
> -------------------------------------------------------------------------
> This SF.net email is sponsored by the 2008 JavaOne(SM) Conference 
> Don't miss this year's exciting event. There's still time to save $100. 
> Use priority code J8TL2D2. 
> http://ad.doubleclick.net/clk;198757673;13503038;p?http://java.sun.com/javaone
> Firebird-Devel mailing list, web interface at https://lists.sourceforge.net/lists/listinfo/firebird-devel

>> You can create some table, fill it with few millions records to grow
> database 
>> file and then drop it. This creates a lot of unused space and you may
> make 
>> your test without file growth penalty.
> 
> Thanks for the tip. I was thinking about this but then I noticed that
> the problem occurs even when the database file is not growing at all. In

    This is what i expected :)

> other words, I apparently have enough free pages in the database file --
> new pages do not need to be allocated. I repeat operations such as 100 x
> checkout and 100 x undo checkout. Checkout adds records, while undo
> checkout effectively deletes the added records. The net size of the
> database does not grow.
> 
> The database file is 190,416 KB and remains at this precise size during
> the tests. Still, the commits of the checkout operations are much slower
> than in FB 2.0. In "undo checkout", which is mostly deleting rows, there
> does not seem to be any performance difference compared to FB 2.0.
> 
> I guess this means that the performance difference cannot be related to
> the new database file preallocation system or to the "double writing"
> issue(?). It must be something else? 

    Yes, i think

> Are there any other commit-related
> changes that could be suspected?

    Yes. Flush algorithm was reworked and it is much faster when we have a big
amount of pages to flush. May be it is somewhat slower when it need to flush a
few pages. Also, in FB 2.1 applied big patch for nbackup code which have impact
on page writes. Without test case it is hard to tell more exactly where the perofmance
penalty is.
 
>> PS you may create some kind of test for us to understand where the
> real problem.
> 
> I will work on this, although it is laborous to create a sample that
> would demonstrate the issue without our software. Before that, I will
> try to do some performance profiling against the FB 2.1 DLL myself in
> order to see what is taking the time.
> 
> Any tips on what I should be profiling and looking at inside commit?

    In both FB 2.1 and FB 2.0 the most commit time is spent inside CCH_flush.
Difference is inside it i believe. But it is possible that another code also have its
overhead.

Regards,
Vlad

Vlad,

Thanks for the explanations. I may be closer to the real cause of the
slowness now. I hope you can help me further.

I profiled the operations with FB 2.0 and FB 2.1. In both cases, 99% of
the time is spent in PIO_write in winnt.cpp. The difference is not so
much in the speed of PIO_write but rather in the number of times it is
getting called. It is called about 6,400 times in FB 2.0 but more than
10,000 times in FB 2.1 in exactly the same circumstances. Why would this
happen?

I repeated the tests several times, each time starting from the same
previously saved copy of the database. The database file was exactly the
same in both cases. I just swicthed the Firebird engine DLL (I am using
Firebird Embedded). The figures below are from the same ODS version, but
I also tried after backup & restore in FB 2.1 and it did not cause any
significant difference. For some reason, FB 2.1 needs to write many more
pages in the same operation where FB 2.0 writes fewer pages.

FB 2.0:

PIO_write x  6528    8236 ms  (1.3 ms/page)
PIO_write x  6390   10792 ms  (1.7 ms/page)
PIO_write x  6426   10638 ms  (1.7 ms/page)
PIO_write x  6420   11310 ms  (1.8 ms/page)

FB 2.1:

PIO_write x 10054   21261 ms  (2.1 ms/page)
PIO_write x  9909   21460 ms  (2.2 ms/page)
PIO_write x  9913   20133 ms  (2.0 ms/page)
PIO_write x  9956   22340 ms  (2.2 ms/page)

There is some difference in PIO_write speed, too, but many factors could
be affecting it (e.g. the total number of pages). I think the primary
issue to resolve is why FB 2.1 calls PIO_write many more times than FB
2.0.

The call paths that consume 99% of the commit time are as follows

FB 2.0:

TRA_commit ->
btc_flush ->
write_buffer ->
write_page ->
PIO_write

FB 2.1:

TRA_commit ->
flushDirty ->
write_buffer ->
write_page ->
PIO_write

Any ideas what could be causing the difference in the number of times
PIO_write is called? What can I do next?

Antti

> Thanks for the explanations. I may be closer to the real cause of the
> slowness now. I hope you can help me further.
> 
> I profiled the operations with FB 2.0 and FB 2.1. In both cases, 99% of
> the time is spent in PIO_write in winnt.cpp. The difference is not so
> much in the speed of PIO_write but rather in the number of times it is
> getting called. It is called about 6,400 times in FB 2.0 but more than
> 10,000 times in FB 2.1 in exactly the same circumstances. Why would this
> happen?

    I don't know. It is very strange result. I assume both 2.0 and 2.1 run
equal number of transactions ? How big is page cache in your database ?

    Can you compare plans and IO statistics of both engines ? Also
it is interesting to look at database statistics after the test (gstat -r)

Regards,
Vlad

> I don't know. It is very strange result. I assume both 
> 2.0 and 2.1 run equal number of transactions ? 
> How big is page cache in your database ?

The number of transactions is almost equal. There are some random
additional transactions that I cannot easily eliminate, but they don't
seem to affect the actual problem.

Page cache size is 66,666 pages (page size 4096). The page cache size is
intentionally a bit larger than the database file size 190 MB because we
want to keep the entire database in memory for best possible SELECT
speed.

> Can you compare plans and IO statistics of both engines ?

Plans are difficult to compare because the checkout operation executes
more than a dozen statements and uses parameters. We are using Firebird
Embedded. Is there an easy way to record the statements that were
executed and to print those out so that I could then execute them
manually and check the plans and IO statistics?

> Also it is interesting to look at database statistics 
> after the test (gstat -r)

As far as I can tell, the statistics do not differ considerably. The
number of transactions has grown by approximately 100 (expected). The
table and index statistics are almost identical -- the number of leaf
buckets in several indices has increased by 1, which I guess is OK.


I did debug the test with both FB 2.0.3 and FB 2.1.0. The difference I
see is that in FB 2.0, write_buffer is called approximately 60 times for
each commit (I am referring to the checkout operation I am testing).
Precisely the same operations cause about 95 write_buffer calls when I
switch the engine to FB 2.1.0. The initial database is exactly the same
in both cases, and the executed statements are the same.

In the test I repeat the checkout operation 100 times. Each time, the
number of write_buffer calls during commit differs in this way between
FB 2.0 and FB 2.1 (about 60 write_buffer calls vs. about 95 write_buffer
calls).

How can I tell what is making the additional write_buffer calls
necessary? I can see that in FB 2.0 CCH_flush calls btc_flush while in
FB 2.1 it calls flushDirty (DIRTY_TREE vs. DIRTY_LIST). Could it be that
the new algorithm is causing additional (unnecessary?) flushing of pages
when it tries to maintain the order of page writes? Or, is the problem
occurring earlier, i.e. FB 2.1 is modifying more pages than FB 2.0?

What next?

Antti

>> Can you compare plans and IO statistics of both engines ?
> 
> Plans are difficult to compare because the checkout operation executes
> more than a dozen statements and uses parameters. We are using Firebird
> Embedded. Is there an easy way to record the statements that were
> executed and to print those out so that I could then execute them
> manually and check the plans and IO statistics?

    It depends on tools you use to develop application. Many of them have tracing
capability which you may activate on application side. It gives you statements and
probably plans. To take IO statistics you need to modify application, i guess.
 
>> Also it is interesting to look at database statistics 
>> after the test (gstat -r)
> 
> As far as I can tell, the statistics do not differ considerably. The
> number of transactions has grown by approximately 100 (expected). The
> table and index statistics are almost identical -- the number of leaf
> buckets in several indices has increased by 1, which I guess is OK.
> 
> 
> I did debug the test with both FB 2.0.3 and FB 2.1.0. The difference I

    It is also interesting to test 2.0.4 as it have latest nbackup patch.

> see is that in FB 2.0, write_buffer is called approximately 60 times for
> each commit (I am referring to the checkout operation I am testing).
> Precisely the same operations cause about 95 write_buffer calls when I
> switch the engine to FB 2.1.0. The initial database is exactly the same
> in both cases, and the executed statements are the same.
> 
> In the test I repeat the checkout operation 100 times. Each time, the
> number of write_buffer calls during commit differs in this way between
> FB 2.0 and FB 2.1 (about 60 write_buffer calls vs. about 95 write_buffer
> calls).

    Do you measure number of write_buffer calls during commit only or during 
statement execution + commit ?
 
> How can I tell what is making the additional write_buffer calls
> necessary? I can see that in FB 2.0 CCH_flush calls btc_flush while in
> FB 2.1 it calls flushDirty (DIRTY_TREE vs. DIRTY_LIST). 

    Correct.

> Could it be that
> the new algorithm is causing additional (unnecessary?) flushing of pages
> when it tries to maintain the order of page writes? 

    I don't think so. But i will investigate such possibility too.

> Or, is the problem
> occurring earlier, i.e. FB 2.1 is modifying more pages than FB 2.0?
> 
> What next?

    Compare also number of calls of CCH_mark, unmark, insertDirty vs btc_insert,
removeDirty vs btc_remove. Or send your profile numbers to me ;) Or, better, 
send to me sample database and application (if it is possible of course).

Regards,
Vlad

> After noticing unexpected performance degradation in some operations,
I
> ran some performance tests between FB 2.0.3 and FB 2.1.0. Commits in
FB
> 2.1 after inserts and updates seem to be MUCH slower than in FB 2.0.

What OS are you running, and what is the Forced Write settings for the
databases?


Sean

> What OS are you running, and what is the Forced Write settings for the
databases?

Windows XP SP2. Forced Writes is ON.

Antti

> > Could it be that the new algorithm is causing additional 
> > (unnecessary?) flushing of pages when it tries to maintain 
> > the order of page writes?
>
> I don't think so. But i will investigate such possibility too.

You seem to be right.

The problem seems to be in marking more pages dirty than before.

> insertDirty vs btc_insert

This seems to make the difference. During our checkout operation
(statement execution, i.e. before commit), there are about 85
insertDirty calls in FB 2.1.0 compared to about 55 btc_insert calls in
FB 2.0.3.

I am only counting insertDirty calls that actually invoke QUE_INSERT.

It seems to be one or two INSERT_INTO statements that are causing the
most insertDirty calls (27 and 15 pages marked dirty in a single INSERT
INTO execution). I will examine these calls in more detail to confirm
that the difference is there and to see if it seems to be related to
updating some specific indexes. I think you can help me more then :-)

> It is also interesting to test 2.0.4 as it have latest nbackup patch.

Does this test still sound valid? Can the nbackup patch affect the
number of pages being marked dirty during INSERT INTO?

> Or, better, send to me sample database and application (if it is
possible of course)

I'll be happy to do this. I will prepare a sample which does not include
real customer data but still demonstrates the problem.

Or, I may be able to create a simplified example now that I seem to get
closer to the actual statements that are marking more pages dirty than
before.

Antti

> > I did debug the test with both FB 2.0.3 and FB 2.1.0. The difference
I
> 
>     It is also interesting to test 2.0.4 as it have latest nbackup
patch.

Actually, 2.0.4 does not have the latest nbackup patch -- it has not yet
been added to the v2.0 branch, it was added to the v2.5 and v2.1
branches after the 2.0.4 was built.


Sean

>>     It is also interesting to test 2.0.4 as it have latest nbackup
> patch.
> 
> Actually, 2.0.4 does not have the latest nbackup patch -- it has not yet
> been added to the v2.0 branch, it was added to the v2.5 and v2.1
> branches after the 2.0.4 was built.

    2.0.4 have included the same patch by RedSoft as 2.1
Per your request if you remember ;)

Regards,
Vlad

> The problem seems to be in marking more pages dirty than before.
> 
>> insertDirty vs btc_insert
> 
> This seems to make the difference. During our checkout operation
> (statement execution, i.e. before commit), there are about 85
> insertDirty calls in FB 2.1.0 compared to about 55 btc_insert calls in
> FB 2.0.3.
> 
> I am only counting insertDirty calls that actually invoke QUE_INSERT.

    Very interesting...
 
> It seems to be one or two INSERT_INTO statements that are causing the
> most insertDirty calls (27 and 15 pages marked dirty in a single INSERT
> INTO execution). I will examine these calls in more detail to confirm
> that the difference is there and to see if it seems to be related to
> updating some specific indexes. I think you can help me more then :-)

    Compare also amount of calls of store(), modify() and IDX_store().
 
>> It is also interesting to test 2.0.4 as it have latest nbackup patch.
> 
> Does this test still sound valid? Can the nbackup patch affect the
> number of pages being marked dirty during INSERT INTO?

    I don't think so. My guess about nbackup is that it adds some overhead
every time page changed its dirty state. But it can't make number of calls
different of course.
 
>> Or, better, send to me sample database and application (if it is
> possible of course)
> 
> I'll be happy to do this. I will prepare a sample which does not include
> real customer data but still demonstrates the problem.
> 
> Or, I may be able to create a simplified example now that I seem to get
> closer to the actual statements that are marking more pages dirty than
> before.

    Good. Waiting for your next message :)

Regards,
Vlad

> >>     It is also interesting to test 2.0.4 as it have latest nbackup
> > patch.
> >
> > Actually, 2.0.4 does not have the latest nbackup patch -- it has not
yet
> > been added to the v2.0 branch, it was added to the v2.5 and v2.1
> > branches after the 2.0.4 was built.
> 
>     2.0.4 have included the same patch by RedSoft as 2.1
> Per your request if you remember ;)

I was referring to the latest patch which solves the problems with
nbackup in v2.1.

So, we were talking about different things.


Sean

>> >>     It is also interesting to test 2.0.4 as it have latest nbackup
>> > patch.
>> >
>> > Actually, 2.0.4 does not have the latest nbackup patch -- it has not
> yet
>> > been added to the v2.0 branch, it was added to the v2.5 and v2.1
>> > branches after the 2.0.4 was built.
>> 
>>     2.0.4 have included the same patch by RedSoft as 2.1
>> Per your request if you remember ;)
> 
> I was referring to the latest patch which solves the problems with
> nbackup in v2.1.

    Why do you think i referred to it ? We talk about 2.0.4. And i have a 
little memory to remember which fix was included in which FB version.

> So, we were talking about different things.

    Yes. I refer to big patch which changed many internals and adds new overhead. 


Regards,
Vlad

> Compare also amount of calls of store(), modify() and IDX_store().

The issue seems to be related to index updating. I debugged through the
operations in both FB 2.0.3 and FB 2.1.0 and the difference is that
index updating that results from inserting a record marks two pages
dirty in FB 2.1.0 while in FB 2.0.3 only one page is marked dirty.

For example, when I insert to a table that has 3 indices, pages are
marked dirty as follows:

FB 2.0.3: 1 page for the actual insertion, and 1 page for each index
=> 1 + 3x1 = 1+3 = 4 pages

FB 2.1.0: 1 page for the actual insertion, and 2 pages for each index
=> 1 + 3x2 = 1+6 = 7 pages

We have lots of indices and apparently the above difference produces all
or most of the problem. During our checkout operation, it raises the
number of dirty pages from about 55 to about 85.

The "new thing" in FB 2.1.0 is at line 2258 in btr.cpp:

	CCH_MARK(tdbb, window);
	bucket->btr_header.pag_flags |= btr_dont_gc;

This causes the additional dirty page during each index update.

It seems to be related to CORE-1300 and CORE-1819. If I read Tracker
comments correctly, it could be that this has already been changed since
2.1.0, perhaps to a more efficient solution??

Do you think this can explain the issue? If yes, is there / will there
be an update that restores the FB 2.0.3 performance?

Antti

>> Compare also amount of calls of store(), modify() and IDX_store().
> 
> The issue seems to be related to index updating. I debugged through the
> operations in both FB 2.0.3 and FB 2.1.0 and the difference is that
> index updating that results from inserting a record marks two pages
> dirty in FB 2.1.0 while in FB 2.0.3 only one page is marked dirty.
> 
> For example, when I insert to a table that has 3 indices, pages are
> marked dirty as follows:
> 
> FB 2.0.3: 1 page for the actual insertion, and 1 page for each index
> => 1 + 3x1 = 1+3 = 4 pages
> 
> FB 2.1.0: 1 page for the actual insertion, and 2 pages for each index
> => 1 + 3x2 = 1+6 = 7 pages
> 
> We have lots of indices and apparently the above difference produces all
> or most of the problem. During our checkout operation, it raises the
> number of dirty pages from about 55 to about 85.
> 
> The "new thing" in FB 2.1.0 is at line 2258 in btr.cpp:
> 
> CCH_MARK(tdbb, window);
> bucket->btr_header.pag_flags |= btr_dont_gc;
> 
> This causes the additional dirty page during each index update.

    Good catch ! I forget about it as i implemented more efficient solution long
time ago :)

> It seems to be related to CORE-1300 and CORE-1819. If I read Tracker
> comments correctly, it could be that this has already been changed since
> 2.1.0, perhaps to a more efficient solution??

    Yes.
 
> Do you think this can explain the issue? If yes, is there / will there
> be an update that restores the FB 2.0.3 performance?

    I think your explanation is correct. I already backported CORE-1819 into 2.1 tree
so 2.1.1 will have it. It seems our snapshot builds worked again so you can try
against snapshot build of FB 2.1. 

Regards,
Vlad

> I think your explanation is correct. I already backported 
> CORE-1819 into 2.1 tree so 2.1.1 will have it. It seems our 
> snapshot builds worked again so you can try against snapshot 
> build of FB 2.1.

Correct. I tested with today's snapshot build and now the number of page
writes and the overall performance of commit is pretty much the same as
with 2.0.

Many thanks for your attention to this issue. We are looking forward to
2.1.1 :-)

Antti

We previously switched from 2.0.3 to 2.1.0 but then noticed that commits
are too slow in 2.1.0. This has been fixed by CORE-1819 so the fix will
be part of FB 2.1.1. In my opinion this fix is an issue that should be
made official fairly soon -- otherwise the migration from 2.0 to 2.1 may
suffer as users find out that 2.1.0 is so much slower in inserts and
updates compared to 2.0.3.

Can you let us know about the planned schedule of FB 2.1.1?

Best regards,
Antti Nivala

Antti Nivala wrote:
> 
> Can you let us know about the planned schedule of FB 2.1.1?

All I can say is that it's expected to be available quite soon. The 
source code is already tagged, the builds will be made once the release 
notes are updated.


Dmitry

> > Can you let us know about the planned schedule of FB 2.1.1?
> 
> All I can say is that it's expected to be available quite soon. The 
> source code is already tagged, the builds will be made once the
release 
> notes are updated.

Thank you. Assuming that "quite soon" means "absolutely before end of
June", it is fine for us. If not, please let me know :-)

Antti