git slow unless piped to cat

git slow unless piped to cat

[Uwe Kleine-König]

Hello,

I have a problem here with git being slow in some situations.
Using git 2.23.0 (from Debian) the effect is:

ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2
tag v5.2
...

real	0m12.727s
user	0m0.300s
sys	0m0.371s

But to get the actual data isn't the problem:

ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2 | cat
tag v5.2
...

real	0m0.764s
user	0m0.014s
sys	0m0.020s

My expectation is that both commands should take approximately the same
amount of time. This is 100% reproducible here.

The backing filesystem could be quicker (don't know, this is xfs in an
logical volume) but this applies to both calls, so this doesn't seem to
be the biggest culprit at least.

This is not a regression, I see similar problems since >2 years. (Didn't
report before because I didn't know such an obvious reproducer.)

Using perf I get in the first case:

   7.99%  git      libz.so.1.2.11      [.] inflate
   3.02%  git      libc-2.28.so        [.] __memcmp_sse4_1
   1.67%  git      [kernel.kallsyms]   [k] __list_del_entry_valid
   1.32%  git      [kernel.kallsyms]   [k] unmap_page_range
   1.25%  git      [kernel.kallsyms]   [k] filemap_map_pages
   ...

while with cat I get:

   3.35%  git      [kernel.kallsyms]  [k] __update_load_avg_cfs_rq
   3.22%  git      [kernel.kallsyms]  [k] update_blocked_averages
   2.37%  git      [kernel.kallsyms]  [k] __list_del_entry_valid
   1.92%  git      [kernel.kallsyms]  [k] hrtimer_interrupt
   1.91%  git      [kernel.kallsyms]  [k] __pagevec_lru_add_fn

It doesn't seem to be related to stdio buffering or coloring as

	stdbuf -o0 git show --no-color v5.2

is slow, too.

Any idea what could be the problem? Is there some info that I might
report additionally to make this better understandable?

Best regards
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

Re: git slow unless piped to cat

[SZEDER Gábor]

On Tue, Aug 27, 2019 at 10:15:59AM +0200, Uwe Kleine-König wrote:
> I have a problem here with git being slow in some situations.
> Using git 2.23.0 (from Debian) the effect is:
> 
> ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2
> tag v5.2
> ...
> 
> real	0m12.727s
> user	0m0.300s
> sys	0m0.371s
> 
> But to get the actual data isn't the problem:
> 
> ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2 | cat
> tag v5.2
> ...
> 
> real	0m0.764s
> user	0m0.014s
> sys	0m0.020s
> 

How does 'git --no-pager show v5.2' perform?  If it's as fast as the
case piping the output to cat, then look into what pager and pager
options you use.

Re: git slow unless piped to cat

[Uwe Kleine-König]

On Tue, Aug 27, 2019 at 10:41:11AM +0200, SZEDER Gábor wrote:
> On Tue, Aug 27, 2019 at 10:15:59AM +0200, Uwe Kleine-König wrote:
> > I have a problem here with git being slow in some situations.
> > Using git 2.23.0 (from Debian) the effect is:
> > 
> > ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2
> > tag v5.2
> > ...
> > 
> > real	0m12.727s
> > user	0m0.300s
> > sys	0m0.371s
> > 
> > But to get the actual data isn't the problem:
> > 
> > ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2 | cat
> > tag v5.2
> > ...
> > 
> > real	0m0.764s
> > user	0m0.014s
> > sys	0m0.020s
> > 
> 
> How does 'git --no-pager show v5.2' perform?  If it's as fast as the
> case piping the output to cat, then look into what pager and pager
> options you use.

	ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git --no-pager show v5.2
	tag v5.2
	...

	real	0m13.225s
	user	0m0.355s
	sys	0m0.336s

So this doesn't seem to be the problem. Also the local configuration
can be ruled out:

	ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time env GIT_CONFIG_NOSYSTEM=1 HOME=/nonexistant XDG_CONFIG_HOME=/nonexistant git --no-pager show --no-color v5.2
	tag v5.2
	...

	real	0m13.587s
	user	0m0.335s
	sys	0m0.336s

Thanks
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

Re: git slow unless piped to cat

[Philipp Zabel]

On Tue, 2019-08-27 at 10:56 +0200, Uwe Kleine-König wrote:
> On Tue, Aug 27, 2019 at 10:41:11AM +0200, SZEDER Gábor wrote:
> > On Tue, Aug 27, 2019 at 10:15:59AM +0200, Uwe Kleine-König wrote:
> > > I have a problem here with git being slow in some situations.
> > > Using git 2.23.0 (from Debian) the effect is:
> > > 
> > > ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2
> > > tag v5.2
> > > ...
> > > 
> > > real	0m12.727s
> > > user	0m0.300s
> > > sys	0m0.371s
> > > 
> > > But to get the actual data isn't the problem:
> > > 
> > > ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2 | cat
> > > tag v5.2
> > > ...
> > > 
> > > real	0m0.764s
> > > user	0m0.014s
> > > sys	0m0.020s
> > > 
> > 
> > How does 'git --no-pager show v5.2' perform?  If it's as fast as the
> > case piping the output to cat, then look into what pager and pager
> > options you use.
> 
> 	ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git --no-pager show v5.2
> 	tag v5.2
> 	...
> 
> 	real	0m13.225s
> 	user	0m0.355s
> 	sys	0m0.336s
> 
> So this doesn't seem to be the problem. Also the local configuration
> can be ruled out:
> 
> 	ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time env GIT_CONFIG_NOSYSTEM=1 HOME=/nonexistant XDG_CONFIG_HOME=/nonexistant git --no-pager show --no-color v5.2
> 	tag v5.2
> 	...
> 
> 	real	0m13.587s
> 	user	0m0.335s
> 	sys	0m0.336s
> 
> Thanks
> Uwe

Have you checked strace output? I see a directory walk through .git/refs
and .git/packed-refs if the output is not redirected.

regards
Philipp

Re: git slow unless piped to cat

[SZEDER Gábor]

On Tue, Aug 27, 2019 at 11:12:06AM +0200, Philipp Zabel wrote:
> On Tue, 2019-08-27 at 10:56 +0200, Uwe Kleine-König wrote:
> > On Tue, Aug 27, 2019 at 10:41:11AM +0200, SZEDER Gábor wrote:
> > > On Tue, Aug 27, 2019 at 10:15:59AM +0200, Uwe Kleine-König wrote:
> > > > I have a problem here with git being slow in some situations.
> > > > Using git 2.23.0 (from Debian) the effect is:
> > > > 
> > > > ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2
> > > > tag v5.2
> > > > ...
> > > > 
> > > > real	0m12.727s
> > > > user	0m0.300s
> > > > sys	0m0.371s
> > > > 
> > > > But to get the actual data isn't the problem:
> > > > 
> > > > ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2 | cat
> > > > tag v5.2
> > > > ...
> > > > 
> > > > real	0m0.764s
> > > > user	0m0.014s
> > > > sys	0m0.020s
> > > > 
> > > 
> > > How does 'git --no-pager show v5.2' perform?  If it's as fast as the
> > > case piping the output to cat, then look into what pager and pager
> > > options you use.
> > 
> > 	ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git --no-pager show v5.2
> > 	tag v5.2
> > 	...
> > 
> > 	real	0m13.225s
> > 	user	0m0.355s
> > 	sys	0m0.336s
> > 
> > So this doesn't seem to be the problem. Also the local configuration
> > can be ruled out:
> > 
> > 	ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time env GIT_CONFIG_NOSYSTEM=1 HOME=/nonexistant XDG_CONFIG_HOME=/nonexistant git --no-pager show --no-color v5.2
> > 	tag v5.2
> > 	...
> > 
> > 	real	0m13.587s
> > 	user	0m0.335s
> > 	sys	0m0.336s
> > 
> > Thanks
> > Uwe
> 
> Have you checked strace output? I see a directory walk through .git/refs
> and .git/packed-refs if the output is not redirected.

That's a good point, 'git show/log' show decorations (refs pointing to
any commits shown) when the output is a terminal:

  $ git show v5.2
  [...]
  commit 0ecfebd2b52404ae0c54a878c872bb93363ada36 (HEAD -> master, tag: v5.2)
  [...]
  $ git show v5.2 |cat
  [...]
  commit 0ecfebd2b52404ae0c54a878c872bb93363ada36
  [...]

