Long SSHD execution duration

[davidch...@gmail.com]

Hi Folks, 

We are facing degraded fetch/clone performance recently. It is taking more time for upload-pack operations even if client working copy is up to date (Status -1 is returned if client is up to date). Please find one such occurrence below from sshd_log.  As per logs documentation, [1] It is taking huge amount for “exec”. How can we debug where exactly gerrit is waiting and getting delayed in “exec” process.?

 

2020-12-10 05:12:56,978 +0200] fda6e242 [SSH git-upload-pack /gerrit-reponame (user)] user a/1003635 git-upload-pack./gerrit-reponame 1ms 178216ms -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 0

 

[1] https://gerrit-documentation.storage.googleapis.com/Documentation/2.16.23/logs.html#_sshd_log

Regards,

Challs

[Luca Milanesio]

On 10 Dec 2020, at 04:42, davidch...@gmail.com <davidch...@gmail.com> wrote:

Hi Folks, 

We are facing degraded fetch/clone performance recently. It is taking more time for upload-pack operations even if client working copy is up to date (Status -1 is returned if client is up to date). Please find one such occurrence below from sshd_log.  As per logs documentation, [1] It is taking huge amount for “exec”. How can we debug where exactly gerrit is waiting and getting delayed in “exec” process.?

 

2020-12-10 05:12:56,978 +0200] fda6e242 [SSH git-upload-pack /gerrit-reponame (user)] user a/1003635 git-upload-pack./gerrit-reponame 1ms 178216ms -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 0

Have you taken a JVM tread dump of Gerrit during that time?

That would help in understanding what’s going on.

HTH

Luca.

 

[1] https://gerrit-documentation.storage.googleapis.com/Documentation/2.16.23/logs.html#_sshd_log

Regards,

Challs

--
--
To unsubscribe, email repo-discuss...@googlegroups.com
More info at http://groups.google.com/group/repo-discuss?hl=en

---
You received this message because you are subscribed to the Google Groups "Repo and Gerrit Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to repo-discuss...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/01c1f0e1-9932-49fb-a452-3a4ac4e9f60bn%40googlegroups.com.

[Matthias Sohn]

On Thu, Dec 10, 2020 at 12:10 PM Luca Milanesio <luca.mi...@gmail.com> wrote:

On 10 Dec 2020, at 04:42, davidch...@gmail.com <davidch...@gmail.com> wrote:

Hi Folks, 

We are facing degraded fetch/clone performance recently. It is taking more time for upload-pack operations even if client working copy is up to date (Status -1 is returned if client is up to date). Please find one such occurrence below from sshd_log.  As per logs documentation, [1] It is taking huge amount for “exec”. How can we debug where exactly gerrit is waiting and getting delayed in “exec” process.?

 

2020-12-10 05:12:56,978 +0200] fda6e242 [SSH git-upload-pack /gerrit-reponame (user)] user a/1003635 git-upload-pack./gerrit-reponame 1ms 178216ms -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 0

Have you taken a JVM tread dump of Gerrit during that time?

That would help in understanding what’s going on.

HTH

Luca.

• Which Gerrit version do you use ?
• Are you using git protocol version 2 which is supported since Gerrit 3.1 ?
• Do you gc all repositories on a regular schedule ?
• Run git count-objects -vH on the gerrit host on some of the bigger repositories to get an impression.
• Did the repositories you see slower performance grow heavily in the recent past ?
• you can use git-sizer to get an impression on what might be problematic 

[1] https://gerrit-documentation.storage.googleapis.com/Documentation/2.16.23/logs.html#_sshd_log

[2] https://git-scm.com/docs/git-count-objects

[3] https://github.com/github/git-sizer

-Matthias

Regards,

Challs

--
--
To unsubscribe, email repo-discuss...@googlegroups.com
More info at http://groups.google.com/group/repo-discuss?hl=en

---
You received this message because you are subscribed to the Google Groups "Repo and Gerrit Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to repo-discuss...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/01c1f0e1-9932-49fb-a452-3a4ac4e9f60bn%40googlegroups.com.

--
--
To unsubscribe, email repo-discuss...@googlegroups.com
More info at http://groups.google.com/group/repo-discuss?hl=en

---
You received this message because you are subscribed to the Google Groups "Repo and Gerrit Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to repo-discuss...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/F564F9E5-A72B-455E-B932-6DA1814613AE%40gmail.com.

[David Charles T M]

Hi Luca,

Thanks for the reply. I had a thread dump taken yesterday. 

[2020-12-09 10:28:15,719 +0200] d46f5ede [SSH git-upload-pack /repo (USER)] USER a/1021440 git-upload-pack./repo 5ms 22838ms -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 0

"SSH git-upload-pack /repo (USER)" prio=1 TIMED_WAITING

java.lang.Object.wait(Native Method)

