504 timeout error on submitting review via the reply button

[Dharama Rao Bala]

Hi Team,

We are getting 504 gateway timeout errors from Gerrit when submitting reviews via the reply button on a intermittent base!
Actually it looks like Gerrit is able to take/apply the changes in the backend but seems, it is not able to respond back to UI in a timely fashion. 
We are on Gerrit version 3.4.1. We started seeing these errors after upgraded Gerrit from 3.0.16 to 3.4.1.
We are not able to find any errors in error_log file / replication_log files.
Any of your advice will be highly appreciated.

Thanks & Regards,
Dharama Rao.

[Martin Fick]

On 2022-02-01 14:34, 'Dharama Rao Bala' via Repo and Gerrit Discussion
wrote:

Sounds like either a plugin/hook delaying things, or more likely java GC
slowing things down. I would monitor your resources usage, and see how
memory/CPU is doing, I believe that 3.4.1 uses more memory than 3.0.16.
Lastly, be sure to disable swap on your Gerrit host, it tends to be a
disaster with java,

-Martin


--
The Qualcomm Innovation Center, Inc. is a member of Code
Aurora Forum, hosted by The Linux Foundation

[Dharama Rao Bala]

Thanks Martin for the immediate response.

Yup, 3.4.1 is memory intensive and we had increased our instance capacity at the time of upgrade. Swap is already disabled.
Current cpu and memory usage looks good. 
Any idea how to check if it is due to any plugin /hook as you mentioned above?

--
--
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/badd6b91ac10ae863e9e38dd0ed4154d%40codeaurora.org.

[Martin Fick]

On 2022-02-01 16:04, Dharama Rao Bala wrote:
> Thanks Martin for the immediate response.
> Yup, 3.4.1 is memory intensive and we had increased our instance
> capacity at the time of upgrade. Swap is already disabled.
> Current cpu and memory usage looks good.
> Any idea how to check if it is due to any plugin /hook as you
> mentioned above?

Determine what you have installed. Unfortunately I'm not that
familiar with what's available to help in 3.4. Check the logs,
use the trace feature? Use the metrics plugin?

[Luca Milanesio]

> On 1 Feb 2022, at 23:16, Martin Fick <mf...@codeaurora.org> wrote:
>
> On 2022-02-01 16:04, Dharama Rao Bala wrote:
>> Thanks Martin for the immediate response.
>> Yup, 3.4.1 is memory intensive and we had increased our instance
>> capacity at the time of upgrade. Swap is already disabled.
>> Current cpu and memory usage looks good.
>> Any idea how to check if it is due to any plugin /hook as you
>> mentioned above?
>
> Determine what you have installed. Unfortunately I'm not that
> familiar with what's available to help in 3.4. Check the logs,
> use the trace feature? Use the metrics plugin?

+ a JVM thread dump?

It would be interesting to know what is Gerrit doing whilst the reverse-proxy is waiting for a response.

Luca.

>
> -Martin
>
> --
> The Qualcomm Innovation Center, Inc. is a member of Code
> Aurora Forum, hosted by The Linux Foundation
>

> --
> --
> 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/3288acfb983f136573dc2cc09a1be877%40codeaurora.org.

[Dharama Rao Bala]

Yup, Generated multiple thread dumps, here is a screenshot of it, all of them shows waiting on a blocked thread.
I have attached the  stacktrace of blocked thread and http statistics.

Any of your suggestions highly appreciated .

[Luca Milanesio]

On 11 Feb 2022, at 00:12, 'Dharama Rao Bala' via Repo and Gerrit Discussion <repo-d...@googlegroups.com> wrote:

Yup, Generated multiple thread dumps, here is a screenshot of it, all of them shows waiting on a blocked thread.

Can you share the thread dump in TXT format? The javamelody screenshot isn’t helpful, unfortunately.

I have attached the  stacktrace of blocked thread and http statistics.

I cannot see any stack trace of the blocked threads: can you check and re-send it?

Luca.

To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/ae92c455-46a0-4ce0-a411-70540c67f4b6n%40googlegroups.com.
<Screen Shot 2022-02-10 at 4.09.55 PM.png><Screen Shot 2022-02-10 at 3.59.53 PM.png><Screen Shot 2022-02-10 at 4.04.21 PM.png><Screen Shot 2022-02-10 at 3.57.36 PM.png>

[Dharama Rao Bala]

Sure. sent the thread dump in another mail.
Here is the stack trace of the blocked thread>

HTTP POST /changes/continuous-delivery%2Fgerrit-replication-test~356153/revisions/1/review (dharama.raobala from 10.141.0.100)

PRIORITY : 5

THREAD ID : 0X00007FB12C398000

NATIVE ID : 0X2B7D

NATIVE ID (DECIMAL) : 11133