And indeed, if you have a lot of refs and cold cache, then that might
account for a couple of seconds difference.  So, how does 'git show
--no-decorate v5.2' perform, and if it performs well, then how many
refs do you have ('git for-each-ref |wc -l')?

Re: git slow unless piped to cat

[Uwe Kleine-König]

On Tue, Aug 27, 2019 at 11:44:07AM +0200, SZEDER Gábor wrote:
> On Tue, Aug 27, 2019 at 11:12:06AM +0200, Philipp Zabel wrote:
> > On Tue, 2019-08-27 at 10:56 +0200, Uwe Kleine-König wrote:
> > > On Tue, Aug 27, 2019 at 10:41:11AM +0200, SZEDER Gábor wrote:
> > > > On Tue, Aug 27, 2019 at 10:15:59AM +0200, Uwe Kleine-König wrote:
> > > > > I have a problem here with git being slow in some situations.
> > > > > Using git 2.23.0 (from Debian) the effect is:
> > > > > 
> > > > > ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2
> > > > > tag v5.2
> > > > > ...
> > > > > 
> > > > > real	0m12.727s
> > > > > user	0m0.300s
> > > > > sys	0m0.371s
> > > > > 
> > > > > But to get the actual data isn't the problem:
> > > > > 
> > > > > ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git show v5.2 | cat
> > > > > tag v5.2
> > > > > ...
> > > > > 
> > > > > real	0m0.764s
> > > > > user	0m0.014s
> > > > > sys	0m0.020s
> > > > > 
> > > > 
> > > > How does 'git --no-pager show v5.2' perform?  If it's as fast as the
> > > > case piping the output to cat, then look into what pager and pager
> > > > options you use.
> > > 
> > > 	ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time git --no-pager show v5.2
> > > 	tag v5.2
> > > 	...
> > > 
> > > 	real	0m13.225s
> > > 	user	0m0.355s
> > > 	sys	0m0.336s
> > > 
> > > So this doesn't seem to be the problem. Also the local configuration
> > > can be ruled out:
> > > 
> > > 	ukl@dude.ptx:/ptx/src/git/linux.git$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time env GIT_CONFIG_NOSYSTEM=1 HOME=/nonexistant XDG_CONFIG_HOME=/nonexistant git --no-pager show --no-color v5.2
> > > 	tag v5.2
> > > 	...
> > > 
> > > 	real	0m13.587s
> > > 	user	0m0.335s
> > > 	sys	0m0.336s
> > > 
> > > Thanks
> > > Uwe
> > 
> > Have you checked strace output? I see a directory walk through .git/refs
> > and .git/packed-refs if the output is not redirected.
> 
> That's a good point, 'git show/log' show decorations (refs pointing to
> any commits shown) when the output is a terminal:
> 
>   $ git show v5.2
>   [...]
>   commit 0ecfebd2b52404ae0c54a878c872bb93363ada36 (HEAD -> master, tag: v5.2)
>   [...]
>   $ git show v5.2 |cat
>   [...]
>   commit 0ecfebd2b52404ae0c54a878c872bb93363ada36
>   [...]

> And indeed, if you have a lot of refs and cold cache, then that might
> account for a couple of seconds difference.  So, how does 'git show
> --no-decorate v5.2' perform, and if it performs well, then how many
> refs do you have ('git for-each-ref |wc -l')?

	$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time env GIT_CONFIG_NOSYSTEM=1 HOME=/nonexistant XDG_CONFIG_HOME=/nonexistant git --no-pager show --no-color --no-decorate v5.2
	...

	real	0m1.041s
	user	0m0.000s
	sys	0m0.021s

	$ git for-each-ref |wc -l
	10013

So this is indeed the problem.

I'm a bit surprised that the default for --decorate depends on the
output being a terminal.

Thanks for your help, I will think about what I want to do. Just using
--no-decorate will work, but isn't nice either. Will test if just
throwing away all those tags from linux-next will make this already
better.

Best regards
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

Re: git slow unless piped to cat

[SZEDER Gábor]

On Tue, Aug 27, 2019 at 12:04:27PM +0200, Uwe Kleine-König wrote:
> I'm a bit surprised that the default for --decorate depends on the
> output being a terminal.

Decorations (and colors as well) are for humans, and humans read the
terminal.

> Thanks for your help, I will think about what I want to do. Just using
> --no-decorate will work, but isn't nice either. Will test if just
> throwing away all those tags from linux-next will make this already
> better.

Note that you can disable decorations by setting the 'log.decorate'
configuration variable to false.

Re: git slow unless piped to cat

[Uwe Kleine-König]

Hello,

On Tue, Aug 27, 2019 at 12:33:09PM +0200, SZEDER Gábor wrote:
> On Tue, Aug 27, 2019 at 12:04:27PM +0200, Uwe Kleine-König wrote:
> > I'm a bit surprised that the default for --decorate depends on the
> > output being a terminal.
> 
> Decorations (and colors as well) are for humans, and humans read the
> terminal.

I agree for colors only. Changing the actually provided information
depending on output being a terminal is IMHO at least surprising.

> > Thanks for your help, I will think about what I want to do. Just using
> > --no-decorate will work, but isn't nice either. Will test if just
> > throwing away all those tags from linux-next will make this already
> > better.
> 
> Note that you can disable decorations by setting the 'log.decorate'
> configuration variable to false.

Being able to configure --decorate-refs= and --decorate-refs-exclude= in
the config would be nice ...

Best regards
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

Re: git slow unless piped to cat

[Michal Suchánek]

On Tue, 27 Aug 2019 12:56:38 +0200
Uwe Kleine-König         <u.kleine-koenig@pengutronix.de> wrote:

> Hello,
> 
> On Tue, Aug 27, 2019 at 12:33:09PM +0200, SZEDER Gábor wrote:
> > On Tue, Aug 27, 2019 at 12:04:27PM +0200, Uwe Kleine-König wrote:  
> > > I'm a bit surprised that the default for --decorate depends on the
> > > output being a terminal.  
> > 
> > Decorations (and colors as well) are for humans, and humans read the
> > terminal.  
> 
> I agree for colors only. Changing the actually provided information
> depending on output being a terminal is IMHO at least surprising.
> 
> > > Thanks for your help, I will think about what I want to do. Just using
> > > --no-decorate will work, but isn't nice either. Will test if just
> > > throwing away all those tags from linux-next will make this already
> > > better.  
> > 
> > Note that you can disable decorations by setting the 'log.decorate'
> > configuration variable to false.  
> 
> Being able to configure --decorate-refs= and --decorate-refs-exclude= in
> the config would be nice ...

The question is if excluding some will speed things up. Depending on
the way they are stored and looked up to match to the commit at hand
this might not be a big win.

Thanks

MIchal

Re: git slow unless piped to cat

[Jeff King]

On Tue, Aug 27, 2019 at 12:04:27PM +0200, Uwe Kleine-König wrote:

> 	$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time env GIT_CONFIG_NOSYSTEM=1 HOME=/nonexistant XDG_CONFIG_HOME=/nonexistant git --no-pager show --no-color --no-decorate v5.2
> 	...
> 
> 	real	0m1.041s
> 	user	0m0.000s
> 	sys	0m0.021s
> 
> 	$ git for-each-ref |wc -l
> 	10013
> 
> So this is indeed the problem.

That's not that many refs. Are they mostly unpacked? Loose refs are
awful on a cold cache, since it's one inode per ref (or worse, since it
has walk the directories, too).

Try:

  find .git/refs -type f | wc -l

to see the loose ones. If there are a lot, try:

  git pack-refs --prune --all

(or just "git gc", which does this).

