Commit/push to SVN repo takes 50 seconds

Bug #849087 reported by Gordon Tyler on 2011-09-13
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Bazaar Subversion Plugin
Medium
Unassigned

Bug Description

As my SVN repo has gotten larger and larger (more revisions), commits/pushes to the SVN repo from a local bzr branch have become slower and slower, currently around 50 seconds. A similar commit to the same repo using the SVN client takes about 2 seconds. The SVN repo has 155000 revisions across a variety of projects. It's hosted on the same LAN as the client.

Here's the log snippet from a recent commit (via the bzr4j plugin for IntelliJ IDEA):

Tue 2011-09-13 11:10:46 -0400
0.048 bazaar version: 2.4.0
0.048 bzr arguments: [u'commit', u'--no-aliases', u'-F', u'C:\\Users\\gtyler\\.IntelliJIdea10\\system\\.bzr4intellij-commit.tmp', u'build.xml']
0.073 looking for plugins in C:/Users/gtyler/AppData/Roaming/bazaar/2.0/plugins
0.076 looking for plugins in C:/Program Files (x86)/Bazaar2.4/plugins
0.077 Plugin name colo already loaded
0.108 encoding stdout as osutils.get_user_encoding() 'cp1252'
0.138 opening working tree 'C:/dev/JMXCartridge'
0.190 bzr-svn: using Subversion 1.6.6 (), subvertpy 0.8.0
0.296 preparing to commit
[ 8564] 2011-09-13 11:11:01.454 INFO: Committing to: http://torsvn/repos/Cartridges/JMXCartridge/trunk
14.956 Selecting files for commit with filter [u'build.xml']
[ 8564] 2011-09-13 11:11:01.460 INFO: modified build.xml
15.376 pushing '<email address hidden>' (['<email address hidden>'])
15.661 open file 'build.xml'
19.258 expand branches: [], ['Cartridges', 'JMXCartridge', 'tags', '*']
19.258 expand branches: ['Cartridges'], ['JMXCartridge', 'tags', '*']
19.258 expand branches: ['Cartridges', 'JMXCartridge'], ['tags', '*']
19.258 expand branches: ['Cartridges', 'JMXCartridge', 'tags'], ['*']
19.309 expand branches: [], ['Cartridges', 'JMXCartridge', 'tags', '*']
19.309 expand branches: ['Cartridges'], ['JMXCartridge', 'tags', '*']
19.309 expand branches: ['Cartridges', 'JMXCartridge'], ['tags', '*']
19.310 expand branches: ['Cartridges', 'JMXCartridge', 'tags'], ['*']
[ 8564] 2011-09-13 11:11:36.086 INFO: Committed revision 1128.
49.588 Committed revid <email address hidden> as revno 1128.
49.645 return code 0

Jelmer Vernooij (jelmer) wrote :

Can you run this with --lsprof --lsprof-file=foo.txt, and share foo.txt ?

Gordon Tyler (doxxx) wrote :

lsprof.txt produced with: bzr commit --lsprof -m "..." > lsprof.txt

Gordon Tyler (doxxx) wrote :

lsprof2.txt produced with: bzr commit --no-aliases --lsprof -m "..." cartridge/src/main/config/scripts-monitoring-policy.xml > lsprof2.txt

Gordon Tyler (doxxx) wrote :

I couldn't get the --lsprof-file option to work. bzr complained that there was no such option. I'm running bzr 2.4.0 on Windows, if that makes any difference.

Neither of these two commits took as long as I expected, about 30 seconds each. A commit earlier this morning took 70 seconds. Unfortunately I didn't have the lsprof option enabled then.

Jelmer Vernooij (jelmer) wrote :

IIRC --lsprof-file requires a = to be used, it doesn't work with a space.

Jelmer Vernooij (jelmer) wrote :

It looks like the sqlite cache is taking up most of the time, I don't know why it needs so much log analysis though.

What version of bzr-svn are you running?

Changed in bzr-svn:
status: New → Triaged
importance: Undecided → Medium
Gordon Tyler (doxxx) wrote :

I'm using the version that's bundled with the bzr 2.4.0 windows installer. Looks like 1.1.0?

Gordon Tyler (doxxx) wrote :

I've also noticed that updates (i.e. 'bzr up') are taking quite a while now and there's a LOT of disk activity, disproportional to the actual amount of change. Most of the time seems to be spent reading the revisions between the one that's on my disk and the most recent revision on the server. It takes a few seconds to read each revision and it seems to be reading every revision in that range regardless of which part of the repo each revision affects, even revisions which don't affect what I have checked out.

