Hg Workbench is very slow

Issue #3834 open
FoxHole
created an issue

My Hg Workbench is sometimes very slow. I am under windows7, using last version of Tortoise Hg. I have several large repositories being tracked by Hg locally For example, I have one repository that

  • has been converted from CVS using cvs2hg (from svn2hg)
  • has more than 7000 changesets
  • is more than 1GB heavy
  • uses extensions largefiles, hgk, mercurial_keyring
  • has several binary files being tracked as large files
  • has a few binary files not tracked as large files( including one file of 300 MB)

With this repo, it can take

  • from 10 seconds, up to 30 seconds to open the repository
  • from 3 seconds, up to 10 seconds to change a changeset

and sometimes, doing a filter in the changeset list or doing a diff with local from an old revision can take several minutes.

Note 1 : This is the case for all the team (approx 10 people) using this repository, not only on my PC

Note 2 : in the past, it was even much much longer but that was due to the collumn "Changes" being displayed. Now, I removed it and it is not as bad but far from good anyway.

Note 3 : this repos has been cloned from a RhodeCode server but the problem is in local configuration, not during push or pull operation, so I think it is not related.

Note 4 : after cvs2hg conversion, I had a problem of End Of Line (I had been unable to make EOL conversion to work properly with the convertor, I don't know why). So after the conversion, I had to apply a EOL conversion on all my text files, to commit and to push. That made quite a big changeset which affected everyline of every text file. I am not sure this could be the reason for my problem because as far as I remember, it was already slow before this conversion, but I prefered to notice it anyway.

In any cases, this slowness comes from the workbench itself : when I browse the repository on the rhodecode server, it is not slow (or far to be so slow).

The main problem is that I have been pushing for several monthes to switch from cvs to mercurial and as it is slow, I am afraid my boss wants to revert back to cvs ... that is why I set the priority to Critical.

1/ Do you think my pb comes from a bug (or a lack of optimzation) inside the workbench or is it the result of something I did (in which case there would be no issue)

2/ Is there a way I could have a profile log or even a general log that could give me information about what is taking so long ?

Tell me if you need any other information, or if I can help in any way to make things move forward on this issue

Thanks in advance

Antoine

Comments (15)

  1. Yuya Nishihara
    • marked as major
    • edited description

    ~7000 changesets are not large. How many files does that repository have?

    • from 3 seconds, up to 10 seconds to change a changeset

    It seems terribly slow.

    If "tree view" is enabled, try disabling it from file list context menu -> List Options -> [v] Flat List.

    1/ Do you think my pb comes from a bug (or a lack of optimzation) inside the workbench or is it the result of something I did (in which case there would be no issue)

    Partly it is due to inefficient code in TortoiseHg, but I'm not sure how bad it is.

    2/ Is there a way I could have a profile log or even a general log that could give me information about what is taking so long ?

    You can guess it by running equivalent command. For example,

    • hg log -G
    • hg log -G -r REVSET
    • hg status --change REV
    • hg diff -c REV
    • hg --config extensions.extdiff extdiff -p COMMAND

    Also, consider trying another GUI client, e.g. SourceTree, if you need immediate solution.

  2. FoxHole reporter

    The repository includes approximattly 25000 files. Most of them are txt files (.c, .cpp, .h, .rc, .mak, .txt ....) some of them are small binary files (graphical assets). One of them is a large (300 MB) files not declared as Large File

    The TreeView is not enabled in the list : I am all the time in Flat View

  3. Yuya Nishihara

    The repository includes approximattly 25000 files. Most of them are txt files

    ~25000 aren't small, but generally it won't take 3 seconds to show single changeset.

    http://selenic.com/repo/linux-2.6/ contains ~40000 files, but it just took ~100msec to switch revisions.

    One of them is a large (300 MB) files not declared as Large File

    It will consume ~1GB RAM to manage that file. But I don't think it affects to unrelated revisions.

  4. C

    I'm having similar problems. My repository is ~30k commits, ~33k files, and the .hg dir is about 1.4 GiB. All of this started with version 3.1 for me.

    The two cases I most commonly see the painful slowness are:

    • Navigating commits clicking the parent/child links

    • Starting a pull operation

    Both of these happen with all extensions disabled. The first is a bit "titchy" ... it seems to be heavily influenced by disk cache. Writing to /proc/sys/vm/drop_caches will make it happen every time though.

    The second happens the first time I open a repo, but I can close a repo and re-open it, without restarting the workbench, and the slowness will come back. It often takes ~10 seconds from clicking the "Check for incoming changes" button before the green "Getting incoming changes..." bar shows. If I click it again, it's "normal speed" however, until I close the repo.

    That this all started in 3.1, and the close/reopen repo behavior, makes me suspicious that it might have something to do with the command server mode, but that's pure speculation on my part.

  5. Yuya Nishihara

    Navigating commits clicking the parent/child links

    It might be caused by the change of the view class in TortoiseHg, or some changes in Mercurial core.

    Starting a pull operation

    I don't think it is related to command server, but it could be if your machine doesn't have enough RAM to spawn new command-server process.

    ~10 seconds [...] before the green "Getting incoming changes..." bar

    "Getting incoming changes" is sent before starting command.

    Just in case, can you try without command server?

    % THGDEBUG=1 thg --config tortoisehg.cmdworker=thread --nofork
    

    Also, can you try both with Mercurial 3.0.x?

    % hg clone http://selenic.com/repo/hg#3.0.2 hg-3.0.2
    % make -C hg-3.0.2 local
    % HGPATH=$PWD/hg-3.0.2 PATH=$PWD/hg-3.0.2:$PATH thg --nofork
    

    Other possible tune-up point

    • --config tortoisehg.graphlimit=100 (Settings -> Log Batch Size)
    • hide "Changes" column (View -> Choose Log Columns; default)
    • disable tree file view (context menu of file list -> Flat List; default)
  6. C

    Thanks for your suggestions.

    Simple things first:

    hide "Changes" column (View -> Choose Log Columns; default)

    There is no "default" button in that window, just the list of columns and OK/Cancel buttons. I don't have the Changes column enabled, though. My columns are: Graph, Rev, Branch, Description, Author, Age, Node.

    disable tree file view (context menu of file list -> Flat List; default)

    That's my default. I occaisonally enable the tree view for inspecting something specific, but Flat is my normal mode.

    --config tortoisehg.graphlimit=100 (Settings -> Log Batch Size)

    No effect on the lag starting a pull operation

    % THGDEBUG=1 thg --config tortoisehg.cmdworker=thread --nofork

    Also no effect on pull lag. However there are some "interesting" messages it puts out. On each step that has a lag, I see a message like this just after the lag ends:

    GarbageCollector.check: 39213 2 5
    collected gen 0, found 47 unreachable
    

    The numbers of course vary each time, but the scale of the numbers stays about the same. Occaisonally there is a message about gen 1 as well, but mainly just gen 0.

    Finally, downgrading mercurial to 3.0.2, but leaving tortoisehg at 3.1, everything behaved the same. Also downgrading tortoisehg to 3.0 made things much snappier. There was still a tiny lag followed by the GarbageCollector output, but it was much much shorter. Finally, bringing mercurial back up to 3.1 and leaving tortoisehg at 3.0 ,the same improved performance was seen.

    So, it seems like this is related to something in tortoisehg in the garbage collection. Pointers on how to continue narrowing this down are welcome :)

  7. Yuya Nishihara
    • changed status to open

    There is no "default" button in that window

    Oops, I wanted to say that "Changes" column is hidden by default.

    --config tortoisehg.cmdworker=thread [...] Also no effect

    So command server is not guilty.

    it seems like this is related to something in tortoisehg in the garbage collection.

    Probably it isn't true. GC won't take 10sec, it should finish in 1-100msec in general.

    Can you check if the slowness is CPU-related or disk-related?

    And is the GUI responsive during that ~10sec?

  8. C

    The GUI is not responsive during those 10 seconds. The "check for incoming changes" toolbar button that I click to trigger this remains in the depressed state, and leaves that state at the same time as the ui becomes responsive again and the green bar appears.

    I'll get back to you on CPU vs. IO bound. I doubt it's I/O bound as this is all on a very fast SSD. Also command line hg operations on this repo are not slow.

  9. C

    It's definitely not I/O bound. Watching the thg process with iotop shows that it's doing no I/O at all for most of that ~10 seconds. There's a tiny bit (tens of kbytes) when I first click the button, and then nothing for the laggy period, and then when the UI un-blocks it starts doing the expected amounts of I/O for the hg in it's doing behind the scenes.

    Monitoring thg with top -d 0.5 -p $(pidof -x thg) -b shows two potentially interesting things:

    1. thg has one CPU pegged during the lag
    2. The lag happens before the hg cmdserver is started. End of the lag coincides with starting the cmdserver.
  10. C

    Did some googling on how to profile python code and came up with this. Hope it helps :)

    I ran python -m cProfile /usr/bin/thg and then did the following steps in the UI:

    • Opened the "problem" repository
    • Clicked the "check for incoming changes" button
      • This produced a chunk of UI-unresposive lag
    • The "Foud 2 incoming changesets" banner appeared
      • There was another chunk of UI-unresponsive lag after the banner appeared but before the changeset list was updated to show them
    • Clicked "Accept"
    • Waited for the pull to finish, and then closed thg

    The profiler out put is rather large, so I've stuck it here: http://pastebin.com/mXXMY710 -- after scrolling through it all (since I didn't google far enough for how to get it to sort the results when called this way), the offender sticks out like a sore thumb:

       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        32413   46.693    0.001   72.507    0.002 hglib.py:100(branchheads)
    

    This repo is both branch crazy, and virtually no branch is ever properly closed:

    $ hg heads | grep ^changeset: | wc -l
    8187
    $ hg heads --topo | grep ^changeset: | wc -l
    2420
    $ hg branches | wc -l
    8095
    $ hg branches --closed | wc -l
    8855
    

    However it looks like part of the problem might be as much the number of hits to the branchheads function as the number of branches/heads it needs to process.

  11. Yuya Nishihara

    @C Thanks, confirmed the problem with 10000 branches.

    Can you create new issue for it? It's probably unrelated to the original report.

    https://bitbucket.org/tortoisehg/thg/issues/new

    Here's a hotfix only for this problem:

    --- a/tortoisehg/hgqt/sync.py
    +++ b/tortoisehg/hgqt/sync.py
    @@ -245,7 +245,7 @@ class SyncWidget(QWidget, qtlib.TaskWidg
                 self.targetcombo.addItem(_('branch: ') + uname, ('--branch', name))
                 self.targetcombo.setItemData(self.targetcombo.count() - 1, name,
                                              Qt.ToolTipRole)
    -            if ctx.thgbranchhead() and name == ctx.branch():
    +            if name == ctx.branch() and ctx.thgbranchhead():
                     selIndex = self.targetcombo.count() - 1
             for name in self.repo._bookmarks.keys():
                 uname = hglib.tounicode(name)
    
  12. Log in to comment