git checkout running very slowly (>12s)

git checkout running very slowly (>12s)

[Andrew Cameron]

Some git operations (notably checkouts) are taking a very long time to execute.
Here is a shell session which illustrates the problem.

$ time git branch foo
git branch foo  0.01s user 0.00s system 77% cpu 0.016 total
$ time git checkout foo
Switched to branch 'foo'
git checkout foo  11.73s user 0.18s system 99% cpu 11.937 total
$ time git checkout master
Switched to branch 'master'
git checkout master  11.62s user 0.18s system 99% cpu 11.813 total
$ git count-objects -v
count: 953
size: 527012
in-pack: 153432
packs: 7
size-pack: 1986072
prune-packable: 0
garbage: 0

I tried doing a sparse checkout to eliminate approximately 40,000 files from the 
checkout, and furthermore doing git update-index --skip-worktree on a tree which 
contained about another 16,600 files, but neither had any noticeable effect on 
checkout times.

---
Andrew Cameron

Re: git checkout running very slowly (>12s)

[Andreas Ericsson]

On 06/15/2011 09:30 PM, Andrew Cameron wrote:
> Some git operations (notably checkouts) are taking a very long time to execute.
> Here is a shell session which illustrates the problem.
> 
> $ time git branch foo
> git branch foo  0.01s user 0.00s system 77% cpu 0.016 total

Creating a branch is just a matter of creating a new ref. In this
case, you're doing it on the currently checked out ref. That's a
constant-time operation that is always very quick.

> $ time git checkout foo
> Switched to branch 'foo'
> git checkout foo  11.73s user 0.18s system 99% cpu 11.937 total

If this sequence of commands is accurate, that's a bit weird. If
you've got another branch checked out first and then switch it
would be understandable, considering the size of the repository.
We should probably still do a tree-by-tree comparison to see
which files are changed though, but I thought that's already
done to avoid superfluous work and allow worktree changes to
carry over to other branches. What version of git are you using?

> $ time git checkout master
> Switched to branch 'master'
> git checkout master  11.62s user 0.18s system 99% cpu 11.813 total
> $ git count-objects -v
> count: 953
> size: 527012
> in-pack: 153432
> packs: 7
> size-pack: 1986072
> prune-packable: 0
> garbage: 0
> 

These figures are nowhere near as interesting as those from
  git ls-files | wc -l
after the checkout is completed.

-- 
Andreas Ericsson                   andreas.ericsson@op5.se
OP5 AB                             www.op5.se
Tel: +46 8-230225                  Fax: +46 8-230231

Considering the successes of the wars on alcohol, poverty, drugs and
terror, I think we should give some serious thought to declaring war
on peace.

Re: git checkout running very slowly (>12s)

[Andrew Cameron]

Andreas Ericsson <ae <at> op5.se> writes:

> 
> On 06/15/2011 09:30 PM, Andrew Cameron wrote:
> > Some git operations (notably checkouts) are taking a very long time to 
execute.
> > Here is a shell session which illustrates the problem.
> > 
> > $ time git branch foo
> > git branch foo  0.01s user 0.00s system 77% cpu 0.016 total
> 
> Creating a branch is just a matter of creating a new ref. In this
> case, you're doing it on the currently checked out ref. That's a
> constant-time operation that is always very quick.
> 
> > $ time git checkout foo
> > Switched to branch 'foo'
> > git checkout foo  11.73s user 0.18s system 99% cpu 11.937 total
> 
> If this sequence of commands is accurate, that's a bit weird. If
> you've got another branch checked out first and then switch it
> would be understandable, considering the size of the repository.
> We should probably still do a tree-by-tree comparison to see
> which files are changed though, but I thought that's already
> done to avoid superfluous work and allow worktree changes to
> carry over to other branches. What version of git are you using?

I suppose I forgot to illustrate that, when I created "foo" I was on "master".  
The order branch checkouts was master -> foo -> master, and both transitions 
took ~12s despite pointing to the same commit and using a clean working tree.  I 
imagine you inferred all of that, but if not, now you know.

$ git --version
git version 1.7.0.4