STATE : BLOCKED

stackTrace:
java.lang.Thread.State: BLOCKED (on object monitor)
at com.googlesource.gerrit.plugins.replication.Destination.schedule(Destination.java:427)
- waiting to lock <0x000000032b8dbf08> (a java.lang.Object)
at com.googlesource.gerrit.plugins.replication.ReplicationQueue.pushReference(ReplicationQueue.java:192)
at com.googlesource.gerrit.plugins.replication.ReplicationQueue.fire(ReplicationQueue.java:160)
at com.googlesource.gerrit.plugins.replication.ReplicationQueue.fire(ReplicationQueue.java:141)
at com.googlesource.gerrit.plugins.replication.ReplicationQueue.onGitReferenceUpdated(ReplicationQueue.java:136)
at com.google.gerrit.server.extensions.events.GitReferenceUpdated.lambda$fire$0(GitReferenceUpdated.java:154)
at com.google.gerrit.server.extensions.events.GitReferenceUpdated$$Lambda$1228/0x0000000840c1e040.run(Unknown Source)
at com.google.gerrit.server.plugincontext.PluginContext.runLogExceptions(PluginContext.java:206)
at com.google.gerrit.server.plugincontext.PluginSetContext.lambda$runEach$1(PluginSetContext.java:148)
at com.google.gerrit.server.plugincontext.PluginSetContext$$Lambda$317/0x000000084049c840.accept(Unknown Source)
at java.lang.Iterable.forEach(java.base@11.0.13/Iterable.java:75)
at com.google.gerrit.server.plugincontext.PluginSetContext.runEach(PluginSetContext.java:148)
at com.google.gerrit.server.extensions.events.GitReferenceUpdated.fire(GitReferenceUpdated.java:154)
at com.google.gerrit.server.extensions.events.GitReferenceUpdated.fire(GitReferenceUpdated.java:130)
at com.google.gerrit.server.update.BatchUpdate.fireRefChangeEvent(BatchUpdate.java:562)
at com.google.gerrit.server.update.BatchUpdate$$Lambda$1344/0x0000000840c6f840.accept(Unknown Source)
at com.google.common.collect.ImmutableList.forEach(ImmutableList.java:406)
at com.google.gerrit.server.update.BatchUpdate.execute(BatchUpdate.java:164)
at com.google.gerrit.server.update.BatchUpdate.execute(BatchUpdate.java:412)
at com.google.gerrit.server.restapi.change.PostReview.apply(PostReview.java:394)
at com.google.gerrit.server.restapi.change.PostReview.apply(PostReview.java:239)
at com.google.gerrit.server.restapi.change.PostReview.apply(PostReview.java:151)
at com.google.gerrit.httpd.restapi.RestApiServlet.lambda$invokeRestModifyViewWithRetry$7(RestApiServlet.java:834)
at com.google.gerrit.httpd.restapi.RestApiServlet$$Lambda$1680/0x0000000840d94040.call(Unknown Source)
at com.google.gerrit.server.update.RetryHelper$$Lambda$1135/0x0000000840bb5040.call(Unknown Source)
at com.github.rholder.retry.AttemptTimeLimiters$NoAttemptTimeLimit.call(AttemptTimeLimiters.java:78)
at com.github.rholder.retry.Retryer.call(Retryer.java:160)
at com.google.gerrit.server.update.RetryHelper.executeWithTimeoutCount(RetryHelper.java:561)
at com.google.gerrit.server.update.RetryHelper.execute(RetryHelper.java:504)
at com.google.gerrit.server.update.RetryableAction.call(RetryableAction.java:172)
at com.google.gerrit.httpd.restapi.RestApiServlet.invokeRestEndpointWithRetry(RestApiServlet.java:909)
at com.google.gerrit.httpd.restapi.RestApiServlet.invokeRestModifyViewWithRetry(RestApiServlet.java:829)
at com.google.gerrit.httpd.restapi.RestApiServlet.service(RestApiServlet.java:532)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:290)
at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:280)
at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:184)
at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:89)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:85)
at com.google.gerrit.httpd.raw.StaticModule$PolyGerritFilter.doFilter(StaticModule.java:392)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.gerrit.httpd.GetUserFilter.doFilter(GetUserFilter.java:92)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.gerrit.httpd.RequireSslFilter.doFilter(RequireSslFilter.java:72)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.gerrit.httpd.RunAsFilter.doFilter(RunAsFilter.java:120)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.gerrit.httpd.SetThreadNameFilter.doFilter(SetThreadNameFilter.java:62)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.gerrit.httpd.AllRequestFilter$FilterProxy$1.doFilter(AllRequestFilter.java:139)
at com.google.gerrit.httpd.AllowRenderInFrameFilter.doFilter(AllowRenderInFrameFilter.java:56)
at com.google.gerrit.httpd.AllRequestFilter$FilterProxy$1.doFilter(AllRequestFilter.java:135)
at com.google.gerrit.httpd.AllRequestFilter$FilterProxy.doFilter(AllRequestFilter.java:141)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.gerrit.httpd.RequestCleanupFilter.doFilter(RequestCleanupFilter.java:60)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.gerrit.httpd.RequestMetricsFilter.doFilter(RequestMetricsFilter.java:92)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.gerrit.httpd.RequestContextFilter.doFilter(RequestContextFilter.java:64)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:121)
at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:133)
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1435)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1350)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:516)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388)
at org.eclipse.jetty.server.HttpChannel$$Lambda$1082/0x0000000840b6f440.dispatch(Unknown Source)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905)
at java.lang.Thread.run(java.base@11.0.13/Thread.java:829)
Locked ownable synchronizers:
- <0x000000049616b458> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

[Luca Milanesio]

> On 11 Feb 2022, at 00:29, Dharama Rao Bala <dharama...@lookout.com> wrote:
>
> Sure. sent the thread dump in another mail.
> Here is the stack trace of the blocked thread>
> HTTP POST /changes/continuous-delivery%2Fgerrit-replication-test~356153/revisions/1/review (dharama.raobala from 10.141.0.100)
> PRIORITY : 5
>
> THREAD ID : 0X00007FB12C398000
>
> NATIVE ID : 0X2B7D
>
> NATIVE ID (DECIMAL) : 11133
>
> STATE : BLOCKED
>
>
> stackTrace:
> java.lang.Thread.State: BLOCKED (on object monitor)
> at com.googlesource.gerrit.plugins.replication.Destination.schedule(Destination.java:427)
> - waiting to lock <0x000000032b8dbf08> (a java.lang.Object)

You need to see who is locking the object <0x000000032b8dbf08> in the other threads.

Do you use Git/SSH for replicating to the other Gerrit replicas?
Luca.

> at com.googlesource.gerrit.plugins.replication.ReplicationQueue.pushReference(ReplicationQueue.java:192)
> at com.googlesource.gerrit.plugins.replication.ReplicationQueue.fire(ReplicationQueue.java:160)
> at com.googlesource.gerrit.plugins.replication.ReplicationQueue.fire(ReplicationQueue.java:141)
> at com.googlesource.gerrit.plugins.replication.ReplicationQueue.onGitReferenceUpdated(ReplicationQueue.java:136)
> at com.google.gerrit.server.extensions.events.GitReferenceUpdated.lambda$fire$0(GitReferenceUpdated.java:154)
> at com.google.gerrit.server.extensions.events.GitReferenceUpdated$$Lambda$1228/0x0000000840c1e040.run(Unknown Source)
> at com.google.gerrit.server.plugincontext.PluginContext.runLogExceptions(PluginContext.java:206)
> at com.google.gerrit.server.plugincontext.PluginSetContext.lambda$runEach$1(PluginSetContext.java:148)
> at com.google.gerrit.server.plugincontext.PluginSetContext$$Lambda$317/0x000000084049c840.accept(Unknown Source)

> at java.lang.Iterable.forEach(java...@11.0.13/Iterable.java:75)

> at java.lang.Thread.run(java...@11.0.13/Thread.java:829)

[Dharama Rao Bala]

Yup, Once code is merged , data will be replicated to Github.

This is occurring at the time, when the reviewer clicks the review /verify button. 

Here I am sharing the thread dump file here

https://drive.google.com/drive/u/0/folders/1_jSzierK0tQ7O2LF93WNwIKS3mqJBGYw

[Luca Milanesio]

> On 11 Feb 2022, at 00:53, Dharama Rao Bala <dharama...@lookout.com> wrote:
>
> Yup, Once code is merged , data will be replicated to Github.
> This is occurring at the time, when the reviewer clicks the review /verify button.
> Here I am sharing the thread dump file here
> https://drive.google.com/drive/u/0/folders/1_jSzierK0tQ7O2LF93WNwIKS3mqJBGYw
>
> On Thu, Feb 10, 2022 at 4:40 PM Luca Milanesio <luca.mi...@gmail.com> wrote:
>
>
> > On 11 Feb 2022, at 00:29, Dharama Rao Bala <dharama...@lookout.com> wrote:
> >
> > Sure. sent the thread dump in another mail.
> > Here is the stack trace of the blocked thread>
> > HTTP POST /changes/continuous-delivery%2Fgerrit-replication-test~356153/revisions/1/review (dharama.raobala from 10.141.0.100)
> > PRIORITY : 5
> >
> > THREAD ID : 0X00007FB12C398000
> >
> > NATIVE ID : 0X2B7D
> >
> > NATIVE ID (DECIMAL) : 11133
> >
> > STATE : BLOCKED
> >
> >
> > stackTrace:
> > java.lang.Thread.State: BLOCKED (on object monitor)
> > at com.googlesource.gerrit.plugins.replication.Destination.schedule(Destination.java:427)
> > - waiting to lock <0x000000032b8dbf08> (a java.lang.Object)
>
> You need to see who is locking the object <0x000000032b8dbf08> in the other threads.

Bingo: the object is locked by a pending push:

"ReplicateTo-fi-1[java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@2e025476[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@b5c5af3[Wrapped task = com.google.gerrit.server.logging.LoggingContextAwareRunnable@128ef3b0]]]" #73 prio=5 os_prio=0 cpu=418413959.65ms elapsed=488442.89s tid=0x00007fb10c067000 nid=0xa81 runnable [0x00007fb0e584d000]
java.lang.Thread.State: RUNNABLE
at java.io.FileInputStream.open0(java...@11.0.13/Native Method)
at java.io.FileInputStream.open(java...@11.0.13/FileInputStream.java:219)
at java.io.FileInputStream.<init>(java...@11.0.13/FileInputStream.java:157)
at org.eclipse.jgit.util.io.SilentFileInputStream.<init>(SilentFileInputStream.java:31)
at org.eclipse.jgit.util.IO.readSome(IO.java:68)
at org.eclipse.jgit.internal.storage.file.RefDirectory.scanRef(RefDirectory.java:1096)
at org.eclipse.jgit.internal.storage.file.RefDirectory.readRef(RefDirectory.java:1064)
at org.eclipse.jgit.internal.storage.file.RefDirectory.readAndResolve(RefDirectory.java:264)
at org.eclipse.jgit.internal.storage.file.RefDirectory.exactRef(RefDirectory.java:286)
at com.google.gerrit.server.notedb.AbstractChangeNotes.readRef(AbstractChangeNotes.java:166)
at com.google.gerrit.server.notedb.ChangeNotes.readRef(ChangeNotes.java:604)
at com.google.gerrit.server.notedb.AbstractChangeNotes.openHandle(AbstractChangeNotes.java:184)
at com.google.gerrit.server.notedb.AbstractChangeNotes.load(AbstractChangeNotes.java:154)
at com.google.gerrit.server.notedb.ChangeNotes$Factory.createChecked(ChangeNotes.java:120)
at com.google.gerrit.server.notedb.ChangeNotes$Factory.createChecked(ChangeNotes.java:124)
at com.google.gerrit.server.query.change.ChangeData.reloadChange(ChangeData.java:508)
at com.google.gerrit.server.query.change.ChangeData.change(ChangeData.java:497)
at com.google.gerrit.server.permissions.RefVisibilityControl.isVisible(RefVisibilityControl.java:95)
at com.google.gerrit.server.permissions.RefControl$ForRefImpl.can(RefControl.java:629)
at com.google.gerrit.server.permissions.RefControl$ForRefImpl.check(RefControl.java:516)
at com.google.gerrit.server.events.EventBroker.isVisibleTo(EventBroker.java:207)
at com.google.gerrit.server.events.EventBroker.fireEvent(EventBroker.java:142)
at com.google.gerrit.server.events.EventBroker.postEvent(EventBroker.java:97)
at com.googlesource.gerrit.plugins.replication.Destination.postReplicationFailedEvent(Destination.java:809)
at com.googlesource.gerrit.plugins.replication.Destination.reschedule(Destination.java:565)
>>>>>> - locked <0x000000032b8dbf08> (a java.lang.Object)
at com.googlesource.gerrit.plugins.replication.PushOne.doRunPushOperation(PushOne.java:482)
at com.googlesource.gerrit.plugins.replication.PushOne.runPushOperation(PushOne.java:389)
at com.googlesource.gerrit.plugins.replication.PushOne.lambda$run$2(PushOne.java:375)


It looks like the scanning of the refs is taking ages !!!!
How many refs do you have on this repo?
What type of filesystem are you using?

Luca.

[Dharama Rao Bala]

This repo has almost 200k refs :-(
Filesystem type is : ext4.
Let me clean this repo and commits. 
I have issues in other repos too.  but let me clean this repo and see how it works.

[Luca Milanesio]

On 11 Feb 2022, at 01:13, Dharama Rao Bala <dharama...@lookout.com> wrote:

This repo has almost 200k refs :-(
Filesystem type is : ext4.
Let me clean this repo and commits. 
I have issues in other repos too.  but let me clean this repo and see how it works.

Please avoid top-posting, just add your comments inline in the response.

200k refs *isn’t that much* ONLY IF they are packed. If they are all loose refs and then the filesystem is on spinning disks, well, it is going to be very slow.

Do you perform regular Git GC on those repos?

Luca.