git@vger.kernel.org list mirror (unofficial, one of many)
 help / color / mirror / code / Atom feed
* High locking contention during repack?
@ 2018-12-12  3:01 Iucha, Florin
  2018-12-12 11:24 ` Jeff King
  0 siblings, 1 reply; 9+ messages in thread
From: Iucha, Florin @ 2018-12-12  3:01 UTC (permalink / raw)
  To: git


Greetings,

 

I am running “git-repack  -A -d -f -F --window=250 --depth=250” on a Git repository converted using git-svn.

 

The repository contains more than 10 years of development, and a mixture of source code and media assets. The size of the objects directory is around 50GB, and there are around 700k objects. There are several svn branches.

 

I have ran the repack with Git 2.17.1 (original package from Ubuntu 18.04), 2.19.1 (package from Ubuntu Git PPA) and with git next (bc1bbc6f855c3b5ef7fcbd0f688f647c4e5b208b).

 

The system is a 16 core / 32 thread Threadripper with 128GB of RAM and NVMe storage. The repack starts strong, with 32 threads but it fairly quickly gets to 99% done and the number of threads drops to 4 then 3 then 2. However, running “dstat 5” I see lots of “sys” time without any IO time (the network traffic you see is caused by SSH).

 

 

--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw
24  24  48   4   0|   0     0 | 362B 8392B|   0     0 |  64k 5042
27  25  44   4   0|   0     0 | 289B 4830B|   0     0 |  36k 5017
24  24  48   4   0|   0     0 | 362B 8392B|   0     0 |  64k 5042
27  25  44   4   0|   0     0 | 289B 4830B|   0     0 |  36k 5017
20  22  54   4   0|   0     0 | 330B 4826B|   0     0 |  31k 4657
22  23  51   3   0|   0     0 | 286B 4834B|   0     0 |  27k 4536
17  23  56   4   0|   0     0 | 299B 4820B|   0     0 |  29k 4099
24  23  49   4   0|   0     0 | 347B 4830B|   0     0 |  32k 4436
27  24  45   4   0|   0     0 | 292B 4820B|   0     0 |  22k 4513
26  27  44   3   0|   0     0 | 292B 4820B|   0     0 |  24k 4878
25  28  44   4   0|   0     0 | 329B 4837B|   0     0 |  45k 5023
23  30  44   3   0|   0  9830B| 370B 4836B|   0     0 |  40k 5064
23  26  47   4   0|   0     0 | 373B 4848B|   0     0 |  52k 4746
25  26  45   4   0|   0     0 | 323B 4833B|   0     0 |  31k 4874
24  28  45   3   0|   0     0 | 269B 4842B|   0     0 |  30k 4820
25  28  43   4   0|   0     0 | 280B 4826B|   0     0 |  45k 5237
25  29  43   3   0|   0     0 | 263B 4826B|   0     0 |  26k 5037
22  30  45   4   0|   0     0 | 287B 4823B|   0     0 |  45k 4154
  0  53  42   5   0|   0     0 | 275B 1210B|   0     0 |5017  1331
  0  53  42   5   0|   0     0 |  97B    0 |   0     0 |5006  1272
  0  53  42   5   0|   0     0 |  70B    0 |   0     0 |5008  1272
  0  53  42   5   0|   0     0 |  24B    0 |   0     0 |5007  1283
11  43  43   4   0|   0     0 | 644B   19k|   0     0 |  20k 2995
25  28  43   4   0|   0   123k| 304B 4802B|   0     0 |  29k 5118
25  27  44   4   0|   0     0 | 297B 4800B|   0     0 |  41k 5121
26  27  43   4   0|   0     0 | 320B 4786B|   0     0 |  29k 4973
22  30  44   3   0|   0     0 | 332B 4786B|   0     0 |  32k 4610
24  27  46   3   0|   0     0 | 296B 4786B|   0     0 |  56k 4632
35  17  44   3   0|   0     0 | 292B 4776B|   0     0 | 100k 4889
34  20  43   4   0|   0  9830B| 610B 4820B|   0     0 |  59k 4811


This when it gets to two threads phase:

  1  40  59   0   0|   0    38k| 373B 2458B|   0     0 |  50k 2874
  0  40  59   0   0|   0     0 | 268B 2892B|   0     0 |  10k 2858
  0  40  59   0   0|   0     0 | 299B 3102B|   0     0 |8392  2919
  1  40  59   0   0|   0     0 | 297B 3176B|   0     0 |  21k 2831
  0  40  59   0   0|   0     0 | 281B 3414B|   0     0 |9192  2856
  1  40  59   0   0|   0     0 | 264B 3493B|   0     0 |  17k 2905
  1  40  59   0   0|   0    35k| 340B 3571B|   0     0 |  13k 2885

 

The repack still progresses, as I see the count of repacked objects being incremented every several minutes. But I suspect there is some terrible lock contention, because otherwise I can’t explain the high system usage with no IO.

 

Running a strace on the running git-repack process shows only these:
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---

 

Any idea on how to debug this? I have ran git-repack under gdb, but it seems to spin on builtin/repack.c line 409.
 

Thank you for Git,

florin

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: High locking contention during repack?
  2018-12-12  3:01 High locking contention during repack? Iucha, Florin
@ 2018-12-12 11:24 ` Jeff King
  2018-12-12 14:04   ` Ævar Arnfjörð Bjarmason
  2018-12-12 16:49   ` Iucha, Florin
  0 siblings, 2 replies; 9+ messages in thread
From: Jeff King @ 2018-12-12 11:24 UTC (permalink / raw)
  To: Iucha, Florin; +Cc: git

On Wed, Dec 12, 2018 at 03:01:47AM +0000, Iucha, Florin wrote:

> I am running “git-repack  -A -d -f -F --window=250 --depth=250” on a
> Git repository converted using git-svn.

Sort of tangential to your question, but:

  - Using "-F" implies "-f" already, so you don't need both. That said,
    you are probably wasting CPU to use "-F", unless you have adjusted
    zlib compression settings since the last pack. (Whereas using "-f"
    is useful, if you're willing to pay the CPU tradeoff).

  - Using --depth=250 does not actually decrease the packfile size very
    much, and results in a packfile which is more expensive for
    subsequent processes to use. Some experimentation showed that
    --depth=50 is a sweet spot, and that is the default for both normal
    "git gc" and "git gc --aggressive" these days.

    See 07e7dbf0db (gc: default aggressive depth to 50, 2016-08-11) for
    more discussion.

> The system is a 16 core / 32 thread Threadripper with 128GB of RAM and
> NVMe storage. The repack starts strong, with 32 threads but it fairly
> quickly gets to 99% done and the number of threads drops to 4 then 3
> then 2. However, running “dstat 5” I see lots of “sys” time without
> any IO time (the network traffic you see is caused by SSH).

This sounds mostly normal and expected. The parallel part of a repack is
the delta search, which is not infinitely parallelizable. Each worker
thread is given a "chunk" of objects, and it uses a sliding window to
search for delta pairs through that chunk. You don't want a chunk that
approaches the window size, since at every chunk boundary you're missing
delta possibilities.

The default chunk size is about 1/nr_threads of the total list size
(i.e., we portion out all the work). And then when a thread finishes, we
take work from the thread with the most work remaining, and portion it
out. However, at some point the chunks approach their minimum, and we
stop dividing. So the number of threads will drop, eventually to 1, and
you'll be waiting on it to finish that final chunk.

So that's all working as planned. Having high sys load does seem a bit
odd. Most of the effort should be going to reading the mmap'd data from
disk, zlib-inflating it and computing a fingerprint, and then comparing
the fingerprints. So that would mostly be user time.

> Running a strace on the running git-repack process shows only these:
> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
> 
> Any idea on how to debug this? I have ran git-repack under gdb, but it seems to spin on builtin/repack.c line 409.

The heavy lifting here is done by the pack-objects child process, not
git-repack itself. Try running with GIT_TRACE=1 in the environment to
see the exact invocation, but timing and debugging:

  git pack-objects --all --no-reuse-delta --delta-base-offset --stdout \
    </dev/null >/dev/null

should produce interesting results.

The SIGALRM loop you see above is likely just the progress meter
triggering once per second (the actual worker threads are updating an
int, and then at least once per second we'll show the int).

-Peff

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: High locking contention during repack?
  2018-12-12 11:24 ` Jeff King
@ 2018-12-12 14:04   ` Ævar Arnfjörð Bjarmason
  2018-12-12 16:49   ` Iucha, Florin
  1 sibling, 0 replies; 9+ messages in thread
From: Ævar Arnfjörð Bjarmason @ 2018-12-12 14:04 UTC (permalink / raw)
  To: Jeff King; +Cc: Iucha, Florin, git


On Wed, Dec 12 2018, Jeff King wrote:

> On Wed, Dec 12, 2018 at 03:01:47AM +0000, Iucha, Florin wrote:
>
>> I am running “git-repack  -A -d -f -F --window=250 --depth=250” on a
>> Git repository converted using git-svn.
>
> Sort of tangential to your question, but:
>
>   - Using "-F" implies "-f" already, so you don't need both. That said,
>     you are probably wasting CPU to use "-F", unless you have adjusted
>     zlib compression settings since the last pack. (Whereas using "-f"
>     is useful, if you're willing to pay the CPU tradeoff).
>
>   - Using --depth=250 does not actually decrease the packfile size very
>     much, and results in a packfile which is more expensive for
>     subsequent processes to use. Some experimentation showed that
>     --depth=50 is a sweet spot, and that is the default for both normal
>     "git gc" and "git gc --aggressive" these days.
>
>     See 07e7dbf0db (gc: default aggressive depth to 50, 2016-08-11) for
>     more discussion.

I wonder if the size is still too high. I'd rather take the 5-10%
speedup quoted in that commit than a slight decrease in disk space use.

The git.git repository now with the repack command in that commit
message, with --depth=$n:

    573M    /tmp/git-1
    200M    /tmp/git-2
    118M    /tmp/git-3
    91M     /tmp/git-4
    82M     /tmp/git-5
    77M     /tmp/git-6
    74M     /tmp/git-7
    72M     /tmp/git-8
    71M     /tmp/git-9
    70M     /tmp/git-10
    67M     /tmp/git-15
    66M     /tmp/git-20
    65M     /tmp/git-40
    65M     /tmp/git-35
    65M     /tmp/git-30
    65M     /tmp/git-25
    64M     /tmp/git-50
    64M     /tmp/git-45

Produced via:

    parallel 'rm -rf /tmp/git-{}; cp -Rvp /tmp/git.git/ /tmp/git-{} && git -C /tmp/git-{} repack -adf --depth={} --window=250' ::: {1..10} 15 20 25 30 35 40 45 50

And then the log -S benchmarks:

              s/iter log -S 1 log -S 50 log -S 45 log -S 35 log -S 30 log -S 25 log -S 20 log -S 15 log -S 10 log -S 5
    log -S 1    12.6       --      -26%      -27%      -32%      -36%      -38%      -38%      -39%      -40%     -42%
    log -S 50   9.28      36%        --       -0%       -7%      -13%      -15%      -16%      -18%      -19%     -21%
    log -S 45   9.25      36%        0%        --       -7%      -12%      -15%      -16%      -17%      -19%     -20%
    log -S 35   8.62      46%        8%        7%        --       -6%       -9%      -10%      -11%      -13%     -14%
    log -S 30   8.12      55%       14%       14%        6%        --       -3%       -4%       -6%       -8%      -9%
    log -S 25   7.86      60%       18%       18%       10%        3%        --       -1%       -3%       -5%      -6%
    log -S 20   7.77      62%       19%       19%       11%        4%        1%        --       -2%       -3%      -5%
    log -S 15   7.64      65%       21%       21%       13%        6%        3%        2%        --       -2%      -4%
    log -S 10   7.51      68%       24%       23%       15%        8%        5%        3%        2%        --      -2%
    log -S 5    7.37      71%       26%       25%       17%       10%        7%        5%        4%        2%       --

So we're getting a 20% speedup in log -S by using --depth=5 instead of
--depth=50, neatly at the cost of 20% more disk space, but could also
get a 19% speedup for 8% (--depth=10) more disk space, etc.

Then in rev-list it makes less of a difference, narrowing this down a
bit:

                s/iter rev-list 50 rev-list 25 rev-list 10  rev-list 5
    rev-list 50   1.61          --         -1%         -4%         -5%
    rev-list 25   1.60          1%          --         -3%         -4%
    rev-list 10   1.55          4%          3%          --         -1%
    rev-list 5    1.54          5%          4%          1%          --

It seems to me we should at least move this to --depth=25 by default. A
~15% speedup in log -S & other mass-blob lookups for 1.5% more disk
space seems like a good trade-off. As your commit notes RAM (or disk
space) is not commonly the bottleneck anymore.

>> The system is a 16 core / 32 thread Threadripper with 128GB of RAM and
>> NVMe storage. The repack starts strong, with 32 threads but it fairly
>> quickly gets to 99% done and the number of threads drops to 4 then 3
>> then 2. However, running “dstat 5” I see lots of “sys” time without
>> any IO time (the network traffic you see is caused by SSH).
>
> This sounds mostly normal and expected. The parallel part of a repack is
> the delta search, which is not infinitely parallelizable. Each worker
> thread is given a "chunk" of objects, and it uses a sliding window to
> search for delta pairs through that chunk. You don't want a chunk that
> approaches the window size, since at every chunk boundary you're missing
> delta possibilities.
>
> The default chunk size is about 1/nr_threads of the total list size
> (i.e., we portion out all the work). And then when a thread finishes, we
> take work from the thread with the most work remaining, and portion it
> out. However, at some point the chunks approach their minimum, and we
> stop dividing. So the number of threads will drop, eventually to 1, and
> you'll be waiting on it to finish that final chunk.
>
> So that's all working as planned. Having high sys load does seem a bit
> odd. Most of the effort should be going to reading the mmap'd data from
> disk, zlib-inflating it and computing a fingerprint, and then comparing
> the fingerprints. So that would mostly be user time.
>
>> Running a strace on the running git-repack process shows only these:
>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
>> --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
>>
>> Any idea on how to debug this? I have ran git-repack under gdb, but it seems to spin on builtin/repack.c line 409.
>
> The heavy lifting here is done by the pack-objects child process, not
> git-repack itself. Try running with GIT_TRACE=1 in the environment to
> see the exact invocation, but timing and debugging:
>
>   git pack-objects --all --no-reuse-delta --delta-base-offset --stdout \
>     </dev/null >/dev/null
>
> should produce interesting results.
>
> The SIGALRM loop you see above is likely just the progress meter
> triggering once per second (the actual worker threads are updating an
> int, and then at least once per second we'll show the int).
>
> -Peff

^ permalink raw reply	[flat|nested] 9+ messages in thread

* RE: High locking contention during repack?
  2018-12-12 11:24 ` Jeff King
  2018-12-12 14:04   ` Ævar Arnfjörð Bjarmason
@ 2018-12-12 16:49   ` Iucha, Florin
  2018-12-12 16:54     ` Ævar Arnfjörð Bjarmason
  2018-12-12 18:08     ` Iucha, Florin
  1 sibling, 2 replies; 9+ messages in thread
From: Iucha, Florin @ 2018-12-12 16:49 UTC (permalink / raw)
  To: Jeff King; +Cc: git

Jeff,

Thank you for the advice, I will reduce the depth.

Running "git pack-objects --all --no-reuse-delta --delta-base-offset --stdout </dev/null >/dev/null", it got to 99% fairly quickly, now it has 5 threads running (using 99.9% CPU), but the "dstat 5" still shows lots of nothing, with some heavy system activity:

--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw 
  1   8  91   0   0| 166k  224k|   0     0 |   0     0 |6892   970 
  0  13  87   0   0|   0     0 | 333B 1758B|   0     0 |2285  1374 
  0  13  87   0   0|   0     0 | 309B 1190B|   0     0 |2233  1265 
  0  13  87   0   0|   0     0 | 282B 1053B|   0     0 |2174  1239 
  0  13  87   0   0|   0     0 | 278B 1251B|   0     0 |1930  1173 
  0  13  87   0   0|   0     0 | 274B  942B|   0     0 |1987  1139 
  0  13  87   0   0|   0     0 | 264B 1168B|   0     0 |1928  1205 
  0  13  87   0   0|   0     0 | 388B 2435B|   0     0 |2245  1280 
  0  13  87   0   0|   0     0 | 268B 1145B|   0     0 |2225  1221 
  0  13  87   0   0|   0     0 | 164B  732B|   0     0 |2607  1333 
  0  13  87   0   0|   0     0 | 156B  996B|   0     0 |2100  1270 
  0  13  87   0   0|   0     0 | 206B 1019B|   0     0 |2192  1296 
  0  13  87   0   0|   0     0 | 198B  824B|   0     0 |2019  1236 
  0  13  87   0   0|   0     0 | 245B  435B|   0     0 |1974  1195 
  0  13  87   0   0|   0     0 | 252B  855B|   0     0 |1852  1166 
  0  13  87   0   0|   0     0 | 230B  758B|   0     0 |2066  1299 
  0  13  87   0   0|   0     0 | 284B  925B|   0     0 |1860  1225 
  0  13  87   0   0|   0     0 | 289B 2682B|   0     0 |1796  1197 
  0  13  87   0   0|   0     0 | 939B 1263B|   0     0 |1913  1304 
  0  13  87   0   0|   0     0 |1212B 1366B|   0     0 |1915  1343

I will try running the command under the debugger and stop it when it gets to this point and poke around.

florin

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: High locking contention during repack?
  2018-12-12 16:49   ` Iucha, Florin
@ 2018-12-12 16:54     ` Ævar Arnfjörð Bjarmason
  2018-12-12 18:08     ` Iucha, Florin
  1 sibling, 0 replies; 9+ messages in thread
From: Ævar Arnfjörð Bjarmason @ 2018-12-12 16:54 UTC (permalink / raw)
  To: Iucha, Florin; +Cc: Jeff King, Git Mailing List

On Wed, Dec 12, 2018 at 5:52 PM Iucha, Florin <Florin.Iucha@amd.com> wrote:
>
> Jeff,
>
> Thank you for the advice, I will reduce the depth.
>
> Running "git pack-objects --all --no-reuse-delta --delta-base-offset --stdout </dev/null >/dev/null", it got to 99% fairly quickly, now it has 5 threads running (using 99.9% CPU), but the "dstat 5" still shows lots of nothing, with some heavy system activity:
>
> --total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw
>   1   8  91   0   0| 166k  224k|   0     0 |   0     0 |6892   970
>   0  13  87   0   0|   0     0 | 333B 1758B|   0     0 |2285  1374
>   0  13  87   0   0|   0     0 | 309B 1190B|   0     0 |2233  1265
>   0  13  87   0   0|   0     0 | 282B 1053B|   0     0 |2174  1239
>   0  13  87   0   0|   0     0 | 278B 1251B|   0     0 |1930  1173
>   0  13  87   0   0|   0     0 | 274B  942B|   0     0 |1987  1139
>   0  13  87   0   0|   0     0 | 264B 1168B|   0     0 |1928  1205
>   0  13  87   0   0|   0     0 | 388B 2435B|   0     0 |2245  1280
>   0  13  87   0   0|   0     0 | 268B 1145B|   0     0 |2225  1221
>   0  13  87   0   0|   0     0 | 164B  732B|   0     0 |2607  1333
>   0  13  87   0   0|   0     0 | 156B  996B|   0     0 |2100  1270
>   0  13  87   0   0|   0     0 | 206B 1019B|   0     0 |2192  1296
>   0  13  87   0   0|   0     0 | 198B  824B|   0     0 |2019  1236
>   0  13  87   0   0|   0     0 | 245B  435B|   0     0 |1974  1195
>   0  13  87   0   0|   0     0 | 252B  855B|   0     0 |1852  1166
>   0  13  87   0   0|   0     0 | 230B  758B|   0     0 |2066  1299
>   0  13  87   0   0|   0     0 | 284B  925B|   0     0 |1860  1225
>   0  13  87   0   0|   0     0 | 289B 2682B|   0     0 |1796  1197
>   0  13  87   0   0|   0     0 | 939B 1263B|   0     0 |1913  1304
>   0  13  87   0   0|   0     0 |1212B 1366B|   0     0 |1915  1343
>
> I will try running the command under the debugger and stop it when it gets to this point and poke around.

FWIW compiling with gcc's gprof support is probably a better way to
figure out "what was my program doing all this time?".

^ permalink raw reply	[flat|nested] 9+ messages in thread

* RE: High locking contention during repack?
  2018-12-12 16:49   ` Iucha, Florin
  2018-12-12 16:54     ` Ævar Arnfjörð Bjarmason
@ 2018-12-12 18:08     ` Iucha, Florin
  2018-12-12 18:30       ` Iucha, Florin
  1 sibling, 1 reply; 9+ messages in thread
From: Iucha, Florin @ 2018-12-12 18:08 UTC (permalink / raw)
  To: Jeff King; +Cc: git, Ævar Arnfjörð Bjarmason

(Apologize for top-posting but making Outlook quote properly is a bear)

Down to 1+4 threads:

--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw 
  0  13  87   0   0|   0     0 |2059B   15k|   0     0 |2200  1730 
  0  13  87   0   0|   0     0 | 585B 2754B|   0     0 |1792  1269 
  0  13  87   0   0|   0     0 | 178B  734B|   0     0 |1691  1157 
  0  13  87   0   0|   0  6554B| 225B  734B|   0     0 |1885  1238 
  0  13  87   0   0|   0     0 | 159B  736B|   0     0 |1958  1262 
  0  13  87   0   0|   0     0 | 310B  760B|   0     0 |1813  1175

(gdb) info threads
  Id   Target Id         Frame 
* 1    Thread 0x7f7b837dcb80 (LWP 11918) "git" 0x000055c7dded56eb in ll_find_deltas (processed=0x7ffce7da82a8, depth=<optimized out>, window=<optimized out>, 
    list_size=0, list=<optimized out>) at builtin/pack-objects.c:2516
  2    Thread 0x7f782e16a700 (LWP 11929) "git" create_delta (index=0x55c807d2ff20, trg_buf=<optimized out>, trg_size=trg_size@entry=9677636, 
    delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674) at diff-delta.c:381
  3    Thread 0x7f6fe77fe700 (LWP 11948) "git" create_delta (index=0x7f6e35171010, trg_buf=<optimized out>, trg_size=trg_size@entry=163385853, 
    delta_size=delta_size@entry=0x7f6fe77fde78, max_size=2328926) at diff-delta.c:381
  4    Thread 0x7f6fe67fc700 (LWP 11950) "git" create_delta (index=0x7f6e3f7f3010, trg_buf=<optimized out>, trg_size=trg_size@entry=74543780, 
    delta_size=delta_size@entry=0x7f6fe67fbe78, max_size=2582505) at diff-delta.c:381
  5    Thread 0x7f6fe5ffb700 (LWP 11951) "git" create_delta (index=0x7f6f01d06010, trg_buf=<optimized out>, trg_size=trg_size@entry=28510185, 
    delta_size=delta_size@entry=0x7f6fe5ffae78, max_size=9146484) at diff-delta.c:381
(gdb) bt
#0  0x00007f7b82f909f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55c7de2ff348 <progress_cond+40>)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x55c7de2ff360 <progress_mutex>, cond=0x55c7de2ff320 <progress_cond>) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=cond@entry=0x55c7de2ff320 <progress_cond>, mutex=mutex@entry=0x55c7de2ff360 <progress_mutex>) at pthread_cond_wait.c:655
#3  0x000055c7dded56eb in ll_find_deltas (processed=0x7ffce7da82a8, depth=<optimized out>, window=<optimized out>, list_size=0, list=<optimized out>)
    at builtin/pack-objects.c:2516
#4  prepare_pack (depth=<optimized out>, window=<optimized out>) at builtin/pack-objects.c:2673
#5  cmd_pack_objects (argc=<optimized out>, argv=<optimized out>, prefix=<optimized out>) at builtin/pack-objects.c:3491
#6  0x000055c7dde74711 in run_builtin (argv=<optimized out>, argc=<optimized out>, p=<optimized out>) at git.c:421
#7  handle_builtin (argc=<optimized out>, argv=<optimized out>) at git.c:647
#8  0x000055c7dde75725 in run_argv (argv=0x7ffce7daa7e0, argcp=0x7ffce7daa7ec) at git.c:701
#9  cmd_main (argc=<optimized out>, argv=<optimized out>) at git.c:798
#10 0x000055c7dde7437f in main (argc=6, argv=0x7ffce7daaa58) at common-main.c:45
(gdb) thread 2
[Switching to thread 2 (Thread 0x7f782e16a700 (LWP 11929))]
#0  create_delta (index=0x55c807d2ff20, trg_buf=<optimized out>, trg_size=trg_size@entry=9677636, delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674)
    at diff-delta.c:381
381                                     if (entry->val != val)
(gdb) bt
#0  create_delta (index=0x55c807d2ff20, trg_buf=<optimized out>, trg_size=trg_size@entry=9677636, delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674)
    at diff-delta.c:381
#1  0x000055c7dded0606 in try_delta (mem_usage=<synthetic pointer>, max_depth=50, src=0x7f702c256bc0, trg=0x7f702c256ca0) at builtin/pack-objects.c:2129
#2  find_deltas (list=<optimized out>, list_size=list_size@entry=0x55c7e467daf4, window=<optimized out>, depth=<optimized out>, processed=<optimized out>)
    at builtin/pack-objects.c:2262
#3  0x000055c7dded0e29 in threaded_find_deltas (arg=0x55c7e467dae0) at builtin/pack-objects.c:2408
#4  0x00007f7b82f8a6db in start_thread (arg=0x7f782e16a700) at pthread_create.c:463
#5  0x00007f7b82cb388f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb) thread 2
[Switching to thread 2 (Thread 0x7f782e16a700 (LWP 11929))]
#0  create_delta (index=0x55c807d2ff20, trg_buf=<optimized out>, trg_size=trg_size@entry=9677636, delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674)
    at diff-delta.c:381
381                                     if (entry->val != val)
(gdb) bt
#0  create_delta (index=0x55c807d2ff20, trg_buf=<optimized out>, trg_size=trg_size@entry=9677636, delta_size=delta_size@entry=0x7f782e169e78, max_size=3585674)
    at diff-delta.c:381
#1  0x000055c7dded0606 in try_delta (mem_usage=<synthetic pointer>, max_depth=50, src=0x7f702c256bc0, trg=0x7f702c256ca0) at builtin/pack-objects.c:2129
#2  find_deltas (list=<optimized out>, list_size=list_size@entry=0x55c7e467daf4, window=<optimized out>, depth=<optimized out>, processed=<optimized out>)
    at builtin/pack-objects.c:2262
#3  0x000055c7dded0e29 in threaded_find_deltas (arg=0x55c7e467dae0) at builtin/pack-objects.c:2408
#4  0x00007f7b82f8a6db in start_thread (arg=0x7f782e16a700) at pthread_create.c:463
#5  0x00007f7b82cb388f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

florin

-----Original Message-----
From: Iucha, Florin 
Sent: Wednesday, December 12, 2018 11:50 AM
To: 'Jeff King' <peff@peff.net>
Cc: git@vger.kernel.org
Subject: RE: High locking contention during repack?

Jeff,

Thank you for the advice, I will reduce the depth.

Running "git pack-objects --all --no-reuse-delta --delta-base-offset --stdout </dev/null >/dev/null", it got to 99% fairly quickly, now it has 5 threads running (using 99.9% CPU), but the "dstat 5" still shows lots of nothing, with some heavy system activity:

--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw 
  1   8  91   0   0| 166k  224k|   0     0 |   0     0 |6892   970 
  0  13  87   0   0|   0     0 | 333B 1758B|   0     0 |2285  1374 
  0  13  87   0   0|   0     0 | 309B 1190B|   0     0 |2233  1265 
  0  13  87   0   0|   0     0 | 282B 1053B|   0     0 |2174  1239 
  0  13  87   0   0|   0     0 | 278B 1251B|   0     0 |1930  1173 
  0  13  87   0   0|   0     0 | 274B  942B|   0     0 |1987  1139 
  0  13  87   0   0|   0     0 | 264B 1168B|   0     0 |1928  1205 
  0  13  87   0   0|   0     0 | 388B 2435B|   0     0 |2245  1280 
  0  13  87   0   0|   0     0 | 268B 1145B|   0     0 |2225  1221 
  0  13  87   0   0|   0     0 | 164B  732B|   0     0 |2607  1333 
  0  13  87   0   0|   0     0 | 156B  996B|   0     0 |2100  1270 
  0  13  87   0   0|   0     0 | 206B 1019B|   0     0 |2192  1296 
  0  13  87   0   0|   0     0 | 198B  824B|   0     0 |2019  1236 
  0  13  87   0   0|   0     0 | 245B  435B|   0     0 |1974  1195 
  0  13  87   0   0|   0     0 | 252B  855B|   0     0 |1852  1166 
  0  13  87   0   0|   0     0 | 230B  758B|   0     0 |2066  1299 
  0  13  87   0   0|   0     0 | 284B  925B|   0     0 |1860  1225 
  0  13  87   0   0|   0     0 | 289B 2682B|   0     0 |1796  1197 
  0  13  87   0   0|   0     0 | 939B 1263B|   0     0 |1913  1304 
  0  13  87   0   0|   0     0 |1212B 1366B|   0     0 |1915  1343

I will try running the command under the debugger and stop it when it gets to this point and poke around.

florin

^ permalink raw reply	[flat|nested] 9+ messages in thread

* RE: High locking contention during repack?
  2018-12-12 18:08     ` Iucha, Florin
@ 2018-12-12 18:30       ` Iucha, Florin
  2018-12-12 19:05         ` Iucha, Florin
  0 siblings, 1 reply; 9+ messages in thread
From: Iucha, Florin @ 2018-12-12 18:30 UTC (permalink / raw)
  To: git; +Cc: Ævar Arnfjörð Bjarmason, Jeff King

It seems to be spending a lot of time in create_delta. I have added a breakpoint on calling create_delta and a few good minutes pass between the breakpoint being hit. The large loop in create_delta has practically no outgoing function calls (save for the realloc on line 476), so I still don't understand how dstat could report 0% user time. htop indicates the worker threads are using 100% CPU time.

florin

^ permalink raw reply	[flat|nested] 9+ messages in thread

* RE: High locking contention during repack?
  2018-12-12 18:30       ` Iucha, Florin
@ 2018-12-12 19:05         ` Iucha, Florin
  2018-12-12 21:50           ` Iucha, Florin
  0 siblings, 1 reply; 9+ messages in thread
From: Iucha, Florin @ 2018-12-12 19:05 UTC (permalink / raw)
  To: git; +Cc: Ævar Arnfjörð Bjarmason, Jeff King

Is there an easy way to figure out what object we're processing in create_delta? I have filtered out some large data files in .gitattributes already.

florin

^ permalink raw reply	[flat|nested] 9+ messages in thread

* RE: High locking contention during repack?
  2018-12-12 19:05         ` Iucha, Florin
@ 2018-12-12 21:50           ` Iucha, Florin
  0 siblings, 0 replies; 9+ messages in thread
From: Iucha, Florin @ 2018-12-12 21:50 UTC (permalink / raw)
  To: git; +Cc: Ævar Arnfjörð Bjarmason, Jeff King

> Is there an easy way to figure out what object we're processing in create_delta? I have filtered out some large data files in .gitattributes already.

For the record:
* add breakpoint on create_delta at diff-delta.c:321
* stop the execution
* switch to the worker thread
* select frame 3: threaded_find_deltas at builtin/pack-objects.c:2408
* p/x me->list.idx.oid.hash

florin

^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2018-12-12 21:50 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-12-12  3:01 High locking contention during repack? Iucha, Florin
2018-12-12 11:24 ` Jeff King
2018-12-12 14:04   ` Ævar Arnfjörð Bjarmason
2018-12-12 16:49   ` Iucha, Florin
2018-12-12 16:54     ` Ævar Arnfjörð Bjarmason
2018-12-12 18:08     ` Iucha, Florin
2018-12-12 18:30       ` Iucha, Florin
2018-12-12 19:05         ` Iucha, Florin
2018-12-12 21:50           ` Iucha, Florin

git@vger.kernel.org list mirror (unofficial, one of many)

This inbox may be cloned and mirrored by anyone:

	git clone --mirror https://public-inbox.org/git
	git clone --mirror http://ou63pmih66umazou.onion/git
	git clone --mirror http://czquwvybam4bgbro.onion/git
	git clone --mirror http://hjrcffqmbrq6wope.onion/git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V1 git git/ https://public-inbox.org/git \
		git@vger.kernel.org
	public-inbox-index git

Example config snippet for mirrors.
Newsgroups are available over NNTP:
	nntp://news.public-inbox.org/inbox.comp.version-control.git
	nntp://ou63pmih66umazou.onion/inbox.comp.version-control.git
	nntp://czquwvybam4bgbro.onion/inbox.comp.version-control.git
	nntp://hjrcffqmbrq6wope.onion/inbox.comp.version-control.git
	nntp://news.gmane.io/gmane.comp.version-control.git
 note: .onion URLs require Tor: https://www.torproject.org/

code repositories for project(s) associated with this inbox:

	https://80x24.org/mirrors/git.git

AGPL code for this site: git clone https://public-inbox.org/public-inbox.git