Huge Performance regressions in bazaar 1.16 and higher

I'm aware of a specific regression where dumb protocol transfers copy
full packs rather than just the needed records; this is fixed in bzr.dev
AIUI.

However, this doesn't explain commit performance.

Could you attach the log from your commit please - it will have been
logged to ~/.bzr.log.

What url scheme are you pushing to - sftp? bzr+ssh?
Is your branch a bound branch? (include the output of 'bzr info').

Thanks,
Rob

Also, could you please tell us from which packages you installed bzr?

It's possible some of the Ubuntu packages are missing the compiled extensions though that shouldn't cause more network traffic.

#1: I am not using a bound branch; it is a commit in a branch contained in a shared repository; bzr info:
jal@odeon:~/bzr/vp-3.2-hot$ bzr info -v
Repository tree (format: 1.14-rich-root)
Location:
  shared repository: /home/jal/bzr
  repository branch: .

Related branches:
    push branch: bzr://bzr/vp-3.2-hot/
  parent branch: bzr://bzr/vp-3.2-hot/
  submit branch: /home/jal/bzr/vp-3.1-hot

Format:
       control: Meta directory format 1
  working tree: Working tree format 5
        branch: Branch format 7
    repository: Packs 6 rich-root (uses btree indexes, requires bzr 1.9)

In the working tree:
     12255 unchanged
         0 modified
         0 added
         0 removed
         0 renamed
         0 unknown
        33 ignored
      1201 versioned subdirectories

Branch history:
       870 revisions
       417 days old
   first revision: Thu 2008-06-05 23:32:54 +0200
  latest revision: Mon 2009-07-27 15:56:14 +0200

Repository:
      7072 revisions

As far as I can ascertain this is the commit's log (I will post a new one as soon as I have a slow one again):
Mon 2009-07-27 15:56:13 +0200
0.018 bzr arguments: [u'commit', u'-m', u'MANUAL MERGE due to bazaar bug 405301']
0.027 looking for plugins in /home/jal/.bazaar/plugins
0.068 looking for plugins in /usr/lib/python2.6/dist-packages/bzrlib/plugins
0.086 encoding stdout as sys.stdout encoding 'UTF-8'
0.108 opening working tree '/home/jal/bzr/vp-3.2-hot'
0.127 preparing to commit
0.262 commit parent revision {<email address hidden>}
0.672 Resizing the inventory entry cache from 10240 to 23866
[10986] 2009-07-27 15:56:14.282 INFO: Committing to: /home/jal/bzr/vp-3.2-hot/
0.692 Selecting files for commit with filter []
[10986] 2009-07-27 15:57:40.289 INFO: modified viewpoint/Oracle/views/v_isi_huurontvangsten.vw
[10986] 2009-07-27 15:58:01.876 INFO: modified viewpoint/WebContent/iRed/Bae/Facturatie/Bae_facturenEditPage.jsp
[10986] 2009-07-27 15:58:01.877 INFO: missing viewpoint/WebContent/iRed/Bae/Facturatie/Bae_facturenEditPage.jsp.OTHER
[10986] 2009-07-27 15:58:01.990 INFO: modified viewpoint/WebContent/iRed/Bae/Facturatie/Gen_cst_lookupForm.jsp
[10986] 2009-07-27 15:58:53.199 INFO: modified viewpoint/src/iRed/Bae/Facturatie/bae_betaaltermijnenBean.java
[10986] 2009-07-27 15:58:53.269 INFO: modified viewpoint/src/iRed/Bae/Facturatie/bae_facturenBean.java
[10986] 2009-07-27 15:59:37.749 INFO: Committed revision 870.
204.250 return code 0

This is a branch off a smart server, i.e. it was branched from a bzr:// source but since this is a commit it is NOT using that. If pushed it would also use bzr:// (and push performance is horrible too as mentioned above).

#2: I got bzr 1.17 for free by a regular upgrade of my Ubuntu workstation which has the bzr ppa repo in it's sources.list.

Another commit which took some 200 secs:
Wed 2009-07-29 14:53:03 +0200
0.012 bzr arguments: [u'-Dhpss', u'commit']
0.020 looking for plugins in /home/jal/.bazaar/plugins
0.062 looking for plugins in /usr/lib/python2.6/dist-packages/bzrlib/plugins
0.079 encoding stdout as sys.stdout encoding 'UTF-8'
0.091 opening working tree '/home/jal/bzr/vp-trunk'
0.096 preparing to commit
0.257 commit parent revision {<email address hidden>}
0.798 Resizing the inventory entry cache from 10240 to 28100
[25175] 2009-07-29 14:53:03.840 INFO: Committing to: /home/jal/bzr/vp-trunk/
0.809 Selecting files for commit with filter []
[25175] 2009-07-29 14:54:02.037 INFO: modified viewpoint/.settings/org.eclipse.wst.common.component
[25175] 2009-07-29 14:54:10.646 INFO: modified viewpoint/Oracle/views/w_crm_subjects.vw
[25175] 2009-07-29 14:54:10.649 INFO: modified viewpoint/Oracle/views/w_info_persons.vw
[25175] 2009-07-29 14:54:25.223 INFO: added viewpoint/WebContent/iRed/Bae/Facturatie/Bae_facturenEditPage.jsp
[25175] 2009-07-29 14:55:50.007 INFO: deleted viewpoint/WebContent/iRed/Bae/Facturatie/Bae_facturenEditPage.jsp
167.390 check paths: None
[25175] 2009-07-29 14:56:23.311 INFO: Committed revision 1344.
200.382 return code 0

It was a small commit as far as file sizes are concerned; the status before it was:
jal@odeon:~/bzr/vp-trunk$ bzr status --show-ids -v
removed:
  viewpoint/WebContent/iRed/Bae/Facturatie/Bae_facturenEditPage.jsp bae_factureneditpage-20090415084807-paajk24f7ho20h1l-1
added:
  viewpoint/WebContent/iRed/Bae/Facturatie/Bae_facturenEditPage.jsp bae_factureneditpage-20080605213346-1rfly8x1o30bmnb6-5141
modified:
  viewpoint/.settings/org.eclipse.wst.common.component org.eclipse.wst.comm-20080605213346-1rfly8x1o30bmnb6-799
  viewpoint/Oracle/views/w_crm_subjects.vw w_crm_subjects.vw-20080606080102-52b41ss7rt8mtyjq-758
  viewpoint/Oracle/views/w_info_persons.vw w_info_persons.vw-20080606080102-52b41ss7rt8mtyjq-784
pending merges:
  Frits Jalvingh 2009-07-29 [merge] Fix conflicts where file was deleted/added
    Frits Jalvingh 2009-07-29 [merge] Fix content conflict that would occur EVERY TIME Bae_facturenEditPage.jsp is changed
    Frits Jalvingh 2009-07-29 Minor textual fix to cause a merge content conflict
    Frits Jalvingh 2009-07-29 Change WTP webapp root
    Leo van der Ende 2009-07-28 [merge]
    Leo van der Ende 2009-07-28 xxx

How long does 'bzr st' take in your tree?

-Rob

I did not notice it being very slow. The first time on a freshly booted PC (no cache, linux) it takes about 15 seconds; the second time in the same dir it takes 1 second.

On Wed, 2009-07-29 at 21:44 +0000, Frits Jalvingh wrote:
> I did not notice it being very slow. The first time on a freshly booted
> PC (no cache, linux) it takes about 15 seconds; the second time in the
> same dir it takes 1 second.

How long does
bzr diff -r -2..-1
take?

-Rob

jal@pyramides:~/bzr/vp-split/vp-trunk$ time bzr diff -r -2..-1 >~/x.x

real 0m2.653s
user 0m2.312s
sys 0m0.152s

So, what we know:
 - diff of a historical inventory is ~2 seconds
 - status in the tree is 1-15 seconds.

From the log:
> [25175] 2009-07-29 14:53:03.840 INFO: Committing to: /home/jal/bzr/vp-trunk/

called in the started() reporter method, which is right before

> 0.809 Selecting files for commit with filter []

_update_builder_with_changes

> [25175] 2009-07-29 14:54:02.037 INFO: modified viewpoint/.settings/org.eclipse.wst.common.component

is the first output found and reported, which could be from
_filter_iter_changes or from _record_entry (_populate_from_inventory),
and nearly a minute after the started call.

Some possibilities are:
 - thrashing
 - extremely slow IO
 - extremely slow iter_changes

however, iter_changes is rule out by the stat performance.

So, I'd like to get an lsprof trace.

Can you please start doing your commits thusly;
bzr commit --lsprof-file commit.callgrind commit -m "foo"

This will create a commit.callgrind, and while it doesn't record
wallclock time, if the problem is internal to bzr, we will at least be
able to see the codepaths being used.

Thanks,
Rob

I would be surprised if it was machine IO related since it occurs on many machines (Linux and Windows) suddenly since 1.16, and other IO intensive software (Eclipse on that same ws) is as fast as usual. Trashing would be unlikely as the machine for that report has 6GB memory of which about 3GB were free at the time. I also have a desktop memory/CPU load thingy running all the time and lots of time to look at it while commiting ;-) and it did not do anything special while commiting wrt memory (CPU was up because 1/8 CPU was on 100%).

Is there anything common in the code for pull and commit? Since pull is horrible too.. I cannot really imagine but it is remarkable that both local and remove stuff breaks in the same way in the same version.

I will do the commits as you specified; I assume the syntax would be:
bzr --lsprof-file commit.callgrind commit -m "foo"
instead of the double commit? I will try this tomorrow (1:30am here now) asap. Thanks a lot for your help!

On Wed, 2009-07-29 at 23:40 +0000, Frits Jalvingh wrote:
>
> I will do the commits as you specified; I assume the syntax would be:
> bzr --lsprof-file commit.callgrind commit -m "foo"
> instead of the double commit? I will try this tomorrow (1:30am here
> now) asap. Thanks a lot for your help!

Yes please.

If you have 8 cores and bzr is pegging one core to 100%, then its likely
a bug/corner case.

What is your repository format (bzr info -v will show us)

-Rob

There is a bzr info above here; for the branch I did the tests on here it states:
jal@odeon:~/bzr/vp-trunk$ bzr info -v
Repository tree (format: 1.14-rich-root)
Location:
  shared repository: /home/jal/bzr
  repository branch: .

Related branches:
    push branch: bzr://bzr/vp-trunk/
  parent branch: bzr://bzr/vp-trunk/
  submit branch: /home/jal/bzr/vp-split/vp

Format:
       control: Meta directory format 1
  working tree: Working tree format 5
        branch: Branch format 7
    repository: Packs 6 rich-root (uses btree indexes, requires bzr 1.9)

In the working tree:
     14988 unchanged
         0 modified
         0 added
         0 removed
         0 renamed
         0 unknown
        70 ignored
      1701 versioned subdirectories

Branch history:
      1345 revisions
       419 days old
   first revision: Thu 2008-06-05 23:32:54 +0200
  latest revision: Wed 2009-07-29 15:44:03 +0200

Repository:
      7121 revisions

Ok; got one. Bzr knew I was watching and behaved reasonably well so it took a while. The .bzr.log contains:
Fri 2009-07-31 01:26:35 +0200
0.047 bzr arguments: [u'--lsprof-file', u'/home/jal/commit.callgrind', u'commit', u'-m', u'Merge execom code, incomplete']
0.069 looking for plugins in /home/jal/.bazaar/plugins
0.186 looking for plugins in /usr/lib/python2.6/dist-packages/bzrlib/plugins
0.418 encoding stdout as sys.stdout encoding 'UTF-8'
0.500 opening working tree '/home/jal/bzr/vp-split/vp-trunk'
0.545 preparing to commit
1.122 commit parent revision {<email address hidden>}
3.190 Resizing the inventory entry cache from 10240 to 29920
[30320] 2009-07-31 01:26:38.776 INFO: Committing to: /home/jal/bzr/vp-split/vp-trunk/
3.210 Selecting files for commit with filter []
[30320] 2009-07-31 01:28:36.763 INFO: modified moca.database/src/nl/itris/viewpoint/db/bae/Invoice.java
[30320] 2009-07-31 01:28:36.814 INFO: added moca.database/src/nl/itris/viewpoint/db/bae/InvoiceType.properties
[30320] 2009-07-31 01:28:36.817 INFO: added moca.database/src/nl/itris/viewpoint/db/bae/InvoiceType_en.properties
[30320] 2009-07-31 01:28:36.820 INFO: added moca.database/src/nl/itris/viewpoint/db/bae/Invoice_en.properties
[30320] 2009-07-31 01:33:24.482 INFO: modified viewpoint/src/nl/itris/vp/pages/bae/invoices/PurchaseInvoicesListPage.java
[30320] 2009-07-31 01:33:59.859 INFO: Committed revision 1364.
[30320] 2009-07-31 01:34:00.352 INFO: Profile data written to "/home/jal/commit.callgrind".
444.786 return code 0

While doing this it did a lot of IO.

The callgrind log is attached.

On Thu, 2009-07-30 at 23:38 +0000, Frits Jalvingh wrote:
> Ok; got one. Bzr knew I was watching and behaved reasonably well so it took a while. The .bzr.log contains:
> Fri 2009-07-31 01:26:35 +0200

Thanks for this. Was this the commit of a merge?

Data from the callgrind says it is doing lots of head operations, and is
using the populate-from-inventory codepath, rather than the iter_changes
based code path (because we disable that for older repository formats
with multiple parents in the commit).

What revno is your repository at? (bzr revno).

You can stop doing --lsprof-file now, the data you've gathered is
excellent.

-Rob

Yes, it was a merge and some of the files were altered during the merge (resolve conflicts, fix some layout issues before commiting).

bzr revno: 1364

When you say "multiple parents in the commit" do you mean a merge? Because something special in this repo is that it is has been merged with an earlier unrelated, separate repository with full history. Which cannot be repeated properly because of another bug (bug 364305).

On Fri, 2009-07-31 at 00:39 +0000, Frits Jalvingh wrote:
> Yes, it was a merge and some of the files were altered during the merge
> (resolve conflicts, fix some layout issues before commiting).
>
> bzr revno: 1364
>
> When you say "multiple parents in the commit" do you mean a merge?
> Because something special in this repo is that it is has been merged
> with an earlier unrelated, separate repository with full history. Which
> cannot be repeated properly because of another bug (bug 364305).

Yes, I do.
So, you're on revno 1364. but there are 7K revisions, and 14K files in
the tree.

I think I know the place to look for the regression. I wager that if you
apply the following patch to your bzr, merge commits will be faster for
you:

=== modified file 'bzrlib/commit.py'
--- bzrlib/commit.py 2009-07-15 05:54:37 +0000
+++ bzrlib/commit.py 2009-07-31 03:53:31 +0000
@@ -287,9 +287,7 @@
         self.use_record_iter_changes = (
             not self.specific_files and
             not self.exclude and
- not self.branch.repository._format.supports_tree_reference and
- (self.branch.repository._format.fast_deltas or
- len(self.parents) < 2))
+ not self.branch.repository._format.supports_tree_reference)
         self.pb = bzrlib.ui.ui_factory.nested_progress_bar()
         self.basis_revid = self.work_tree.last_revision()
         self.basis_tree = self.work_tree.basis_tree()

Ok, I did the patch. The first part where it tells you the changes is indeed faster; it is about as fast as status now. But after that it hangs a long time again. The log file is:

Fri 2009-07-31 12:41:45 +0200
0.012 bzr arguments: [u'--lsprof-file', u'/home/jal/commit.callgrind', u'commit', u'-m', u'Merge with trunk of ViewPoint']
0.020 looking for plugins in /home/jal/.bazaar/plugins
0.083 looking for plugins in /usr/lib/python2.6/dist-packages/bzrlib/plugins
0.118 encoding stdout as sys.stdout encoding 'UTF-8'
0.132 opening working tree '/home/jal/bzr/vp-split/vp'
0.147 preparing to commit
[17492] 2009-07-31 12:41:46.146 INFO: Committing to: /home/jal/bzr/vp-split/vp/
0.157 Selecting files for commit with filter []
1.228 Resizing the inventory entry cache from 10240 to 29990
[17492] 2009-07-31 12:41:48.085 INFO: modified moca.database/src/nl/itris/viewpoint/db/hibernate/HibernateUtil.java
[17492] 2009-07-31 12:41:48.086 INFO: added moca.database/src/nl/itris/viewpoint/db/red/DaoViewpointDocument.java
[17492] 2009-07-31 12:41:48.087 INFO: added moca.database/src/nl/itris/viewpoint/db/red/DisBlob.java
[17492] 2009-07-31 12:41:48.087 INFO: modified moca.database/src/nl/itris/viewpoint/db/red/ViewPointDocument.java
[17492] 2009-07-31 12:41:48.122 INFO: modified viewpoint/.settings/org.eclipse.wst.common.component
[17492] 2009-07-31 12:41:48.122 INFO: modified viewpoint/Documentatie/ReleaseNote-3-3.txt
[17492] 2009-07-31 12:41:48.129 INFO: modified viewpoint/Oracle/pck/fin_general.pck
[17492] 2009-07-31 12:41:48.129 INFO: modified viewpoint/Oracle/pck/tda_general.pck
[17492] 2009-07-31 12:41:48.130 INFO: added viewpoint/Oracle/tablechanges/20090728_VOOW_ALTER_FIN_BUDGET_MUTATIES.sql
[17492] 2009-07-31 12:41:48.132 INFO: modified viewpoint/Oracle/triggers/dis_dbb_briu.trg
[17492] 2009-07-31 12:41:48.141 INFO: modified viewpoint/Oracle/views/w_crm_subjects.vw
[17492] 2009-07-31 12:41:48.141 INFO: modified viewpoint/Oracle/views/w_info_persons.vw
[17492] 2009-07-31 12:41:48.159 INFO: modified viewpoint/WebContent/iRed/Bae/Facturatie/Bae_boekingsregelsEditPage.jsp
[17492] 2009-07-31 12:41:48.160 INFO: added viewpoint/WebContent/iRed/Bae/Facturatie/Bae_facturenEditPage.jsp
[17492] 2009-07-31 12:41:48.160 INFO: deleted viewpoint/WebContent/iRed/Bae/Facturatie/Bae_facturenEditPage.jsp
[17492] 2009-07-31 12:41:48.160 INFO: modified viewpoint/WebContent/iRed/Bae/Facturatie/Bae_werkopdrachtenLovPage.jsp
[17492] 2009-07-31 12:41:48.173 INFO: modified viewpoint/WebContent/iRed/Tda/Fin/Npo_procuratie_collectief.jsp
[17492] 2009-07-31 12:41:48.175 INFO: modified viewpoint/WebContent/iRed/Tda/Pmo/Mjb/Pmo_mjb_sheet.js
[17492] 2009-07-31 12:41:48.175 INFO: modified viewpoint/WebContent/iRed/Tda/Pmo/Projects/Pmo_projectenEditPage.jsp
[17492] 2009-07-31 12:41:48.177 INFO: modified viewpoint/WebContent/iRed/Wfl/Dis/Dis_postkamerMenuPage.jsp
[17492] 2009-07-31 12:41:48.178 INFO: modified viewpoint/applet-src/ViewPointWorkflow/ModuleDialog.java
[17492] 2009-07-31 12:41:48.179 INFO: modified viewpoint/applet-src/ViewPointWorkflow/Workflow.java
[17492] 2009-07-31 12:41:48.180 INFO: modified viewpoint/src/Tags/Form/Select_intoGrid.java
[17492] 2009-07-31 12:41:...

And with respect to the revno and the revisions: we merge an awful lot; we have 5 branches in total for 4 supported versions of the product; a fix made in the lowest version merges upward to all higher versions and that happens a lot. I guess this would cause the many revisions? The 14K files is actually small; to be able to use Bazaar we had to remove lots of files from the tree to get it workable, especially under Windows which appearently uses stone tables and blunt tools as a file system.

Thanks for the additional callgrind - very interesting.

I've filed a bug on filter support - filters are causing an early read
and may provoke memory bloat; I don't think that that is your specific
problem, but its worth knowing about so that we can fix it.

30% of the commit time was reading files from disk
60% was doing heads calculations

We read 8521 files from disk, about 400 more than have changed. This may
be a bug in filters causing status to think more things were changed
than were. Or it may be a result of the merge that is taking place. Were
you using filters before you upgraded?

We do 8521 heads heads calculations, which precisely matches the file
count read from disk. This makes me lean towards suspecting the merge
code path.

heads() is fast paths to return immediately if there is only one head.
So bzr thinks that in the merge you are doing:
Working:[parentA, parentB]
there are 8521 files which have different last-changed in parent A and
parent B.

Tell me, do you have a pattern where you repeatedly merge from some
branch B, but never merge back into that branch? Or vice verca -
repeatedly merge into B but never merge from it.

If so, this will slowly accumulate a larger and larger set of differing
last-changed fields, and bzr will be repeatedly checking to see if the
other branch had in fact changed.

The rest of this mail is assuming that you are repeatedly merging from a
branch which is never merged into (or merging into a branch that isn't
merged from).

I wonder/suspect that this is happening as well in the other commit code
path, but I don't know what we changed there to provoke it. Perhaps just
an efficiency bug in the btree support code. (which is where 50% of the
commit time goes).

A few things we can do:
 - stop reading from the local disk when a file not changed from
basis->working tree if we're only examining it due to it showing up in a
basis->merge_parent delta. That will save 25% of the commit time for
you.
 - We could do a merge-basis calculation and discard last-changed fields
  from the source which are not in the set of revisions being merged.
  I'm not sure this would always give correct results - I'm speculating
  about doing it.
 - make heads faster; consider using the graph preprocessing heads
   tool we have now, or tweaking the graph layer more.
 - be more selective about what components of the basis->merge parent
   delta we include *in the case that the content hasn't changed*. Again
   this could lead to incorrect file graphs (failing to converge on
   flip-flop changes on one side), so we'll need to be careful about
   whether, or how, we do this.
 - ???
 - profit.

So, its my weekend now, but I'll spin off a bug for this on Monday
trying to break it down into components, get some info together and see
about a hot fix for you.

-Rob

On Sat, 2009-08-01 at 00:29 +0000, Robert Collins wrote:
>
> We read 8521 files from disk, about 400 more than have changed. This
> may
> be a bug in filters causing status to think more things were changed
> than were. Or it may be a result of the merge that is taking place.
> Were
> you using filters before you upgraded?

I meant 400 times the number that have changed.

> Were you using filters before you upgraded?
No; 1.16 was the 1st version where content filtering was usable. We have now enabled it to handle line endings more properly.

Would it be helpful if I disabled content filtering on my machine for a while?

> Tell me, do you have a pattern where you repeatedly merge from some branch B, but never merge back into that branch?
Yes, totally. As I told above the 5 branches represent different versions. When I fix something in the lowest version it gets merged "upwards" to the newer versions and finally to the trunk branch. Of course we NEVER merge a "higher version" branch to a "lower version" branch for that would make the versions the same - it would merge back all new development done for the higher version. Most of the trouble you see here is from that trunk branch which collected /all/ fixes on /all/ versions below it. This I think also explains the large #of revisions; a single fix merge here contains all of the commit/merge revisions of all lower branches below it.

The part about heads and having to re-check whether (files?) in the other branch had changed is way over my head; I would need to learn your terminology 1st. I am surprised a bit, because I expected merge to only work with the difference in revisions between the two trees, and then only on the files that have changed in those revisions on both sides.

Thanks again for your time and have a good weekend!

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Frits Jalvingh wrote:
>> Were you using filters before you upgraded?
> No; 1.16 was the 1st version where content filtering was usable. We have now enabled it to handle line endings more properly.
>
> Would it be helpful if I disabled content filtering on my machine for a
> while?
>
>> Tell me, do you have a pattern where you repeatedly merge from some branch B, but never merge back into that branch?
> Yes, totally. As I told above the 5 branches represent different versions. When I fix something in the lowest version it gets merged "upwards" to the newer versions and finally to the trunk branch. Of course we NEVER merge a "higher version" branch to a "lower version" branch for that would make the versions the same - it would merge back all new development done for the higher version. Most of the trouble you see here is from that trunk branch which collected /all/ fixes on /all/ versions below it. This I think also explains the large #of revisions; a single fix merge here contains all of the commit/merge revisions of all lower branches below it.
>
> The part about heads and having to re-check whether (files?) in the
> other branch had changed is way over my head; I would need to learn your
> terminology 1st. I am surprised a bit, because I expected merge to only
> work with the difference in revisions between the two trees, and then
> only on the files that have changed in those revisions on both sides.
>
> Thanks again for your time and have a good weekend!
>

So I know the merge code is smart enough to use a basis tree to
determine what has actually changed.

However, I don't think the commit code has that luxury. So imagine a
commit graph that looks something like:

 A
 |\
 B C
 |/|
 D E
 |/|
 F G
 |/|
 H I
 |/
 J

The left side is your latest release branch, and the right side is your
previous release branch. Also, lets assume that changes either need a
little bit of tweaking or that the target file is already slightly
different from the right hand side. What this means is that for the file
modified by C it will be slightly different in D.

So what does this get at. Let's assume there were certain changes, and
I'll classify those as C-files, E-files, G-files and I-files.

Now in I, all C-files will have a last-modified value of C, all E-files
will have a last-modified of E, and so on.

However, because of the "tweaking" that I mentioned, in *H*, all of the
C-files will have a last-modified of *D*, all of the E-files will have a
last-modified of F, etc.

So when we merge I into H to get J, the *merge* code will pick G as the
common base, and try to apply only those changes from G => I to H, which
is what we want.

However, the *commit* code will then need to figure out the per-file
graphs, etc. And what it will see is all of the C-files, E-files,
G-files have different last-modified values between that stored in H and
that stored in I. And it isn't immediately obvious that the value in H
supersedes the value in I. So we have to do a heads() check.

I'm not sure if there is much else that we could do. One argument is
that we could see that the working content is identical to the left
paren...

Thanks for your detailed explanation. It will help me understand Bazaar internals better. I can follow you as far as the last-modified dates are concerned; I understand that in this kind of merge tweaked files have different last-modified values. But tweaked files in a merge would be an exception, not the rule (usually most merges apply cleanly, without conflicts, and we do not do too many changes after that).
But what I gather from your explanation is that merging repeatedly makes more and more files have different last-modified values over time; and this makes commit performance progressively worse over time?

What I do not get is why the commit would have to bother with the c-files at all at the time we're commiting J; the merge for that (and the commit) has already been completed in D; why does the commit on J have to focus on those files again?

I'm losing you at the "heads() check" - no idea what it does ;-) I do understand that at commit time you would need to construct the final delta's for the individual files taking history into account - is this what you call the graphs?

I'd really like to understand the problem but I have very little knowledge of bazaar internals (there is little information to be found). If you have time to explain I'd love it, but feel free to ignore my questions and just tell me what you need to help fixing the problem.

I can do the IRC thing and am comfortable changing the code; I can just setup a copy of the source and tweak that, or change the ubuntu-installed source if that's better. My knowledge of python is less than rudimentary though.
Before we can do this I need to set-up a stable test case as you mentioned - the repository above has already progressed further on. I am trying to create a branch at the same level as the commit here but that is already running for 2 hours and appearently not even close to completion. Is there a special IRC channel and a best time to try to reach you people (please include a timezone so I can translate to time in the Netherlands ;-)?

In addition I'll do some testing using bzr-1.14.1 since I have to prepare moving back to that version in our company (development has come mostly to a standstill because of all the problems with this version). It will give us some comparisons perhaps.

Ok; the commit performance of bzr 1.8 and 1.14.1 is similar on this particular commit as 1.17, so this is not a regression. The other bug (# 405251) is though.

I think we determined that at least part of this was due to problems in committing files in the presence of content filtering, which was fixed in 1.18.1 and 2.0. Are there still other problems here?

Sorry for the late reply; I've been on vacation ;-)
I agree with your analysis.
Because the original repository was damaged beyond repair I've created a fully new repository which currently has only around 100 revisions in 4 branches and do not currently see this problem.
I think this is more-or-less a duplicate of the content-filtering bug.

Thanks for the reply Frits. I'll mark this bug as fix released. Hopefully we can fix the content-filtering bug soon.