6

By analyzing a problem I'm trying to understand this strange stack trace:

Thread 3049: (state = BLOCKED)
- java.lang.Object.wait(long) @bci=0 (Compiled frame; information may be imprecise)
- java.io.PipedInputStream.read() @bci=142, line=326 (Compiled frame)
- java.io.PipedInputStream.read(byte[], int, int) @bci=43, line=377 (Compiled frame)
- org.apache.http.entity.InputStreamEntity.writeTo(java.io.OutputStream) @bci=75, line=140 (Compiled frame)
- org.apache.http.impl.execchain.RequestEntityProxy.writeTo(java.io.OutputStream) @bci=10, line=123 (Compiled frame)
- org.apache.http.impl.DefaultBHttpClientConnection.sendRequestEntity(org.apache.http.HttpEntityEnclosingRequest) @bci=31, line=156 (Compiled frame)
- org.apache.http.impl.conn.CPoolProxy.sendRequestEntity(org.apache.http.HttpEntityEnclosingRequest) @bci=5, line=162 (Compiled frame)
- org.apache.http.protocol.HttpRequestExecutor.doSendRequest(org.apache.http.HttpRequest, org.apache.http.HttpClientConnection, org.apache.http.protocol.HttpContext) @bci=223, line=238 (Compiled frame)
- org.apache.http.protocol.HttpRequestExecutor.execute(org.apache.http.HttpRequest, org.apache.http.HttpClientConnection, org.apache.http.protocol.HttpContext) @bci=25, line=123 (Compiled frame)
- org.apache.http.impl.execchain.MainClientExec.execute(org.apache.http.conn.routing.HttpRoute, org.apache.http.client.methods.HttpRequestWrapper, org.apache.http.client.protocol.HttpClientContext, org.apache.http.client.methods.HttpExecutionAware) @bci=714, line=271 (Compiled frame)
- org.apache.http.impl.execchain.ProtocolExec.execute(org.apache.http.conn.routing.HttpRoute, org.apache.http.client.methods.HttpRequestWrapper, org.apache.http.client.protocol.HttpClientContext, org.apache.http.client.methods.HttpExecutionAware) @bci=447, line=184 (Compiled frame)
- org.apache.http.impl.execchain.RetryExec.execute(org.apache.http.conn.routing.HttpRoute, org.apache.http.client.methods.HttpRequestWrapper, org.apache.http.client.protocol.HttpClientContext, org.apache.http.client.methods.HttpExecutionAware) @bci=39, line=88 (Compiled frame)
- org.apache.http.impl.client.InternalHttpClient.doExecute(org.apache.http.HttpHost, org.apache.http.HttpRequest, org.apache.http.protocol.HttpContext) @bci=168, line=184 (Compiled frame)
- java.util.concurrent.locks.AbstractQueuedSynchronizer.doReleaseShared() @bci=69, line=695 (Compiled frame)
- java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(int) @bci=9, line=1342 (Compiled frame)
- java.util.concurrent.CountDownLatch.countDown() @bci=5, line=291 (Compiled frame)
- com.mycompany.browse.concurrent.stream.CustomPipedInputStream.close() @bci=8, line=43 (Compiled frame)
- com.mycompany.browse.mina.handler.BrowseHttpMessageProcessor$1.run() @bci=57, line=200 (Compiled frame)
- java.util.concurrent.Executors$RunnableAdapter.call() @bci=4, line=511 (Compiled frame)
- java.util.concurrent.FutureTask.run() @bci=42, line=266 (Compiled frame)
- java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=95, line=1142 (Compiled frame)
- java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5, line=617 (Compiled frame)
- java.lang.Thread.run() @bci=11, line=745 (Compiled frame)

Based on the stack trace, AbstractQueuedSynchronizer calls Apache HTTP client. How could this happen? We are running Oracle Java 1.8 on Amazon Linux

And I have a lot of threads with exactly the same stacktrace. Anytime.

Later Edit: renamed from impossible to Inconceivable as suggested

ZsJoska
  • 187
  • 1
  • 6
  • 1
    What's impossible about it? – user207421 Feb 26 '18 at 09:55
  • 2
    @EJB I would wonder how `java.util.concurrent.locks.AbstractQueuedSynchronizer.doReleaseShared()` would call `org.apache.http.impl.client.InternalHttpClient.doExecute(...)`. From the source code of `AbstractQueuedSynchronizer` I can't see how this could happen. – lexicore Feb 26 '18 at 09:59
  • That's not the same as it being impossible. – user207421 Feb 26 '18 at 10:19
  • 2
    That stacktrace doesn't indicate that `InternalHttpClient` is used in the source of `AbstractQueuedSynchronizer`. But it does look like the problem is with using a custom `PipedStream` with a flawed close operation. – Kayaman Feb 26 '18 at 10:27
  • Well right, it is not impossible because I have it :) But how could happen? Clearly AbstractQueuedSynchronizer doesn't know about Apache Http client, neither does some abstract task/runnable call. And yes, I try to figure it out how could we end in reading from the stream during our close code. This is causing lock on the thread. – ZsJoska Feb 26 '18 at 10:37
  • 2
    Can you give us the exact JVM version? Do you think that there is anything in `com.mycompany.browse.concurrent.stream.CustomPipedInputStream` worth sharing? – Mick Mnemonic Feb 26 '18 at 10:53
  • The exact java version is java version "1.8.0_101" Java(TM) SE Runtime Environment (build 1.8.0_101-b13) Java HotSpot(TM) 64-Bit Server VM (build 25.101-b13, mixed mode) We retrieve the stacktrace with jstack command. Analyzing, well just statically looking at the stack trace because I am unable to reproduce locally. – ZsJoska Feb 26 '18 at 11:08
  • 2
    My money's on `com.mycompany.browse.concurrent.stream.CustomPipedInputStream` being broken. – Andrew Henle Feb 26 '18 at 11:26
  • 1
    @Kayaman What puzzles me is how it could appear that `AbstractQueuedSynchronizer.doReleaseShared()` is calling `InternalHttpClient.doExecute(...)`. In the source code of `AbstractQueuedSynchronizer` I don't see where `doReleaseShared` would call anything external. – lexicore Feb 26 '18 at 11:28
  • @AndrewHenle This is very probable, but still how would it result in the "impossible" stacktrace? – lexicore Feb 26 '18 at 11:29
  • These are _compiled_ frames, so due to JIT inlining etc. they may contain code from more than one method and the original source code isn't that useful for debugging, right? – Mick Mnemonic Feb 26 '18 at 11:41
  • 1
    @MickMnemonic exactly my thought (I accidentally deleted the comments in this post :| ), initially I thought about `JFR` and it's async way of getting the stack traces, but since the OP said `jstack` I wanted to say the same thing, I just wonder if it is right though and some "neighbor" stacks are taken too... – Eugene Feb 26 '18 at 11:52
  • @lexicore *how would it result in the "impossible" stacktrace?* We might find out if the questioner posts the code in for the class. And why is this stack trace being called "impossible"? "Inconceivable" seems more appropriate... – Andrew Henle Feb 26 '18 at 11:52
  • @AndrewHenle I don't think the usage of the word "impossible" is important. – lexicore Feb 26 '18 at 13:12
  • 1
    @AndrewHenle What I'm puzzled about is how can `InternalHttpClient.doExecute` seemingly be called from `AbstractQueuedSynchronizer.doReleaseShared`, it just does not follow from the source code of `AbstractQueuedSynchronizer.doReleaseShared`. – lexicore Feb 26 '18 at 13:15
  • @lexicore but the source code is irrelevant. You can stare at `AbstractQueuedSynchronizer` all you want, without it making sense. You first see that `customPipedInputStream.close()` is called, which counts down a `Latch` (which goes to internals), then you have stack frames that don't follow linearly anymore. Then you have blocking at `PipedInputStream.read()` which gave the suggestion that their custom stream class is borked. – Kayaman Feb 26 '18 at 13:15
  • @Kayaman I'd be grateful for an explanation, why. – lexicore Feb 26 '18 at 13:16
  • 2
    You've got this stack trace in forced mode: `jstack -F`. There is a [big difference](https://stackoverflow.com/a/35963059/3448419) between `jstack` and `jstack -F`: the forced mode works out-of-process, asynchronously and without the cooperation from JVM. It is less reliable than regular `jstack`, because JVM is not at safepoint and its state may be inconsistent. For example, it can be in the middle of garbage collection. The second reason is that stack dump is reconstructed by the external tool (Serviceability Agent) which is known to have issues. – apangin Feb 27 '18 at 01:34
  • So, why do you use forced mode (`-F`)? I'd recommend to use regular `jstack` if you want reliable stack traces. – apangin Feb 27 '18 at 01:37
  • It certainly doesn't look like a stack trace that the standard stack trace output generates. – the8472 Feb 27 '18 at 20:16
  • @apangin, you have right, your comment would be the accepted answer – ZsJoska Feb 28 '18 at 14:54

1 Answers1

3

As far as I see, you've got this stack trace in forced mode: jstack -F. There is a big difference between jstack and jstack -F described here.

The forced mode works out-of-process, asynchronously and without the cooperation from JVM. It is less reliable than regular jstack, because JVM is not at safepoint and its state may be inconsistent. For example, it can be in the middle of garbage collection.

The second reason is that stack dump is reconstructed by the external tool (Serviceability Agent) which is not quite perfect. So, in order to get reliable stack traces, I suggest to use jstack in normal mode when possible.

apangin
  • 92,924
  • 10
  • 193
  • 247