Can I do something to reset the sqlite cache maybe?

Gordon Tyler (doxxx) wrote :

BTW, regarding the lsprof-file option, this is what I tried:

C:\dev\JMXCartridge>bzr --lsprof --lsprof-file=lsprof3.txt up
bzr: ERROR: unknown command "--lsprof-file=lsprof3.txt"

Gordon Tyler (doxxx) wrote :

But I just tried leaving out the '=' and that actually worked!

Gordon Tyler (doxxx) wrote :

lsprof output for 'bzr up' when there are changes in the remote svn branch to fetch.

Corresponding bzr.log snippet:

Fri 2011-09-23 11:27:20 -0400
0.046 bazaar version: 2.4.0
0.046 bzr arguments: [u'--lsprof', u'--lsprof-file', u'lsprof3.txt', u'up']
0.051 looking for plugins in C:/Users/gtyler/AppData/Roaming/bazaar/2.0/plugins
0.052 looking for plugins in C:/Program Files (x86)/Bazaar2.4/plugins
0.101 encoding stdout as sys.stdout encoding 'cp437'
0.139 opening working tree 'C:/dev/JMXCartridge'
0.287 bzr-svn: using Subversion 1.6.6 (), subvertpy 0.8.0
68.872 Packing repository GCRepositoryPackCollection(CHKInventoryRepository('file:///C:/dev/JMXCartridge/.bzr/branches/.bzr/repository/')), which has 8 pack files, containing 1207 revisions with hint ['893baaf65a854f46a761248952f0cc5c'].
68.873 repacking 2 revisions
68.877 repacking 2 inventories
68.880 repacking chk: 2 id_to_entry roots, 2 p_id_map roots, 24 total keys
68.893 repacking 17 texts
68.948 repacking 0 signatures
<SNIP FILE LISTING>
[ 7824] 2011-09-23 11:28:30.030 INFO: All changes applied successfully.
[ 7824] 2011-09-23 11:28:30.039 INFO: Updated to revision 1171 of branch http://torsvn/repos/Cartridges/JMXCartridge/trunk
69.715 Transferred: 131kB (1.9kB/s r:1kB w:1kB u:129kB)
[ 7824] 2011-09-23 11:28:30.275 INFO: Profile data written to "lsprof3.txt".
69.887 return code 0

On 09/23/2011 05:42 AM, Gordon Tyler wrote:
> I've also noticed that updates (i.e. 'bzr up') are taking quite a while
> now and there's a LOT of disk activity, disproportional to the actual
> amount of change. Most of the time seems to be spent reading the
> revisions between the one that's on my disk and the most recent revision
> on the server. It takes a few seconds to read each revision and it seems
> to be reading every revision in that range regardless of which part of
> the repo each revision affects, even revisions which don't affect what I
> have checked out.
>
> Can I do something to reset the sqlite cache maybe?
>
Resetting the sqlite cache won't really help, the question is why it's
looking in the sqlite cache so much.

It would be really useful to see the cachegrind lsprof output, so we can
see what is calling sqlite so much; I suspect you need to have the
--lsprof-file parameter working for that though.

Cheers,

Jelmer

Gordon Tyler (doxxx) wrote :

Well it looks like I have the lsprof-file option working so next commit I'll try to remember to do it with a cachegrind file instead.

Gordon Tyler (doxxx) wrote :

Attached lsprof callgrind file for a commit.

Jelmer Vernooij (jelmer) wrote :

It looks like almost all time is spent updating tags. Do you have branch.fetch_tags enabled?

Gordon Tyler (doxxx) wrote :

Maybe. I don't recall enabling it specifically, but I may have done so some time ago and forgotten. I'll check on Monday. I know I do have a tag somewhere in the history but I don't use them anymore.

Gordon Tyler (doxxx) wrote :

I don't appear to have fetch_tags enabled:

C:\dev\JMXCartridge>bzr config
branch:
  parent_location = http://torsvn/repos/Cartridges/JMXCartridge/trunk
  commit_data = {}

Is there some place else that I should be checking?

Gordon Tyler (doxxx) wrote :

Is there any other information you need from me?

Jelmer Vernooij (jelmer) wrote :

no, I just need some time to look into this...

Gordon Tyler (doxxx) wrote :

I think this is related to bug 882388 and bug 882917.

Jelmer Vernooij (jelmer) on 2011-11-11
tags: added: performance
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers