poutsma/web-function-sample

Every other request gets stuck in ReactorServer

PeterPerhac opened this issue · 3 comments

While everything works fine when starting the Driver with startTomcatServer(), startReactorServer() is funny in that only odd requests work. Every other request is stuck forever.

Thread dump when stuck:

/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/bin/java -Didea.launcher.port=7537 "-Didea.launcher.bin.path=/Applications/IntelliJ IDEA CE.app/Contents/bin" -Dfile.encoding=UTF-8 -classpath "/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/charsets.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/deploy.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/cldrdata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/dnsns.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/jaccess.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/jfxrt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/localedata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/nashorn.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/sunec.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/ext/zipfs.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/javaws.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/jce.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/jfr.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/jfxswt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/jsse.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/management-agent.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/plugin.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/resources.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/lib/rt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/lib/ant-javafx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/lib/dt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/lib/javafx-mx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/lib/jconsole.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/lib/packager.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/lib/sa-jdi.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/lib/tools.jar:/Users/peterperhac/personal/reactive-tinkering/web-function-sample/target/classes:/Users/peterperhac/.m2/repository/org/reactivestreams/reactive-streams/1.0.0/reactive-streams-1.0.0.jar:/Users/peterperhac/.m2/repository/io/projectreactor/reactor-core/3.0.2.RELEASE/reactor-core-3.0.2.RELEASE.jar:/Users/peterperhac/.m2/repository/io/projectreactor/ipc/reactor-netty/0.5.1.RELEASE/reactor-netty-0.5.1.RELEASE.jar:/Users/peterperhac/.m2/repository/io/netty/netty-all/4.1.3.Final/netty-all-4.1.3.Final.jar:/Users/peterperhac/.m2/repository/io/projectreactor/ipc/reactor-ipc/0.5.1.RELEASE/reactor-ipc-0.5.1.RELEASE.jar:/Users/peterperhac/.m2/repository/org/apache/tomcat/embed/tomcat-embed-core/8.5.4/tomcat-embed-core-8.5.4.jar:/Users/peterperhac/.m2/repository/org/springframework/spring-web-reactive/5.0.0.M2/spring-web-reactive-5.0.0.M2.jar:/Users/peterperhac/.m2/repository/org/springframework/spring-core/5.0.0.M2/spring-core-5.0.0.M2.jar:/Users/peterperhac/.m2/repository/commons-logging/commons-logging/1.2/commons-logging-1.2.jar:/Users/peterperhac/.m2/repository/org/springframework/spring-web/5.0.0.M2/spring-web-5.0.0.M2.jar:/Users/peterperhac/.m2/repository/org/springframework/spring-aop/5.0.0.M2/spring-aop-5.0.0.M2.jar:/Users/peterperhac/.m2/repository/org/springframework/spring-beans/5.0.0.M2/spring-beans-5.0.0.M2.jar:/Users/peterperhac/.m2/repository/org/springframework/spring-context/5.0.0.M2/spring-context-5.0.0.M2.jar:/Users/peterperhac/.m2/repository/org/springframework/spring-expression/5.0.0.M2/spring-expression-5.0.0.M2.jar:/Users/peterperhac/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.8.2/jackson-databind-2.8.2.jar:/Users/peterperhac/.m2/repository/com/fasterxml/jackson/core/jackson-annotations/2.8.0/jackson-annotations-2.8.0.jar:/Users/peterperhac/.m2/repository/com/fasterxml/jackson/core/jackson-core/2.8.2/jackson-core-2.8.2.jar:/Applications/IntelliJ IDEA CE.app/Contents/lib/idea_rt.jar" com.intellij.rt.execution.application.AppMain org.springframework.samples.web.reactive.function.Driver
Press ENTER to exit.
Sep 23, 2016 11:02:52 PM reactor.util.Loggers$JdkLogger info
INFO: BIND OK /127.0.0.1:8080
2016-09-23 23:03:07
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.102-b14 mixed mode):

"threadDeathWatcher-2-1" #14 daemon prio=1 os_prio=31 tid=0x00007fcdad819800 nid=0x1407 waiting on condition [0x00007000018de000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at io.netty.util.ThreadDeathWatcher$Watcher.run(ThreadDeathWatcher.java:150)
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
at java.lang.Thread.run(Thread.java:745)

"reactor-tcp-server-io-2" #13 prio=5 os_prio=31 tid=0x00007fcdad813000 nid=0x3d07 runnable [0x00007000017db000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x000000076ca3bb40> (a io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x000000076ca3ba78> (a java.util.Collections$UnmodifiableSet)
- locked <0x000000076ca3b958> (a sun.nio.ch.KQueueSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:692)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:352)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:877)
at java.lang.Thread.run(Thread.java:745)

"reactor-tcp-server-select-1" #12 prio=5 os_prio=31 tid=0x00007fcdad988000 nid=0x5c0f runnable [0x00007000016d8000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x000000076ca17940> (a io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x000000076ca10f28> (a java.util.Collections$UnmodifiableSet)
- locked <0x000000076ca0f510> (a sun.nio.ch.KQueueSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:692)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:352)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:877)
at java.lang.Thread.run(Thread.java:745)

"Monitor Ctrl-Break" #10 daemon prio=5 os_prio=31 tid=0x00007fcdad07f000 nid=0x5603 runnable [0x00007000015d5000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
- locked <0x000000076ad96b08> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:184)
at java.io.BufferedReader.fill(BufferedReader.java:161)
at java.io.BufferedReader.readLine(BufferedReader.java:324)
- locked <0x000000076ad96b08> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:389)
at com.intellij.rt.execution.application.AppMain$1.run(AppMain.java:84)
at java.lang.Thread.run(Thread.java:745)

"Service Thread" #9 daemon prio=9 os_prio=31 tid=0x00007fcdab00d800 nid=0x5203 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #8 daemon prio=9 os_prio=31 tid=0x00007fcdaa815800 nid=0x5003 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007fcdad044800 nid=0x4e03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007fcdad044000 nid=0x4c03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007fcdad029000 nid=0x4a03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fcdae004000 nid=0x3e0f waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fcdab802000 nid=0x3803 in Object.wait() [0x0000700000d3a000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000076ab08e98> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
- locked <0x000000076ab08e98> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fcdad022800 nid=0x3603 in Object.wait() [0x0000700000c37000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000076ab06b40> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x000000076ab06b40> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=31 tid=0x00007fcdae801800 nid=0x1703 runnable [0x0000700000218000]
java.lang.Thread.State: RUNNABLE
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:255)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
- locked <0x000000076ab1f9f8> (a java.io.BufferedInputStream)
at org.springframework.samples.web.reactive.function.Driver.main(Driver.java:49)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)

"VM Thread" os_prio=31 tid=0x00007fcdac802800 nid=0x3403 runnable

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fcdaa80e000 nid=0x2403 runnable

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fcdab000000 nid=0x2603 runnable

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fcdab001000 nid=0x2803 runnable

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fcdab002000 nid=0x2a03 runnable

"GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007fcdab002800 nid=0x2c03 runnable

"GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007fcdac800800 nid=0x2e03 runnable

"GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007fcdac801000 nid=0x3003 runnable

"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fcdac802000 nid=0x3203 runnable

"VM Periodic Task Thread" os_prio=31 tid=0x00007fcdac806800 nid=0x5403 waiting on condition

JNI global references: 506

Heap
PSYoungGen total 76288K, used 57729K [0x000000076ab00000, 0x0000000770000000, 0x00000007c0000000)
eden space 65536K, 88% used [0x000000076ab00000,0x000000076e3606a0,0x000000076eb00000)
from space 10752K, 0% used [0x000000076f580000,0x000000076f580000,0x0000000770000000)
to space 10752K, 0% used [0x000000076eb00000,0x000000076eb00000,0x000000076f580000)
ParOldGen total 175104K, used 0K [0x00000006c0000000, 0x00000006cab00000, 0x000000076ab00000)
object space 175104K, 0% used [0x00000006c0000000,0x00000006c0000000,0x00000006cab00000)
Metaspace used 15452K, capacity 15770K, committed 15872K, reserved 1062912K
class space used 1879K, capacity 1963K, committed 2048K, reserved 1048576K

lfo commented

Thanks for this sample, It works like a charm with the TomcatDriver.

But, I have a similar problem with the ReactorDriver.

Having this issue as well with just the Reactor server.

Hopefully #3 resolved this.