org.apache.sshd.common.channel.Window.waitForCondition(Window.java:292)

org.apache.sshd.common.channel.Window.waitForSpace(Window.java:252)

org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:188)

org.apache.sshd.common.channel.ChannelOutputStream.write(ChannelOutputStream.java:127)

org.eclipse.jgit.util.io.TimeoutOutputStream.write(TimeoutOutputStream.java:125)

org.eclipse.jgit.transport.UploadPack$ResponseBufferedOutputStream.write(UploadPack.java:2183)

org.eclipse.jgit.transport.PacketLineOut.writePacket(PacketLineOut.java:144)

org.eclipse.jgit.transport.RefAdvertiser$PacketLineOutRefAdvertiser.advertiseId(RefAdvertiser.java:114)

org.eclipse.jgit.transport.RefAdvertiser.advertiseAny(RefAdvertiser.java:390)

org.eclipse.jgit.transport.RefAdvertiser.send(RefAdvertiser.java:337)

org.eclipse.jgit.transport.RefAdvertiser.send(RefAdvertiser.java:293)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1404)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1337)

org.eclipse.jgit.transport.UploadPack.service(UploadPack.java:891)

org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:776)

com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:78)

com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:98)

com.google.gerrit.sshd.AbstractGitCommand.access$000(AbstractGitCommand.java:31)

com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:63)

com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:467)

com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:83)

java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

java.util.concurrent.FutureTask.run(FutureTask.java:266)

java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:646)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

java.lang.Thread.run(Thread.java:748)

"SSH git-upload-pack /repo (USER)-Timer" daemon prio=1 TIMED_WAITING

java.lang.Object.wait(Native Method)

org.eclipse.jgit.util.io.InterruptTimer$AlarmState.run(InterruptTimer.java:195)

java.lang.Thread.run(Thread.java:748)

Regards,

Challs

[Luca Milanesio]

> On 10 Dec 2020, at 16:23, David Charles T M <davidch...@gmail.com> wrote:
>
> Hi Luca,
>
> Thanks for the reply. I had a thread dump taken yesterday.
>
> [2020-12-09 10:28:15,719 +0200] d46f5ede [SSH git-upload-pack /repo (USER)] USER a/1021440 git-upload-pack./repo 5ms 22838ms -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 0
>
> "SSH git-upload-pack /repo (USER)" prio=1 TIMED_WAITING
> java.lang.Object.wait(Native Method)
> org.apache.sshd.common.channel.Window.waitForCondition(Window.java:292)
> org.apache.sshd.common.channel.Window.waitForSpace(Window.java:252)
> org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:188)
> org.apache.sshd.common.channel.ChannelOutputStream.write(ChannelOutputStream.java:127)
> org.eclipse.jgit.util.io.TimeoutOutputStream.write(TimeoutOutputStream.java:125)
> org.eclipse.jgit.transport.UploadPack$ResponseBufferedOutputStream.write(UploadPack.java:2183)

That sounds interesting ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

So, basically, even if there's nothing to do, it spends 22s writing stuff?

Can you enable the GIT protocol tracing on the client side?
GIT_TRACE_PACKET=true git fetch ...

We need to understand *how much* data is transferred and what's the bandwidth available.

Are you fetching everything? Just one ref?

P.S. From the Git protocol packets we'll see that anyway.

HTH

Luca.

[David Charles T M]

Hi Matthias,

·  Which Gerrit version do you use ?

[Challs]  v2.16.22

·  Are you using git protocol version 2 which is supported since Gerrit 3.1 ?

[Challs] No, we are not using v2 protocol

·  Do you gc all repositories on a regular schedule ?

[Challs] Yes, we have an automated system which validates and runs GC for repos when object count is above 7000 or pack count is above 20.  

 

·  Did the repositories you see slower performance grow heavily in the recent past ?

[Challs] : This degradation is seen in big repos as well as in small repos.

 

[gerrit@host framework.git]$git count-objects -vH | xargs

count: 734 size: 2.93 MiB in-pack: 112834 packs: 10 size-pack: 152.73 MiB prune-packable: 2 garbage: 0 size-garbage: 0 bytes

[gerrit@host framework.git]$cd /gerrit/gerrit/git/AbstractionLayer.git/

[gerrit@host AbstractionLayer.git]$git count-objects -vH | xargs

count: 71 size: 284.00 KiB in-pack: 32859 packs: 15 size-pack: 9.59 MiB prune-packable: 0 garbage: 0 size-garbage: 0 bytes

[gerrit@host AbstractionLayer.git]$cd /gerrit/gerrit/git//somerepo.git

[gerrit@host somerepo.git]$git count-objects -vH | xargs

count: 2692 size: 12.82 MiB in-pack: 4699960 packs: 27 size-pack: 1.43 GiB prune-packable: 11 garbage: 0 size-garbage: 0 bytes

[gerrit@host somerepo.git]$

Regards,

Challs

[David Charles T M]

Hi Luca,

CI system is normally fetching the changes alone. So it is one ref at a moment. 

We will check the possibilities to enable GIT protocol tracing as it will be creating more logs. 

Regards,

Challs

[Luca Milanesio]

> On 10 Dec 2020, at 16:57, David Charles T M <davidch...@gmail.com> wrote:
>
> Hi Luca,
>

> CI system is normally fetching the changes alone. So it is one ref at a moment.

… and how many refs has the repo in total?

[Matthias Sohn]

On Thu, Dec 10, 2020 at 5:33 PM David Charles T M <davidch...@gmail.com> wrote:

Hi Matthias,

·  Which Gerrit version do you use ?

[Challs]  v2.16.22

·  Are you using git protocol version 2 which is supported since Gerrit 3.1 ?

[Challs] No, we are not using v2 protocol

·  Do you gc all repositories on a regular schedule ?

[Challs] Yes, we have an automated system which validates and runs GC for repos when object count is above 7000 or pack count is above 20.  

 

·  Did the repositories you see slower performance grow heavily in the recent past ?

[Challs] : This degradation is seen in big repos as well as in small repos.

 

[gerrit@host framework.git]$git count-objects -vH | xargs

count: 734 size: 2.93 MiB in-pack: 112834 packs: 10 size-pack: 152.73 MiB prune-packable: 2 garbage: 0 size-garbage: 0 bytes

[gerrit@host framework.git]$cd /gerrit/gerrit/git/AbstractionLayer.git/

[gerrit@host AbstractionLayer.git]$git count-objects -vH | xargs

count: 71 size: 284.00 KiB in-pack: 32859 packs: 15 size-pack: 9.59 MiB prune-packable: 0 garbage: 0 size-garbage: 0 bytes

[gerrit@host AbstractionLayer.git]$cd /gerrit/gerrit/git//somerepo.git

[gerrit@host somerepo.git]$git count-objects -vH | xargs

count: 2692 size: 12.82 MiB in-pack: 4699960 packs: 27 size-pack: 1.43 GiB prune-packable: 11 garbage: 0 size-garbage: 0 bytes

[gerrit@host somerepo.git]$

 

from a size perspective the first two shouldn't cause performance issues, to my experience

size related issues typically happen on repositories above 1GB.

Another interesting metric which may influence performance especially with protocol version < 2 is the number of refs.

You can count that using

all refs

$ git show-ref | wc -l

loose refs

$ find refs/ -type f | wc -l

How did you configure the JGit cache ? It's used to reduce IO.

Its size is configured using option core.packedGitLimit [4].

Ideally it should be large enough to cache all packfiles of your

frequently accessed repositories. Max size is 1/4 of max heap.

[4] https://gerrit-documentation.storage.googleapis.com/Documentation/2.16.22/config-gerrit.html#core

[David Charles T M]

Hi Matthias,

We have tried to finetune core parameters. Still git-upload-pack operations show intermittent peaks in exec times. 

[root@host ~]# git config -f /gerrit/gerrit/etc/gerrit.config --get-regex heap

container.heaplimit 288g

[root@host ~]# git config -f /gerrit/gerrit/etc/gerrit.config --get-regex core

core.packedgitopenfiles 40960

core.packedgitlimit 72g

core.packedgitwindowsize 64k

core.repositorycacheexpireafter 30min

[root@host ~]#

116Kb [(HEAD detached at FETCH_HEAD)]:
└─$ cat /tmp/tracefetch.txt | grep 'packet: fetch' | awk {'print $NF'} | cut -d / -f2 | sort | uniq -c
2 0000
125 cache-automerge
106790 changes
1915 heads
1 meta
1 notes
114514 tags
1462 users

Regards,

Challs

[David Charles T M]

Hi Luca,

Please find below.

count	2548
size	11.96 MiB
in-pack	4739861
packs	4
size-pack	1.43 GiB

prune-packable	0
garbage	0
size-garbage	0 bytes

Tags	57329
Changes/Patchsets	107019
Branches	1914
Total Refs	167851
Size	1783M

116Kb [(HEAD detached at FETCH_HEAD)]:
└─$ cat /tmp/tracefetch.txt | grep 'packet: fetch' | awk {'print $NF'} | cut -d / -f2 | sort | uniq -c
2 0000
125 cache-automerge
106790 changes
1915 heads
1 meta
1 notes
114514 tags
1462 users

Regards,

Challs

[Matthias Sohn]

On Wed, Dec 16, 2020 at 5:31 AM David Charles T M <davidch...@gmail.com> wrote:

Hi Matthias,

We have tried to finetune core parameters. Still git-upload-pack operations show intermittent peaks in exec times. 

[root@host ~]# git config -f /gerrit/gerrit/etc/gerrit.config --get-regex heap

container.heaplimit 288g

that's a large heap, did you leave some memory for the OS and filesystem cache ?

 

[root@host ~]# git config -f /gerrit/gerrit/etc/gerrit.config --get-regex core

core.packedgitopenfiles 40960

core.packedgitlimit 72g

this is huge, you can check how much is really used in monitoring, e.g. [1] or [2]

 

core.packedgitwindowsize 64k

why do you use such large cache pages ?

 

core.repositorycacheexpireafter 30min

[root@host ~]#

116Kb [(HEAD detached at FETCH_HEAD)]:
└─$ cat /tmp/tracefetch.txt | grep 'packet: fetch' | awk {'print $NF'} | cut -d / -f2 | sort | uniq -c
2 0000
125 cache-automerge
106790 changes
1915 heads
1 meta
1 notes
114514 tags
1462 users

[1] JGit cache usage is shown in the process dashboard of

https://gerrit.googlesource.com/gerrit-monitoring/+/refs/heads/master, 

you can deploy this monitoring solution in a kubernetes cluster, or you can install grafana, prometheus,

metrics-reporter-prometheus plugin and promtail manually and use the grafana dashboards defined in this project.

[2] https://gerrit.googlesource.com/plugins/javamelody

look at metric jgit_block_cache_cache_used

[David Charles T M]

Hi Matthias,

that's a large heap, did you leave some memory for the OS and filesystem cache ?

[Challs] We have 503GB RAM on the server.

this is huge, you can check how much is really used in monitoring, e.g. [1] or [2]

[Challs] We have javamelody, but we dont have mbeans to provide such metrics. We shall install it soon and get some overview of how much cache is used.

why do you use such large cache pages ?

[Challs] It was increased to reduce the disk IO read. Does this have a negative impact with performance. ? 

Regards,

Challs

[David Charles T M]

Hi Luca/All,

When I was analysing some SSH connection logs for upload-pack operations, exec time is never equal to time which is split for each operation triggered by git-upload-pack. Here it took 86s for upload pack operation, but time spent by jgit for searching, reusing, counting, compressing, writing etc is very minimal. How can we debug where exactly is time spent by such upload-pack connections inside gerrit.?

[2021-01-06 10:11:26,086 +0200] 2ab22e7b [SSH git-upload-pack /gerrit_repo (user)] user a/1003635 git-upload-pack./gerrit_repo 1ms 86470ms 2029ms 0ms 0ms 150ms 0ms 0ms 150ms 2 0 1 380 0 git/2.26.2

Regards,

Challs

[Luca Milanesio]

On 6 Jan 2021, at 11:44, David Charles T M <davidch...@gmail.com> wrote:

Hi Luca/All,

When I was analysing some SSH connection logs for upload-pack operations, exec time is never equal to time which is split for each operation triggered by git-upload-pack. Here it took 86s for upload pack operation, but time spent by jgit for searching, reusing, counting, compressing, writing etc is very minimal. How can we debug where exactly is time spent by such upload-pack connections inside gerrit.?

You can get a JVM thread-dump when the upload-pack is in the middle of the execution of those 86s and then from there we can see what is actually doing.

HTH

Luca.

[Matthias Sohn]

On Wed, Jan 6, 2021 at 12:44 PM David Charles T M <davidch...@gmail.com> wrote:

Hi Luca/All,

When I was analysing some SSH connection logs for upload-pack operations, exec time is never equal to time which is split for each operation triggered by git-upload-pack. Here it took 86s for upload pack operation, but time spent by jgit for searching, reusing, counting, compressing, writing etc is very minimal. How can we debug where exactly is time spent by such upload-pack connections inside gerrit.?

[2021-01-06 10:11:26,086 +0200] 2ab22e7b [SSH git-upload-pack /gerrit_repo (user)] user a/1003635 git-upload-pack./gerrit_repo 1ms 86470ms 2029ms 0ms 0ms 150ms 0ms 0ms 150ms 2 0 1 380 0 git/2.26.2

fields in the log record are explained in [1]:

wait:                                     1ms 

exec:                            86470ms 

negotiating:                    2029ms 

searching for reuse:             0ms 

searching for sizes:              0ms 

counting:                          150ms 

compressing:                       0ms 

writing:                                 0ms 

total time in UploadPack: 150ms 

bitmap index misses:                2 

total deltas:                               0 

total objects:                             1 

total bytes:                            380 

status:                                       0 

client agent:                 git/2.26.2

This was a very small transport, only a single object and 380 bytes were transferred.

Do you use any synchronous hooks [2] ? If yes, which hooks do you use and how is hooks.syncHookTimeout configured ?

Please avoid top posting on this list.

[1] https://gerrit-review.googlesource.com/Documentation/logs.html

[2] https://gerrit.googlesource.com/plugins/hooks/+/refs/heads/master/src/main/resources/Documentation/hooks.md#synchronous-hooks

[3] https://gerrit.googlesource.com/plugins/hooks/+/refs/heads/master/src/main/resources/Documentation/config.md#hooks.syncHookTimeout

-Matthias

[David Charles T M]

Hi Matthias,

We use synchronous hooks and hooks.syncHookTimeout is not configured (so i guess it takes 30s default value). We use the hooks below.

1. commit-received
2. comment-added
3. change-restored
4. change-merged
5. change-abandoned
6. patchset-created
7. submit
8. reviewer-added
9. ref-updated
10. ref-update
11. change-deleted.

Regards,

Challs

[Luca Milanesio]

On 6 Jan 2021, at 13:56, Luca Milanesio <luca.mi...@gmail.com> wrote:

On 6 Jan 2021, at 11:44, David Charles T M <davidch...@gmail.com> wrote:

Hi Luca/All,

When I was analysing some SSH connection logs for upload-pack operations, exec time is never equal to time which is split for each operation triggered by git-upload-pack. Here it took 86s for upload pack operation, but time spent by jgit for searching, reusing, counting, compressing, writing etc is very minimal. How can we debug where exactly is time spent by such upload-pack connections inside gerrit.?

You can get a JVM thread-dump when the upload-pack is in the middle of the execution of those 86s and then from there we can see what is actually doing.

@David did you manage to get the JVM thread-dump to confirm what is blocking the Git/SSH execution?

Luca.

[David Charles T M]

H Luca,

@David did you manage to get the JVM thread-dump to confirm what is blocking the Git/SSH execution?

We were able to get thread dump once when the upload-pack operation went above 60s. As there were multiple upload-pack operations running at same time, we are unable to point it to the right thread.

Logs below:

[2021-01-08 04:31:21,604 +0200] 8578a5a6 [SSH git-upload-pack /repo (user)] user a/1003635 git-upload-pack./repo 1ms 85467ms 2034ms 1ms 0ms 53ms 0ms 0ms 54ms 28 20 24 2510 0 git/2.26.2

[2021-01-08 04:31:25,099 +0200] 42aba45f [SSH git-upload-pack /repo (user)] user a/1003635 git-upload-pack./repo 1ms 69808ms 2506ms 0ms 0ms 3080ms 0ms 0ms 3080ms 8915 7 9 809 0 git/2.26.2

[2021-01-08 04:31:22,638 +0200] 427e4492 [SSH git-upload-pack /repo (user)] user a/1003635 git-upload-pack./repo 1ms 67835ms -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 0

[2021-01-08 04:31:20,563 +0200] 7fe50bec [SSH git-upload-pack repo (user)] user a/1003635 git-upload-pack.repo 0ms 67425ms -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 0

Thread dump below: 

"SSH git-upload-pack /repo (user)-Timer" daemon prio=1 TIMED_WAITING

java.lang.Object.wait(Native Method)

org.eclipse.jgit.util.io.InterruptTimer$AlarmState.run(InterruptTimer.java:198)

java.lang.Thread.run(Thread.java:748)

"SSH git-upload-pack /repo (user)-Timer" daemon prio=1 TIMED_WAITING

java.lang.Object.wait(Native Method)

org.eclipse.jgit.util.io.InterruptTimer$AlarmState.run(InterruptTimer.java:198)

java.lang.Thread.run(Thread.java:748)

"SSH git-upload-pack /repo (user)-Timer" daemon prio=1 TIMED_WAITING

java.lang.Object.wait(Native Method)

org.eclipse.jgit.util.io.InterruptTimer$AlarmState.run(InterruptTimer.java:198)

java.lang.Thread.run(Thread.java:748)

"SSH git-upload-pack repo (user)" prio=1 RUNNABLE

dk.brics.automaton.MinimizationOperations.minimizeHopcroft(MinimizationOperations.java:361)

dk.brics.automaton.MinimizationOperations.minimize(MinimizationOperations.java:65)

dk.brics.automaton.Automaton.minimize(Automaton.java:967)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:334)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:347)

dk.brics.automaton.RegExp.findLeaves(RegExp.java:412)

dk.brics.automaton.RegExp.findLeaves(RegExp.java:409)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:331)

dk.brics.automaton.RegExp.toAutomatonAllowMutate(RegExp.java:308)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:227)

com.google.gerrit.server.util.MostSpecificComparator.finite(MostSpecificComparator.java:97)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:59)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:52)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:43)

java.util.TimSort.binarySort(TimSort.java:296)

java.util.TimSort.sort(TimSort.java:221)

java.util.Arrays.sort(Arrays.java:1512)

java.util.ArrayList.sort(ArrayList.java:1462)

com.google.gerrit.server.permissions.SectionSortCache.sort(SectionSortCache.java:90)

com.google.gerrit.server.permissions.PermissionCollection$Factory.filter(PermissionCollection.java:149)

com.google.gerrit.server.permissions.ProjectControl.controlForRef(ProjectControl.java:123)

com.google.gerrit.server.permissions.ProjectControl$ForProjectImpl.ref(ProjectControl.java:352)

com.google.gerrit.server.permissions.DefaultRefFilter.canReadRef(DefaultRefFilter.java:400)

com.google.gerrit.server.permissions.DefaultRefFilter.filter(DefaultRefFilter.java:216)

com.google.gerrit.server.permissions.ProjectControl$ForProjectImpl.filter(ProjectControl.java:410)

com.google.gerrit.server.git.DefaultAdvertiseRefsHook.getAdvertisedRefs(DefaultAdvertiseRefsHook.java:45)

org.eclipse.jgit.transport.AbstractAdvertiseRefsHook.advertiseRefs(AbstractAdvertiseRefsHook.java:64)

org.eclipse.jgit.transport.UploadPack.getAdvertisedOrDefaultRefs(UploadPack.java:809)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1371)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1337)

org.eclipse.jgit.transport.UploadPack.service(UploadPack.java:891)

org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:776)

com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:78)

com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:98)

com.google.gerrit.sshd.AbstractGitCommand.access$000(AbstractGitCommand.java:31)

com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:63)

com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:467)

com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:83)

java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

java.util.concurrent.FutureTask.run(FutureTask.java:266) java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:646)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

java.lang.Thread.run(Thread.java:748)

"SSH git-upload-pack repo (user)-Timer" daemon prio=1 TIMED_WAITING

java.lang.Object.wait(Native Method)

org.eclipse.jgit.util.io.InterruptTimer$AlarmState.run(InterruptTimer.java:198)

java.lang.Thread.run(Thread.java:748)

"SSH git-upload-pack /repo (user)" prio=1 RUNNABLE

dk.brics.automaton.MinimizationOperations.minimizeHopcroft(MinimizationOperations.java:366)

dk.brics.automaton.MinimizationOperations.minimize(MinimizationOperations.java:65)

dk.brics.automaton.Automaton.minimize(Automaton.java:967)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:334)

dk.brics.automaton.RegExp.toAutomatonAllowMutate(RegExp.java:308)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:227)

com.google.gerrit.server.util.MostSpecificComparator.transitions(MostSpecificComparator.java:109)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:70)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:52)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:43)

java.util.TimSort.binarySort(TimSort.java:296)

java.util.TimSort.sort(TimSort.java:221)

java.util.Arrays.sort(Arrays.java:1512)

java.util.ArrayList.sort(ArrayList.java:1462)

com.google.gerrit.server.permissions.SectionSortCache.sort(SectionSortCache.java:90)

com.google.gerrit.server.permissions.PermissionCollection$Factory.filter(PermissionCollection.java:149)

com.google.gerrit.server.permissions.ProjectControl.controlForRef(ProjectControl.java:123)

com.google.gerrit.server.permissions.ProjectControl$ForProjectImpl.ref(ProjectControl.java:352)

com.google.gerrit.server.permissions.DefaultRefFilter.canReadRef(DefaultRefFilter.java:400)

com.google.gerrit.server.permissions.DefaultRefFilter.filter(DefaultRefFilter.java:216)

com.google.gerrit.server.permissions.ProjectControl$ForProjectImpl.filter(ProjectControl.java:410)

com.google.gerrit.server.git.DefaultAdvertiseRefsHook.getAdvertisedRefs(DefaultAdvertiseRefsHook.java:45)

org.eclipse.jgit.transport.AbstractAdvertiseRefsHook.advertiseRefs(AbstractAdvertiseRefsHook.java:64)

org.eclipse.jgit.transport.UploadPack.getAdvertisedOrDefaultRefs(UploadPack.java:809)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1371)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1337)

org.eclipse.jgit.transport.UploadPack.service(UploadPack.java:891)

org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:776)

com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:78)

com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:98)

com.google.gerrit.sshd.AbstractGitCommand.access$000(AbstractGitCommand.java:31)

com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:63)

com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:467)

com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:83)

java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

java.util.concurrent.FutureTask.run(FutureTask.java:266) java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:646)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

java.lang.Thread.run(Thread.java:748)

"SSH git-upload-pack /repo (user)" prio=1 RUNNABLE

dk.brics.automaton.MinimizationOperations.minimizeHopcroft(MinimizationOperations.java:361)

dk.brics.automaton.MinimizationOperations.minimize(MinimizationOperations.java:65)

dk.brics.automaton.Automaton.minimize(Automaton.java:967)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:334)

dk.brics.automaton.RegExp.toAutomatonAllowMutate(RegExp.java:308)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:227)

com.google.gerrit.server.util.MostSpecificComparator.transitions(MostSpecificComparator.java:109)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:70)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:52)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:43)

java.util.TimSort.binarySort(TimSort.java:296)

java.util.TimSort.sort(TimSort.java:221)

java.util.Arrays.sort(Arrays.java:1512)

java.util.ArrayList.sort(ArrayList.java:1462)

com.google.gerrit.server.permissions.SectionSortCache.sort(SectionSortCache.java:90)

com.google.gerrit.server.permissions.PermissionCollection$Factory.filter(PermissionCollection.java:149)

com.google.gerrit.server.permissions.ProjectControl.controlForRef(ProjectControl.java:123)

com.google.gerrit.server.permissions.ProjectControl$ForProjectImpl.ref(ProjectControl.java:352)

com.google.gerrit.server.permissions.DefaultRefFilter.canReadRef(DefaultRefFilter.java:400)

com.google.gerrit.server.permissions.DefaultRefFilter.filter(DefaultRefFilter.java:216)

com.google.gerrit.server.permissions.ProjectControl$ForProjectImpl.filter(ProjectControl.java:410)

com.google.gerrit.server.git.DefaultAdvertiseRefsHook.getAdvertisedRefs(DefaultAdvertiseRefsHook.java:45)

org.eclipse.jgit.transport.AbstractAdvertiseRefsHook.advertiseRefs(AbstractAdvertiseRefsHook.java:64)

org.eclipse.jgit.transport.UploadPack.getAdvertisedOrDefaultRefs(UploadPack.java:809)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1371)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1337)

org.eclipse.jgit.transport.UploadPack.service(UploadPack.java:891)

org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:776)

com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:78)

com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:98)

com.google.gerrit.sshd.AbstractGitCommand.access$000(AbstractGitCommand.java:31)

com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:63)

com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:467)

com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:83)

java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

java.util.concurrent.FutureTask.run(FutureTask.java:266) java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:646)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

java.lang.Thread.run(Thread.java:748)

"SSH git-upload-pack /repo (user)" prio=1 RUNNABLE

dk.brics.automaton.MinimizationOperations.minimizeHopcroft(MinimizationOperations.java:320)

dk.brics.automaton.MinimizationOperations.minimize(MinimizationOperations.java:65)

dk.brics.automaton.Automaton.minimize(Automaton.java:967)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:326)

dk.brics.automaton.RegExp.findLeaves(RegExp.java:412)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:330)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:347)

dk.brics.automaton.RegExp.findLeaves(RegExp.java:412)

dk.brics.automaton.RegExp.findLeaves(RegExp.java:409)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:331)

dk.brics.automaton.RegExp.toAutomatonAllowMutate(RegExp.java:308)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:227)

com.google.gerrit.server.util.MostSpecificComparator.transitions(MostSpecificComparator.java:109)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:70)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:52)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:43)

java.util.TimSort.binarySort(TimSort.java:296)

java.util.TimSort.sort(TimSort.java:221)

java.util.Arrays.sort(Arrays.java:1512)

java.util.ArrayList.sort(ArrayList.java:1462)

com.google.gerrit.server.permissions.SectionSortCache.sort(SectionSortCache.java:90)

com.google.gerrit.server.permissions.PermissionCollection$Factory.filter(PermissionCollection.java:149)

com.google.gerrit.server.permissions.ProjectControl.controlForRef(ProjectControl.java:123)

com.google.gerrit.server.permissions.ProjectControl$ForProjectImpl.ref(ProjectControl.java:352)

com.google.gerrit.server.permissions.DefaultRefFilter.canReadRef(DefaultRefFilter.java:400)

com.google.gerrit.server.permissions.DefaultRefFilter.filter(DefaultRefFilter.java:216)

com.google.gerrit.server.permissions.ProjectControl$ForProjectImpl.filter(ProjectControl.java:410)

com.google.gerrit.server.git.DefaultAdvertiseRefsHook.getAdvertisedRefs(DefaultAdvertiseRefsHook.java:45)

org.eclipse.jgit.transport.AbstractAdvertiseRefsHook.advertiseRefs(AbstractAdvertiseRefsHook.java:64)

org.eclipse.jgit.transport.UploadPack.getAdvertisedOrDefaultRefs(UploadPack.java:809)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1371)

org.eclipse.jgit.transport.UploadPack.sendAdvertisedRefs(UploadPack.java:1337)

org.eclipse.jgit.transport.UploadPack.service(UploadPack.java:891)

org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:776)

com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:78)

com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:98)

com.google.gerrit.sshd.AbstractGitCommand.access$000(AbstractGitCommand.java:31)

com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:63)

com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:467)

com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:83)

java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

java.util.concurrent.FutureTask.run(FutureTask.java:266) java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:646)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

java.lang.Thread.run(Thread.java:748)

Regards,

Challs 

[Luca Milanesio]

On 8 Jan 2021, at 04:38, David Charles T M <davidch...@gmail.com> wrote:

H Luca,

@David did you manage to get the JVM thread-dump to confirm what is blocking the Git/SSH execution?

We were able to get thread dump once when the upload-pack operation went above 60s. As there were multiple upload-pack operations running at same time, we are unable to point it to the right thread.

Anyway, all of them are stuck in the refs filtering: how many refs are in the repository?

Luca.

[David Charles T M]

Hi Luca,

Anyway, all of them are stuck in the refs filtering: how many refs are in the repository?

We have 93458 references in the repo. Below given is the references count shown in fetch output with GIT_TRACE_PACKET enabled.

 └─$ cat //opt/perf/out_files/gq.RtgydB | grep 'packet:'  | awk {'print $NF'} | cut -d / -f2 | sort | uniq -c

      2 0000

    125 cache-automerge

  31832 changes

   1930 heads

      1 meta

      1 notes

 116088 tags

   1479 users

Regards,

Challs

[Sven Selberg]

Wow! That's a lot of tags.
Given that there's one meta ref in the "refs/changes" namespace for each change and I would guess that there's an average of at least 2 patchsets, you have ~10 tags for each change!

 

   1479 users

Regards,

Challs

[David Charles T M]

Hi Sven,

Actually tag count is 58K. We had 1Lakh changes in the repo, recently we have split the repo and moved all closed changes to archival repo. So change references count was reduced.

[gerrit@host repo.git]$git tag -l | wc -l

58106

Regards,

Challs

[Matthias Sohn]

All these threads are busy sorting permissions for all refs in order to compute which refs to advertise to the client

which sent a fetch request.

Try to increase the size of the cache "permission_sort" [1]. Sorting the permission sections can be expensive

when regular expressions are used, this cache remembers the ordering for each branch.

[1] https://gerrit-documentation.storage.googleapis.com/Documentation/2.16.22/config-gerrit.html#cache_names

 

--

--
To unsubscribe, email repo-discuss...@googlegroups.com
More info at http://groups.google.com/group/repo-discuss?hl=en

---
You received this message because you are subscribed to the Google Groups "Repo and Gerrit Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to repo-discuss...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/CABwvxzrAMhauNjhQ6%3DXJ0tLBpk2-5K%2Bnq8Af%3DMVqb1-M1cjY7g%40mail.gmail.com.

[Shaohui Liu]

@David Charles

If you see all the operations hung on RegExp toAutomaton operations,  you can check if there are too complexed access regexes added in the project recently.

We encountered a simlar problem yesterday and it don't work to enlarge the permisson cache. 

After we add a debug log, we found the the very bad performance of RefPattern.toRegExp(pattern).toAutomaton() in MostSpecificComparator.java for some  access regexes.

```

[2021-08-12T00:44:48.441+0800] [HTTP GET /changes/?O=881&S=0&n=25&q=status%3Aopen%20-is%3Awip (xxxx from 127.0.0.1)] INFO com.google.gerrit.server.util.MostSpecificComparator : pattern: ^refs/heads/(.*-camellia-.*|.*-iris-.*|.*-merlin-.*|.*-selene-.*|.*-curtana-.*|.*-dandelion-.*|.*-fleur-.*|.*-ginkgo-.*|.*-mojito-.*|.*-rosemary-.*|.*-lime-.*|.*-evergreen-.*) cost too long: 17781 ms

```

When we removed that regex,  the system is recovered. Hope this helps~

```

dk.brics.automaton.MinimizationOperations.minimizeHopcroft(MinimizationOperations.java:320)

dk.brics.automaton.MinimizationOperations.minimize(MinimizationOperations.java:65)

dk.brics.automaton.Automaton.minimize(Automaton.java:967)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:326)

dk.brics.automaton.RegExp.findLeaves(RegExp.java:412)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:330)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:347)

dk.brics.automaton.RegExp.findLeaves(RegExp.java:412)

dk.brics.automaton.RegExp.findLeaves(RegExp.java:409)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:331)

dk.brics.automaton.RegExp.toAutomatonAllowMutate(RegExp.java:308)

dk.brics.automaton.RegExp.toAutomaton(RegExp.java:227)

com.google.gerrit.server.util.MostSpecificComparator.transitions(MostSpecificComparator.java:109)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:70)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:52)

com.google.gerrit.server.util.MostSpecificComparator.compare(MostSpecificComparator.java:43)

```

[davidch...@gmail.com]

Hi,

Actually our issue was mainly with SSHD operations. After some repo cleanup, it reduced. But still long SSH duration are visible in logs.

If you see all the operations hung on RegExp toAutomaton operations,  you can check if there are too complexed access regexes added in the project recently.

We encountered a simlar problem yesterday and it don't work to enlarge the permisson cache. 

After we add a debug log, we found the the very bad performance of RefPattern.toRegExp(pattern).toAutomaton() in MostSpecificComparator.java for some  access regexes.

Regards,

Challs