stream-events stops working after several days of uptime

[Saša Živkov]

Version: Gerrit 2.9

As some of our users complained about their Jenkins Server (using the Gerrit Trigger Plugin)

not building new changes any more we found out that Gerrit't stream-events stopped sending

the events. After restarting Gerrit server the stream-events starts working again... for some days.

Looking at Gerrit's thread dumps I see that the "SSH-Stream-Worker-N" threads never awake

after entering the org.apache.sshd.common.channel.Window.wait() in the

org.apache.sshd.common.channel.Window.waitForSpace().

After some days, all SSH-Stream-Worker threads manage to reach that point and stay in the

wait state forever... The stack trace of such a thread looks like [1].

Anyone experiencing the same issue?

Saša

[1]

"SSH-Stream-Worker-4" cpu=50600.00 [reset 50600.00] ms elapsed=169149.20 [reset 169149.20] s allocated=216251025

io= file i/o: 7428288/0 B, net i/o: 0/0 B, files opened:0, socks opened:0  [reset file i/o: 7428288/0 B, net i/o

prio=10 tid=0x00007f221cc0d000 nid=0x73e5 / 29669  pthread-id=139783870990080 in Object.wait()  [_thread_blocked

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(J)V(Native Method)

        - waiting on <0x00007f22a7b62290> (a org.apache.sshd.common.channel.Window)

        at java.lang.Object.wait()V(Object.java:503)

        at org.apache.sshd.common.channel.Window.waitForSpace()I(Window.java:148)

        - locked <0x00007f22a7b62290> (a org.apache.sshd.common.channel.Window)

        at org.apache.sshd.common.channel.ChannelOutputStream.flush()V(ChannelOutputStream.java:116)

        - locked <0x00007f22a7b62478> (a org.apache.sshd.common.channel.ChannelOutputStream)

        at sun.nio.cs.StreamEncoder.implFlush()V(StreamEncoder.java:297)

        at sun.nio.cs.StreamEncoder.flush()V(StreamEncoder.java:141)

        - locked <0x00007f22a7b83618> (a java.io.OutputStreamWriter)

        at java.io.OutputStreamWriter.flush()V(OutputStreamWriter.java:229)

        at java.io.BufferedWriter.flush()V(BufferedWriter.java:254)

        - locked <0x00007f22a7b83618> (a java.io.OutputStreamWriter)

        at java.io.PrintWriter.flush()V(PrintWriter.java:320)

        - locked <0x00007f22a7b835d0> (a java.io.BufferedWriter)

        at java.io.PrintWriter.checkError()Z(PrintWriter.java:357)

        at com.google.gerrit.sshd.commands.StreamEvents.writeEvents()V(StreamEvents.java:186)

        at com.google.gerrit.sshd.commands.StreamEvents.access$100(Lcom/google/gerrit/sshd/commands/StreamEvents

        at com.google.gerrit.sshd.commands.StreamEvents$3.run()V(StreamEvents.java:82)

        at java.util.concurrent.Executors$RunnableAdapter.call()Ljava/lang/Object;(Executors.java:471)

        at java.util.concurrent.FutureTask.run()V(FutureTask.java:262)

        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Ljava/util/concurrent

        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run()V(ScheduledThreadPoolExecut

        at com.google.gerrit.server.git.WorkQueue$Task.run()V(WorkQueue.java:364)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V(

        at java.util.concurrent.ThreadPoolExecutor$Worker.run()V(ThreadPoolExecutor.java:615)

        at java.lang.Thread.run()V(Thread.java:812)

[Francois Valdy]

Hi,

We're having the same issue with Gerrit 2.8.5, ssh-worker threads get stuck at this exact stack trace (on an average 1 would get stuck per day, with 4 active stream-events listeners), and when all are stuck, no further event is pushed to subscribers.

It doesn't get sorted/unfreeze if the listeners get disconnected.

I've upgrade sshd-core from 0.11.1-atlassian to 0.12.0 (simply updated the jar inside the war, no migration/rebuild required) yesterday, and so far I haven't seen any thread get stuck.

I suspected this change [1] could be related, but failed to find any hard proof.

I'll update this thread if the issue re-occurs (or not).

[1] https://github.com/apache/mina-sshd/commit/1a84ede6bcdc7b93338bef8427c4a3fee96ad61f

[Shawn Pearce]

On Fri, Aug 1, 2014 at 7:48 AM, Francois Valdy <francoi...@gmail.com> wrote:

Hi,

We're having the same issue with Gerrit 2.8.5, ssh-worker threads get stuck at this exact stack trace (on an average 1 would get stuck per day, with 4 active stream-events listeners), and when all are stuck, no further event is pushed to subscribers.

It doesn't get sorted/unfreeze if the listeners get disconnected.

I've upgrade sshd-core from 0.11.1-atlassian to 0.12.0 (simply updated the jar inside the war, no migration/rebuild required) yesterday, and so far I haven't seen any thread get stuck.

I suspected this change [1] could be related, but failed to find any hard proof.

I'll update this thread if the issue re-occurs (or not).

[1] https://github.com/apache/mina-sshd/commit/1a84ede6bcdc7b93338bef8427c4a3fee96ad61f

This change shouldn't be the culprit. IIRC the TcpipServerChannel handles port forwarding (disabled in Gerrit), while stream events is a more typical command channel.

My first guess is, a client disconnected and the server doesn't know. We are trying to send a message to a dead channel. Instead of erroring out the thread is waiting for space to transmit, as the client's output buffer is now full because its not draining data.

[Francois Valdy]

You're probably right.

FTR we've got one SSH stream worker thread stuck today, so the upgrade to 0.12.0 doesn't fix it.

[Bassem Rabil]

We reproduced this issue with Gerrit 2.9 using the below steps. For a machine with 4 CPU we got 5 waiting threads for SSH-Stream-Worker, I am expecting that larger machines with more CPUs will have more stuck threads and this issue would have more impact on the Gerrit instance.

1. Start new Gerrit instance

- No SSH-Stream-Worker threads

2. Start 2 new terminals with stream-events      

- Two threads created and events are streamed smoothly

SSH-Stream-Worker-1 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-2 no 1 WAITING sun.misc.Unsafe.park(Native Method)

3. Kill stream events terminals

- Five threads are waiting for stream-events and nothing is streamed. Number of CPUs for the host is 4 CPU, I think the number of threads would be number of CPUs +1. For larger machines with more CPUs, this will be affecting the performance significantly.

SSH-Stream-Worker-1 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-2 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-3 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-4 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-5 no 1 WAITING sun.misc.Unsafe.park(Native Method)

4. Restart the 2 terminals with stream-events

- Five threads are waiting for stream-events and events are streamed smoothly

SSH-Stream-Worker-1 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-2 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-3 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-4 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-5 no 1 WAITING sun.misc.Unsafe.park(Native Method)

5. Kill thread SSH-Stream-Worker-5 using javamelody plugin kill thread.

- Five threads are waiting for stream-events and events are NOT streamed anymore

SSH-Stream-Worker-1 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-2 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-3 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-4 no 1 WAITING sun.misc.Unsafe.park(Native Method)

SSH-Stream-Worker-6 no 1 WAITING sun.misc.Unsafe.park(Native Method)

[Saša Živkov]

These looks OK.

A blocked SSH-Stream-Worker thread is in WAITING state on in the

Object.wait method called from the waitForSpace method from the apache mina:

"SSH-Stream-Worker-9" ...

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(J)V(Native Method)

        - waiting on <0x00007f0f20e4d3a8> (a org.apache.sshd.common.channel.Window)

        at java.lang.Object.wait()V(Object.java:503)

        at org.apache.sshd.common.channel.Window.waitForSpace()I(Window.java:148)

 ....

--
--
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.
For more options, visit https://groups.google.com/d/optout.

[Shawn Pearce]

But I think these are dead client connections. So the thread is blocked waiting forever for space that will never be granted by the long gone client.

[Saša Živkov]

Yes, when we see a SSH-Stream-Worker thread being blocked in Object.wait which was called from the

org.apache.sshd.common.channel.Window.waitForSpace

then it will never recover.

However, I was commenting on the SSH-Stream-Worker waiting on sun.misc.Unsafe.park(...).

These stack traces looks like:

"SSH-Stream-Worker-10" ...

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(ZJ)V(Native Method)

        - parking to wait for  <0x00007f0f1b5dd540> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

        at java.util.concurrent.locks.LockSupport.park(Ljava/lang/Object;)V(LockSupport.java:186)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await()V(AbstractQueuedSynchronizer.java:2043)

        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take()Ljava/util/concurrent/RunnableScheduledFuture;(ScheduledThreadPoolExecutor.

        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take()Ljava/lang/Object;(ScheduledThreadPoolExecutor.java:807)

        at java.util.concurrent.ThreadPoolExecutor.getTask()Ljava/lang/Runnable;(ThreadPoolExecutor.java:1068)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V(ThreadPoolExecutor.java:1130)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run()V(ThreadPoolExecutor.java:615)

        at java.lang.Thread.run()V(Thread.java:812)

and, for me, this looks like a normal case where this thread is waiting in its thread pool.

At least on our Gerrit system I observe that as long as we have at least one SSH-Stream-Worker in that

state the events are being sent.

[olgagr...@gmail.com]

Hi,

Looking at the Gerrit thread dump below:

java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(J)V(Native Method)

        - waiting on <0x00007f22a7b62290> (a org.apache.sshd.common.channel.Window)

        at java.lang.Object.wait()V(Object.java:503)

        at org.apache.sshd.common.channel.Window.waitForSpace()I(Window.java:148)

        - locked <0x00007f22a7b62290> (a org.apache.sshd.common.channel.Window)

        at org.apache.sshd.common.channel.ChannelOutputStream.flush()V(ChannelOutputStream.java:116)

        - locked <0x00007f22a7b62478> (a org.apache.sshd.common.channel.ChannelOutputStream)

        at sun.nio.cs.StreamEncoder.implFlush()V(StreamEncoder.java:297)

        at sun.nio.cs.StreamEncoder.flush()V(StreamEncoder.java:141)

        - locked <0x00007f22a7b83618> (a java.io.OutputStreamWriter)

        at java.io.OutputStreamWriter.flush()V(OutputStreamWriter.java:229)

        at java.io.BufferedWriter.flush()V(BufferedWriter.java:254)

        - locked <0x00007f22a7b83618> (a java.io.OutputStreamWriter)

        at java.io.PrintWriter.flush()V(PrintWriter.java:320)

        - locked <0x00007f22a7b835d0> (a java.io.BufferedWriter)

        at java.io.PrintWriter.checkError()Z(PrintWriter.java:357)

        at com.google.gerrit.sshd.commands.StreamEvents.writeEvents()V(StreamEvents.java:186)

        at com.google.gerrit.sshd.commands.StreamEvents.access$100(Lcom/google/gerrit/sshd/commands/StreamEvents

In the class org.apache.sshd.common.channel.Window , line 148

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

the waiting happens when  the window size == 0 and it is not closed.

If you can enable logging at the debug level for the library “Apache MINA SSHD Project” you can try to confirm the size of the window. If the window is overflown then you will have a message logged like “Waiting for some space on …”. Perhaps the client streams too many events and the size of the window is too small. The Javadoc for this class states:

” A Window for a given channel.

 Windows are used to not overflow the client or server when sending datas. Both clients and servers have a local and remote window and won't send anymore data until the window has been expanded.”

I think the solution for this problem could be to allow to configure a bigger window depending on the anticipated load or expand the window at the run time without restarting Gerrit.

Regards,

Olga Grinberg

[Bassem Rabil]

Sasa,

Were you able to find a workaround for such issue other than restarting the instance ? Is it still re-occuring at your end ?

Thanks and Regards

Bassem Guendy

[Saša Živkov]

On Mon, Aug 11, 2014 at 8:12 PM, Bassem Rabil <bassem.ra...@ericsson.com> wrote:

Sasa,

Were you able to find a workaround for such issue other than restarting the instance ?

No :-(

 

Is it still re-occuring at your end ?

Yes... I have to restart our Gerrit server once every 1-2 weeks.

Usually, I don't wait until the stream-events is totally stuck... instead I create

thread dumps periodically and check how many of the SSH-Stream-Worker-*

threads are stuck. If it is more than 50% of them then I restart Gerrit.

[Hugo Arès]

Hi Saša,

We are planning to deploy 2.9 in production soon but we want to avoid restarting the server so I added an ssh command that re-size the pool of ssh-stream-workers as a temporary solution if we get the same problem. This will allow us to allocate more worker threads to compensate for the ones that are stuck.

How many thread do you have for ssh-stream-workers (I actually want to know how many threads get stuck over a 1 to 2 week period)?

Did you try reverting the sshd library?

On our side, we tried to reproduce that problem but we were not able to, so we will proceed will the 2.9 upgrade and see if it happens in production.

Hugo

[Hugo Arès]

We are now using 2.9 in production and we have this issue :(

I investigated and found out that, as Shawn suspected, the stuck thread is waiting for space but the client is disconnected. I tried to reproduce the problem by disconnecting the client when the server is waiting for space but the server handled the disconnection and stopped to wait for space.

Any idea how reproduce/fix that problem?

Hugo

[Saša Živkov]

On Fri, Aug 15, 2014 at 5:24 PM, Hugo Arès <hugo...@ericsson.com> wrote:

Hi Saša,

We are planning to deploy 2.9 in production soon but we want to avoid restarting the server so I added an ssh command that re-size the pool of ssh-stream-workers as a temporary solution if we get the same problem. This will allow us to allocate more worker threads to compensate for the ones that are stuck.

How many thread do you have for ssh-stream-workers (I actually want to know how many threads get stuck over a 1 to 2 week period)?

We have 10 SSH-Stream-Worker threads and, in average, have to restart Gerrit once a week because they all get stuck.

 

Did you try reverting the sshd library?

No

[Saša Živkov]

On Fri, Sep 5, 2014 at 2:51 PM, Hugo Arès <hugo...@ericsson.com> wrote:

We are now using 2.9 in production and we have this issue :(

I investigated and found out that, as Shawn suspected, the stuck thread is waiting for space but the client is disconnected. I tried to reproduce the problem by disconnecting the client when the server is waiting for space but the server handled the disconnection and stopped to wait for space.

How did you observe that? Was there any stack trace in the error_log caused by the disconnect?

[Hugo Arès]

I attached to the production instance, pause the waiting thread, inspected the variables of the channel to find out the ssh sessionId and then search the ssh_log for that sessionId.
I saw in the ssh_log that this session was terminated.

[David Ostrovsky]

Am Freitag, 5. September 2014 14:51:12 UTC+2 schrieb Hugo Arès:

We are now using 2.9 in production and we have this issue :(

I investigated and found out that, as Shawn suspected, the stuck thread is waiting for space but the client is disconnected. I tried to reproduce the problem by disconnecting the client when the server is waiting for space but the server handled the disconnection and stopped to wait for space.

Any idea how reproduce/fix that problem?

See Guillaume's suggestions in [1].

[1]  https://issues.apache.org/jira/browse/SSHD-348

[Khai Do]

I was wondering if this issue has been fixed?  if so what was the change to fix it? Thanks.

[David Ostrovsky]

Am Samstag, 15. November 2014 16:48:06 UTC+1 schrieb Khai Do:

I was wondering if this issue has been fixed?  if so what was the change to fix it? Thanks.

These changes are needed to upgrade SSHD to version 0.13.

We havn't tried to back port them to 2.8, though. Also note, that

nobody has confirmed yet, that the problem was actually fixed.

https://gerrit-review.googlesource.com/61350

https://gerrit-review.googlesource.com/61351

https://gerrit-review.googlesource.com/61352

https://gerrit-review.googlesource.com/61353

[Khai Do]

We are on 2.8.4 and we use stream events extensively so I can confirm that this isn't a problem in 2.8.  We are thinking of upgrading so I wanted to make sure that it's fixed before we attempt an upgrade.  Thanks for the info David.  

[Vlad Canţîru]

Yes, this issue was solved.

[Hugo Arès]

Vlad (evlacan) said it was solved but actually, we reverted the sshd library in 2.9, which solved our problem and did not upgraded to include sshd newer version yet.

So, like David said, nobody confirmed that the problem is fixed. Somebody reported that issue in the tracker[1], another possible user that could confirm if it is fixed.

[1]https://code.google.com/p/gerrit/issues/detail?id=3013

On Saturday, November 15, 2014 12:45:22 PM UTC-5, evlacan wrote:

Yes, this issue was solved.

On Saturday, November 15, 2014, Khai Do <zaro...@gmail.com> wrote:

We are on 2.8.4 and we use stream events extensively so I can confirm that this isn't a problem in 2.8.  We are thinking of upgrading so I wanted to make sure that it's fixed before we attempt an upgrade.  Thanks for the info David.  

On Saturday, November 15, 2014 8:24:24 AM UTC-8, David Ostrovsky wrote:

Am Samstag, 15. November 2014 16:48:06 UTC+1 schrieb Khai Do:

I was wondering if this issue has been fixed?  if so what was the change to fix it? Thanks.

These changes are needed to upgrade SSHD to version 0.13.

We havn't tried to back port them to 2.8, though. Also note, that

nobody has confirmed yet, that the problem was actually fixed.

https://gerrit-review.googlesource.com/61350

https://gerrit-review.googlesource.com/61351

https://gerrit-review.googlesource.com/61352

https://gerrit-review.googlesource.com/61353

--
--

To unsubscribe, email repo-discuss+unsubscribe@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+unsubscribe@googlegroups.com.

[David Ostrovsky]

Am Montag, 17. November 2014 15:27:23 UTC+1 schrieb Hugo Arès:

Vlad (evlacan) said it was solved but actually, we reverted the sshd library in 2.9, which solved our problem and did not upgraded to include sshd newer version yet.

So, like David said, nobody confirmed that the problem is fixed. Somebody reported that issue in the tracker[1], another possible user that could confirm if it is fixed.

[1]https://code.google.com/p/gerrit/issues/detail?id=3013

Downgrade to 0.9 path is a bit complicated, because of number of regressions in SSHD.

Have you used the instructions from [1], or do you have a better downgrade path, with

all-in-one-patch?

[1] https://gerrit-review.googlesource.com/60161

[Hugo Arès]

I did that before you contributed the downgrade so I simply reverted the 4 commits that were done after 2.8.4 regarding sshd. I wanted to go back to exactly what we had in 2.8.4, it was a known stable state for us (we were not experiencing any issues that were fixed in later version of sshd).

[David Ostrovsky]

Am Montag, 17. November 2014 18:59:45 UTC+1 schrieb Hugo Arès:

I did that before you contributed the downgrade so I simply reverted the 4 commits that were done after 2.8.4 regarding sshd. I wanted to go back to exactly what we had in 2.8.4, it was a known stable state for us (we were not experiencing any issues that were fixed in later version of sshd).

Thanks. I would suggest not to wait for confirmation (looks like only you, Gustaf or Saša can confirm that it works)

and release 2.9.2 ASAP with upgraded SSHD to 0.13. We know that the downgrade path works.

[Hugo Arès]

I agree, we should proceed with 2.9.2. There are 6 changes[1] on stable-2.9, maybe we could  try to get those in before releasing?

[1]https://gerrit-review.googlesource.com/#/q/status:open+project:gerrit+branch:stable-2.9

[Saša Živkov]

On Mon, Nov 24, 2014 at 11:49 AM, David Ostrovsky <david.o...@gmail.com> wrote:

Am Montag, 17. November 2014 18:59:45 UTC+1 schrieb Hugo Arès:

I did that before you contributed the downgrade so I simply reverted the 4 commits that were done after 2.8.4 regarding sshd. I wanted to go back to exactly what we had in 2.8.4, it was a known stable state for us (we were not experiencing any issues that were fixed in later version of sshd).

Thanks. I would suggest not to wait for confirmation (looks like only you, Gustaf or Saša can confirm that it works)

 

The only thing I can definitely confirm is that SSHD 0.9.0 + "SSH handshake fix" +  "Authentication with partial success fix"

works.

Unfortunately, I couldn't test the SSHD 0.13 yet.

and release 2.9.2 ASAP with upgraded SSHD to 0.13. We know that the downgrade path works.

--
--
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.