> > $ time git checkout master
> > Switched to branch 'master'
> > git checkout master  11.62s user 0.18s system 99% cpu 11.813 total
> > $ git count-objects -v
> > count: 953
> > size: 527012
> > in-pack: 153432
> > packs: 7
> > size-pack: 1986072
> > prune-packable: 0
> > garbage: 0
> > 
> 
> These figures are nowhere near as interesting as those from
>   git ls-files | wc -l
> after the checkout is completed.
> 

$ git checkout master
Switched to branch 'master'
$ git ls-files | wc -l
90831

Re: git checkout running very slowly (>12s)

[Andrew Cameron]

Andrew Cameron <andrew <at> worksmartlabs.com> writes:

> 
> $ git --version
> git version 1.7.0.4
> 

In the interest of leaving a message of hope in the archives for users 
experiencing this same problem, I will record to the list that I managed to 
solve the problem, if not understand it.  As you can see in the transcript 
above, I had been using an older version of git:

> $ git --version
> git version 1.7.0.4

After running sudo apt-get build-dep git-core and then building git from
source, we see this instead:

> $ git --version
> git version 1.7.5.4

And the success story:

$ time git checkout master
Switched to branch 'master'
git checkout master  0.88s user 0.25s system 99% cpu 1.135 total
$ time git checkout -
Switched to branch 'newbranch'
git checkout -  0.87s user 0.25s system 99% cpu 1.121 total

It might be interesting to note that both before and after upgrading git, 
running "strace -c git checkout master" in an attempt to figure out where all my 
time was spent was *not* particularly helpful.  An excerpt from strace's output 
from before the upgrade:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.003499           0     90884         7 lstat64

And another one from afterwards:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.24    0.003276           0     90886         7 lstat64

In other words, it appears that an efficient lstat implementation was not the 
key factor in this problem.  The root cause remains a mystery, but in my case, 
the solution was to upgrade Git.

Thanks for reading.

Re: git checkout running very slowly (>12s)

[Jeff King]

On Mon, Jun 20, 2011 at 08:26:37PM +0000, Andrew Cameron wrote:

> In other words, it appears that an efficient lstat implementation was not the 
> key factor in this problem.  The root cause remains a mystery, but in my case, 
> the solution was to upgrade Git.

If you can reliably trigger the problem by switching versions and you
are still curious and want to spend a little more time on it, you may be
able to bisect the fix to solve the mystery.

Keep in mind that you are bisecting a fix, not a regression, so your
meanings of "good" and "bad" will be opposite of what you expect. I.e.,
"bad" commits will have the fix, and "good" commits will not (I know
this is confusing; it's an artifact of the way bisect works).

-Peff

Re: git checkout running very slowly (>12s)

[Jeff King]

On Mon, Jun 20, 2011 at 08:44:52PM -0400, Jeff King wrote:

> > In other words, it appears that an efficient lstat implementation
> > was not the key factor in this problem.  The root cause remains a
> > mystery, but in my case, the solution was to upgrade Git.
> 
> If you can reliably trigger the problem by switching versions and you
> are still curious and want to spend a little more time on it, you may
> be able to bisect the fix to solve the mystery.

I was curious, and your issue was easy to replicate, so I bisected it
myself. The fix was:

  commit e53e6b4433f264250c2e586167caf61721b0185c
  Author: Brian Downing <bdowning@lavos.net>
  Date:   Thu Jun 10 21:59:07 2010 -0500

      unpack-trees: Make index lookahead less pessimal

which went into v1.7.1.1.

-Peff

Re: git checkout running very slowly (>12s)

[Andrew Cameron]

On Tue, Jun 21, 2011 at 10:34 AM, Jeff King <peff@peff.net> wrote:

> I was curious, and your issue was easy to replicate, so I bisected it
> myself. The fix was:
>
>  commit e53e6b4433f264250c2e586167caf61721b0185c
>  Author: Brian Downing <bdowning@lavos.net>
>  Date:   Thu Jun 10 21:59:07 2010 -0500
>
>      unpack-trees: Make index lookahead less pessimal
>
> which went into v1.7.1.1.
>
> -Peff
>

You beat me to it.  Thanks for the suggestion and the investigative work!

Andrew