Modern versions of Git should delete any leftover empty directories
after pruning the loose variants, but I think won't go out of their way
to remove ones they didn't delete from. And those are still expensive to
walk on a cold cache. If it's still slow, try:

  find .git/refs/* -type d | xargs rmdir -v

-Peff

Re: git slow unless piped to cat

[Uwe Kleine-König]

On Tue, Aug 27, 2019 at 02:59:30PM -0400, Jeff King wrote:
> On Tue, Aug 27, 2019 at 12:04:27PM +0200, Uwe Kleine-König wrote:
> 
> > 	$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time env GIT_CONFIG_NOSYSTEM=1 HOME=/nonexistant XDG_CONFIG_HOME=/nonexistant git --no-pager show --no-color --no-decorate v5.2
> > 	...
> > 
> > 	real	0m1.041s
> > 	user	0m0.000s
> > 	sys	0m0.021s
> > 
> > 	$ git for-each-ref |wc -l
> > 	10013
> > 
> > So this is indeed the problem.
> 
> That's not that many refs. Are they mostly unpacked? Loose refs are
> awful on a cold cache, since it's one inode per ref (or worse, since it
> has walk the directories, too).
> 
> Try:
> 
>   find .git/refs -type f | wc -l

ukl@dude.ptx:/ptx/src/git/linux.git$ find refs -type f | wc -l 
2874

(Note this is a bare repository. So I used refs instead of .git/refs.)

> to see the loose ones. If there are a lot, try:
> 
>   git pack-refs --prune --all
> 
> (or just "git gc", which does this).

This is a daily updated mirror that is also incrementally backed up. I
repack from time to time, but hesitate to do this regularily as each
time I repack the next backup run is "expensive" and I get many small
packs. I did this now anyhow.

After that I have:

	$ find objects/[0-9a-f][0-9a-f] -type f | wc -l
	166
	$ find objects/pack | wc -l
	98

> Modern versions of Git should delete any leftover empty directories
> after pruning the loose variants, but I think won't go out of their way
> to remove ones they didn't delete from. And those are still expensive to
> walk on a cold cache. If it's still slow, try:
> 
>   find .git/refs/* -type d | xargs rmdir -v

There were a few:

$ find refs/ -depth -type d -empty -print -delete | wc -l
147

(Oops, after the repacking above this also removed ./refs which I had to
restore to make git recognize this as a repository.)

With these two things done it is a bit faster:

	$ sudo sh -c "echo 3 > /proc/sys/vm/drop_caches"; time env GIT_CONFIG_NOSYSTEM=1 HOME=/nonexistant XDG_CONFIG_HOME=/nonexistant git --no-pager show --no-color v5.2 
	tag v5.2

	...
	real	0m11.022s
	user	0m0.321s
	sys	0m0.248s

Best regards
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

Re: git slow unless piped to cat

[Bryan Turner]

On Tue, Aug 27, 2019 at 2:32 PM Uwe Kleine-König
<u.kleine-koenig@pengutronix.de> wrote:
>
> On Tue, Aug 27, 2019 at 02:59:30PM -0400, Jeff King wrote:
> > On Tue, Aug 27, 2019 at 12:04:27PM +0200, Uwe Kleine-König wrote:
> >
> > to see the loose ones. If there are a lot, try:
> >
> >   git pack-refs --prune --all
> >
> > (or just "git gc", which does this).
>
> This is a daily updated mirror that is also incrementally backed up. I
> repack from time to time, but hesitate to do this regularily as each
> time I repack the next backup run is "expensive" and I get many small
> packs. I did this now anyhow.

Just noting that Jeff didn't suggest a repack; he suggested a
pack-refs. This should have little, if any impact on your backup
processing, because all it's going to do is rewrite the "packed-refs"
file and delete loose refs. It doesn't modify any files under objects/
at all.

Bryan

Re: git slow unless piped to cat

[Uwe Kleine-König]

Hello,

On Tue, Aug 27, 2019 at 02:38:57PM -0700, Bryan Turner wrote:
> On Tue, Aug 27, 2019 at 2:32 PM Uwe Kleine-König
> <u.kleine-koenig@pengutronix.de> wrote:
> >
> > On Tue, Aug 27, 2019 at 02:59:30PM -0400, Jeff King wrote:
> > > On Tue, Aug 27, 2019 at 12:04:27PM +0200, Uwe Kleine-König wrote:
> > >
> > > to see the loose ones. If there are a lot, try:
> > >
> > >   git pack-refs --prune --all
> > >
> > > (or just "git gc", which does this).
> >
> > This is a daily updated mirror that is also incrementally backed up. I
> > repack from time to time, but hesitate to do this regularily as each
> > time I repack the next backup run is "expensive" and I get many small
> > packs. I did this now anyhow.
> 
> Just noting that Jeff didn't suggest a repack; he suggested a
> pack-refs. This should have little, if any impact on your backup
> processing, because all it's going to do is rewrite the "packed-refs"
> file and delete loose refs. It doesn't modify any files under objects/
> at all.

Ah, right. That also explains why I still had a few loose objects. I
cut-n-pasted the command, so I did as suggested, just thought it was
something different.

Thanks
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |