search

pgjdbc / r2dbc-postgresql

Postgresql R2DBC Driver
https://r2dbc.io
Apache License 2.0
1.01k stars 177 forks source link

High CPU usage when cancelled query #242

Closed steven-sheehy closed 4 years ago

steven-sheehy commented 4 years ago

Bug Report

Using 0.8.1 in our project and running into an issue where we see very high CPU utilization after performing a simple select on a table. The below jstack output shows some sort of infinite loop in io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.drainLoop(ReactorNettyClient.java:828).

Also, after the query is completed and returned the appropriate results, pg_stat_activity still shows that query as active even though it should've been completed and returned to the pool. I've confirmed with logs for doOnCancel and doOnComplete that this flux is actually complete. Eventually all connections in the thread pool show as active and the thread pool is exhausted. It's not clear if these are related or two separate issues.

Versions

Current Behavior

Application logs

jstack output ``` 2020-02-03 22:11:34 Full thread dump OpenJDK 64-Bit Server VM (11.0.6+10-post-Ubuntu-1ubuntu118.04.1 mixed mode, sharing): Threads class SMR info: _java_thread_list=0x00007fd974001880, length=20, elements={ 0x00007fd9a0165000, 0x00007fd9a0167000, 0x00007fd9a016f000, 0x00007fd9a0171800, 0x00007fd9a0173800, 0x00007fd9a0175800, 0x00007fd9a01ac800, 0x00007fd9a01b1800, 0x00007fd9a0bb1800, 0x00007fd9a046a000, 0x00007fd9a0997000, 0x00007fd9a0997800, 0x00007fd9a0c36000, 0x00007fd9a15d9800, 0x00007fd9a15f0000, 0x00007fd9a1872800, 0x00007fd9a187d800, 0x00007fd9a0015000, 0x00007fd9640a5000, 0x00007fd95400b800 } "Reference Handler" #2 daemon prio=10 os_prio=0 cpu=5.61ms elapsed=198.14s tid=0x00007fd9a0165000 nid=0x4562 waiting on condition [0x00007fd9842d3000] java.lang.Thread.State: RUNNABLE at java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.6/Native Method) at java.lang.ref.Reference.processPendingReferences(java.base@11.0.6/Reference.java:241) at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.6/Reference.java:213) Locked ownable synchronizers: - None "Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.54ms elapsed=198.14s tid=0x00007fd9a0167000 nid=0x4563 in Object.wait() [0x00007fd9841d2000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(java.base@11.0.6/Native Method) - waiting on <0x000000008b2caba8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@11.0.6/ReferenceQueue.java:155) - waiting to re-lock in wait() <0x000000008b2caba8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@11.0.6/ReferenceQueue.java:176) at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.6/Finalizer.java:170) Locked ownable synchronizers: - None "Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.41ms elapsed=198.14s tid=0x00007fd9a016f000 nid=0x4564 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=11534.97ms elapsed=198.14s tid=0x00007fd9a0171800 nid=0x4565 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE No compile task Locked ownable synchronizers: - None "C1 CompilerThread0" #6 daemon prio=9 os_prio=0 cpu=3708.57ms elapsed=198.14s tid=0x00007fd9a0173800 nid=0x4566 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE No compile task Locked ownable synchronizers: - None "Sweeper thread" #7 daemon prio=9 os_prio=0 cpu=63.44ms elapsed=198.14s tid=0x00007fd9a0175800 nid=0x4567 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "Service Thread" #8 daemon prio=9 os_prio=0 cpu=27.01ms elapsed=198.11s tid=0x00007fd9a01ac800 nid=0x4568 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "Common-Cleaner" #9 daemon prio=8 os_prio=0 cpu=12.86ms elapsed=198.10s tid=0x00007fd9a01b1800 nid=0x456a in Object.wait() [0x00007fd96f2f8000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(java.base@11.0.6/Native Method) - waiting on <0x000000008b239728> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@11.0.6/ReferenceQueue.java:155) - waiting to re-lock in wait() <0x000000008b239728> (a java.lang.ref.ReferenceQueue$Lock) at jdk.internal.ref.CleanerImpl.run(java.base@11.0.6/CleanerImpl.java:148) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) at jdk.internal.misc.InnocuousThread.run(java.base@11.0.6/InnocuousThread.java:134) Locked ownable synchronizers: - None "reactor-tcp-epoll-1" #14 daemon prio=5 os_prio=0 cpu=177360.54ms elapsed=190.39s tid=0x00007fd9a0bb1800 nid=0x4602 runnable [0x00007fd96e09e000] java.lang.Thread.State: RUNNABLE at io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.drainLoop(ReactorNettyClient.java:828) at io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.onNext(ReactorNettyClient.java:795) at io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.onNext(ReactorNettyClient.java:713) at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:112) at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:845) at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:213) at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:213) at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:218) at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:351) at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:348) at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:90) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:321) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:308) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:422) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355) at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:227) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:792) at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:475) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) Locked ownable synchronizers: - None "reactor-tcp-epoll-2" #15 daemon prio=5 os_prio=0 cpu=136.70ms elapsed=190.39s tid=0x00007fd9a046a000 nid=0x4603 runnable [0x00007fd96cf9f000] java.lang.Thread.State: RUNNABLE at io.netty.channel.epoll.Native.epollWait(Native Method) at io.netty.channel.epoll.Native.epollWait(Native.java:129) at io.netty.channel.epoll.Native.epollWait(Native.java:122) at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:290) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:347) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) Locked ownable synchronizers: - None "reactor-tcp-epoll-3" #16 daemon prio=5 os_prio=0 cpu=114.51ms elapsed=190.39s tid=0x00007fd9a0997000 nid=0x4604 runnable [0x00007fd96ca2b000] java.lang.Thread.State: RUNNABLE at io.netty.channel.epoll.Native.epollWait(Native Method) at io.netty.channel.epoll.Native.epollWait(Native.java:129) at io.netty.channel.epoll.Native.epollWait(Native.java:122) at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:290) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:347) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) Locked ownable synchronizers: - None "reactor-tcp-epoll-4" #17 daemon prio=5 os_prio=0 cpu=119.56ms elapsed=190.39s tid=0x00007fd9a0997800 nid=0x4605 runnable [0x00007fd96c92a000] java.lang.Thread.State: RUNNABLE at io.netty.channel.epoll.Native.epollWait(Native Method) at io.netty.channel.epoll.Native.epollWait(Native.java:129) at io.netty.channel.epoll.Native.epollWait(Native.java:122) at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:290) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:347) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) Locked ownable synchronizers: - None "elastic-metrics-publisher" #18 daemon prio=5 os_prio=0 cpu=680.37ms elapsed=189.26s tid=0x00007fd9a0c36000 nid=0x4619 waiting on condition [0x00007fd96c429000] java.lang.Thread.State: TIMED_WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@11.0.6/Native Method) - parking to wait for <0x00000000971c9490> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.6/LockSupport.java:234) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.6/AbstractQueuedSynchronizer.java:2123) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.6/ScheduledThreadPoolExecutor.java:1182) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.6/ScheduledThreadPoolExecutor.java:899) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.6/ThreadPoolExecutor.java:1054) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.6/ThreadPoolExecutor.java:1114) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.6/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) Locked ownable synchronizers: - None "grpc-default-boss-ELG-1-1" #19 daemon prio=5 os_prio=0 cpu=38.55ms elapsed=187.12s tid=0x00007fd9a15d9800 nid=0x4640 runnable [0x00007fd96c128000] java.lang.Thread.State: RUNNABLE at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait0(Native Method) at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait(Native.java:101) at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:304) at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:355) at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044) at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) Locked ownable synchronizers: - None "container-0" #20 prio=5 os_prio=0 cpu=0.28ms elapsed=187.10s tid=0x00007fd9a15f0000 nid=0x4641 in Object.wait() [0x00007fd9437ee000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(java.base@11.0.6/Native Method) - waiting on <0x0000000097015cc8> (a java.lang.Object) at java.lang.Object.wait(java.base@11.0.6/Object.java:328) at io.grpc.internal.ServerImpl.awaitTermination(ServerImpl.java:330) - waiting to re-lock in wait() <0x0000000097015cc8> (a java.lang.Object) at net.devh.boot.grpc.server.serverfactory.GrpcServerLifecycle$1.run(GrpcServerLifecycle.java:99) Locked ownable synchronizers: - None "reactor-http-epoll-1" #21 daemon prio=5 os_prio=0 cpu=7.50ms elapsed=186.91s tid=0x00007fd9a1872800 nid=0x4644 runnable [0x00007fd9436ed000] java.lang.Thread.State: RUNNABLE at io.netty.channel.epoll.Native.epollWait(Native Method) at io.netty.channel.epoll.Native.epollWait(Native.java:129) at io.netty.channel.epoll.Native.epollWait(Native.java:122) at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:290) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:347) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) Locked ownable synchronizers: - None "server" #22 prio=5 os_prio=0 cpu=2.44ms elapsed=186.90s tid=0x00007fd9a187d800 nid=0x4645 waiting on condition [0x00007fd9435ec000] java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@11.0.6/Native Method) 2020-02-03 22:11:38 Full thread dump OpenJDK 64-Bit Server VM (11.0.6+10-post-Ubuntu-1ubuntu118.04.1 mixed mode, sharing): Threads class SMR info: _java_thread_list=0x00007fd974001880, length=20, elements={ 0x00007fd9a0165000, 0x00007fd9a0167000, 0x00007fd9a016f000, 0x00007fd9a0171800, 0x00007fd9a0173800, 0x00007fd9a0175800, 0x00007fd9a01ac800, 0x00007fd9a01b1800, 0x00007fd9a0bb1800, 0x00007fd9a046a000, 0x00007fd9a0997000, 0x00007fd9a0997800, 0x00007fd9a0c36000, 0x00007fd9a15d9800, 0x00007fd9a15f0000, 0x00007fd9a1872800, 0x00007fd9a187d800, 0x00007fd9a0015000, 0x00007fd9640a5000, 0x00007fd95400b800 } "Reference Handler" #2 daemon prio=10 os_prio=0 cpu=5.61ms elapsed=202.27s tid=0x00007fd9a0165000 nid=0x4562 waiting on condition [0x00007fd9842d3000] java.lang.Thread.State: RUNNABLE at java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.6/Native Method) at java.lang.ref.Reference.processPendingReferences(java.base@11.0.6/Reference.java:241) at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.6/Reference.java:213) Locked ownable synchronizers: - None "Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.54ms elapsed=202.27s tid=0x00007fd9a0167000 nid=0x4563 in Object.wait() [0x00007fd9841d2000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(java.base@11.0.6/Native Method) - waiting on <0x000000008b2caba8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@11.0.6/ReferenceQueue.java:155) - waiting to re-lock in wait() <0x000000008b2caba8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@11.0.6/ReferenceQueue.java:176) at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.6/Finalizer.java:170) Locked ownable synchronizers: - None "Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.41ms elapsed=202.26s tid=0x00007fd9a016f000 nid=0x4564 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=11535.00ms elapsed=202.26s tid=0x00007fd9a0171800 nid=0x4565 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE No compile task Locked ownable synchronizers: - None "C1 CompilerThread0" #6 daemon prio=9 os_prio=0 cpu=3708.59ms elapsed=202.26s tid=0x00007fd9a0173800 nid=0x4566 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE No compile task Locked ownable synchronizers: - None "Sweeper thread" #7 daemon prio=9 os_prio=0 cpu=63.44ms elapsed=202.26s tid=0x00007fd9a0175800 nid=0x4567 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: "Sweeper thread" #7 daemon prio=9 os_prio=0 cpu=63.44ms elapsed=202.26s tid=0x00007fd9a0175800 nid=0x4567 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "Service Thread" #8 daemon prio=9 os_prio=0 cpu=27.01ms elapsed=202.23s tid=0x00007fd9a01ac800 nid=0x4568 runnable [0x0000000000000000] - parking to wait for <0x0000000096f2e270> (a java.util.concurrent.CountDownLatch$Sync) at java.util.concurrent.locks.LockSupport.park(java.base@11.0.6/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.6/AbstractQueuedSynchronizer.java:885) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(java.base@11.0.6/AbstractQueuedSynchronizer.java:1039) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@11.0.6/AbstractQueuedSynchronizer.java:1345) at java.util.concurrent.CountDownLatch.await(java.base@11.0.6/CountDownLatch.java:232) at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:87) at reactor.core.publisher.Mono.block(Mono.java:1663) at org.springframework.boot.web.embedded.netty.NettyWebServer$1.run(NettyWebServer.java:131) Locked ownable synchronizers: - None "DestroyJavaVM" #24 prio=5 os_prio=0 cpu=8443.05ms elapsed=186.89s tid=0x00007fd9a0015000 nid=0x455b waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "grpc-default-worker-ELG-3-1" #25 daemon prio=5 os_prio=0 cpu=369.48ms elapsed=181.79s tid=0x00007fd9640a5000 nid=0x46b5 runnable [0x00007fd9434eb000] java.lang.Thread.State: RUNNABLE at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait0(Native Method) at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait(Native.java:101) at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:304) at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:355) at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044) at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(java.base@11.0.6/Thread.java:834) Locked ownable synchronizers: - None "Attach Listener" #37 daemon prio=9 os_prio=0 cpu=0.46ms elapsed=21.04s tid=0x00007fd95400b800 nid=0x541c waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "VM Thread" os_prio=0 cpu=191.38ms elapsed=198.14s tid=0x00007fd9a0162000 nid=0x4561 runnable "GC Thread#0" os_prio=0 cpu=326.77ms elapsed=198.16s tid=0x00007fd9a002d000 nid=0x455c runnable "GC Thread#1" os_prio=0 cpu=299.57ms elapsed=197.92s tid=0x00007fd964001000 nid=0x456b runnable "G1 Main Marker" os_prio=0 cpu=1.82ms elapsed=198.15s tid=0x00007fd9a005c000 nid=0x455d runnable "G1 Conc#0" os_prio=0 cpu=114.67ms elapsed=198.15s tid=0x00007fd9a005e000 nid=0x455e runnable "G1 Refine#0" os_prio=0 cpu=6.82ms elapsed=198.15s tid=0x00007fd9a00c8800 nid=0x455f runnable "G1 Young RemSet Sampling" os_prio=0 cpu=55.07ms elapsed=198.15s tid=0x00007fd9a00ca800 nid=0x4560 runnable "VM Periodic Task Thread" os_prio=0 cpu=156.21ms elapsed=198.11s tid=0x00007fd9a01af000 nid=0x4569 waiting on condition JNI global refs: 35, weak refs: 0 ```

Table schema

Steps to reproduce

Expected behavior/code

Possible Solution

Additional context

mp911de commented 4 years ago

Caused by #231.

steven-sheehy commented 4 years ago

I've made a reproducer project at https://github.com/steven-sheehy/r2dbc-highcpu

Please checkout and debug R2DbcExampleApplicationTests. If you run jstack or put a break point in ReactorNettyClient$BackendMessageSubscriber.drainLoop() after it runs for ahwile you can see that it is an infinite busy loop.

mp911de commented 4 years ago

Thanks a lot. The issue is that we react to whether the buffer has buffered protocol frames but not whether the conversation has demand. The drain loop keeps looping forever. It actually should exit if the conversation has no demand.

mp911de commented 4 years ago

I just pushed a fix for this one. The test case runs after upgrading to 0.8.2.BUILD-SNAPSHOT.

steven-sheehy commented 4 years ago

Thanks, I can confirm it addresses the high CPU