Skywalking: memory leak in Vert.x instrumentation

[pantovad]

Please answer these questions before submitting your issue.

• Why do you submit this issue?
• [ ] Question or discussion
• [x] Bug
• [ ] Requirement
• [ ] Feature or performance improvement

---

Question

• What do you want to know?

---

Bug

• Which version of SkyWalking, OS and JRE?
  Skywalking v8.1.0
  CentOS/Docker adoptopenjdk/openjdk8:alpine-slim
  JRE Openjdk 8
  Vert.x v3.7.1

• What happened?
  When enabling SkyWalking Java agent using default configuration the Vert.x framework is successfully instrumented and traced however memory leak appears causing memory exhaustion.

---

Requirement or improvement

• Please describe your requirements or improvement suggestions.
  Fix the memory leak issue.

[wu-sheng]

Could you share a demo code with memory leak?

[pantovad]

Unfortunately I can not share the code as this is a commercial application. Also difficult to provide a demo code as the application is quite complex order management system.

[wu-sheng]

What could you provide to give us some tips? OOM is not a thing easy to locate.

[pantovad]

I observed the JVM in VisualVM and I see high activity of vert.x-eventloop-thread-0 allocating ~75% memory. When skywalking agent not enabled it is on ~35%. It takes ~12h for the app to exhaust memory (heap size is 512m).

In the agent log these are the interesting logs appearing:
WARN 2020-09-14 09:37:39:972 vert.x-eventloop-thread-0 TracingContext : More than 300 spans required to create
java.lang.RuntimeException: Shadow tracing context. Thread dump

ERROR 2020-09-14 08:51:53:094 vert.x-eventloop-thread-5 InstMethodsInter : class[class io.vertx.ext.web.impl.RouteImpl] after method[handleContext] intercept failure
java.lang.NullPointerException

ERROR 2020-09-14 09:39:07:976 vert.x-eventloop-thread-5 InstMethodsInter : class[class io.vertx.ext.web.impl.RouteImpl] before method[handleContext] intercept failure
java.lang.IndexOutOfBoundsException: Index: 3, Size: 2

Also I was unable to disable Vert.x plugin activation using -Dskywalking.plugin.exclude_plugins="vertx-core-3.x".

[wu-sheng]

@BFergerson Is above log helpful? I am not sure about vertx part.

[BFergerson]

@wu-sheng, not really. I can't tell where the NPE or IOOBE is coming from without the full stack trace.

@pantovad, can you provide more of the logs? Either here or via emailing me ([email protected]).

[pantovad]

Sure here it is:

WARN 2020-09-14 09:46:59:987 vert.x-eventloop-thread-0 TracingContext : More than 300 spans required to create
java.lang.RuntimeException: Shadow tracing context. Thread dump
at org.apache.skywalking.apm.agent.core.context.TracingContext.isLimitMechanismWorking(TracingContext.java:562)
at org.apache.skywalking.apm.agent.core.context.TracingContext.createExitSpan(TracingContext.java:323)
at org.apache.skywalking.apm.agent.core.context.ContextManager.createExitSpan(ContextManager.java:119)
at org.apache.skywalking.apm.plugin.jdbc.postgresql.PreparedStatementExecuteMethodsInterceptor.beforeMethod(PreparedStatementExecuteMethodsInterceptor.java:48)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:76)
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java)
at org.postgresql.jdbc.PgPreparedStatement.executeQuery$original$8BkqTx1U(PgPreparedStatement.java:108)
at org.postgresql.jdbc.PgPreparedStatement.executeQuery$original$8BkqTx1U$accessor$7BFhzgDa(PgPreparedStatement.java)
at org.postgresql.jdbc.PgPreparedStatement$auxiliary$t3DCbAMh.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java)
at org.apache.commons.dbcp2.PoolableConnection.validate(PoolableConnection.java:287)
at org.apache.commons.dbcp2.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:630)
at org.apache.commons.dbcp2.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:648)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:472)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:349)
at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:753)
at ch.ergon.cryptobroker.common.db.ConnectionManager.getThreadConnection(ConnectionManager.java:101)
at ch.ergon.cryptobroker.common.db.ConnectionManager.withDSL(ConnectionManager.java:153)
at ch.ergon.cryptobroker.common.db.DbUtil.withDSL(DbUtil.java:50)
at ch.ergon.cryptobroker.order.dao.LiquidityDAO.getLiquidity(LiquidityDAO.java:71)
at ch.ergon.cryptobroker.order.handler.LiquidityHandler.storeLiquidity(LiquidityHandler.java:169)
at ch.ergon.cryptobroker.order.handler.LiquidityHandler.lambda$calculateLiquidityFromBalance$19(LiquidityHandler.java:239)
at io.vertx.core.Future.lambda$compose$1(Future.java:265)
at io.vertx.core.impl.SucceededFuture.setHandler(SucceededFuture.java:40)
at io.vertx.core.Future.compose(Future.java:261)
at ch.ergon.cryptobroker.order.handler.LiquidityHandler.calculateLiquidityFromBalance(LiquidityHandler.java:238)
at ch.ergon.cryptobroker.order.handler.LiquidityHandler.lambda$calculateAndStoreCcysLiquidity$14(LiquidityHandler.java:223)
at java.util.stream.ReferencePipeline$3$1.accept(Unknown Source)
at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(Unknown Source)
at java.util.stream.AbstractPipeline.copyInto(Unknown Source)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(Unknown Source)
at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
at java.util.stream.ReferencePipeline.collect(Unknown Source)
at ch.ergon.cryptobroker.order.handler.LiquidityHandler.calculateAndStoreCcysLiquidity(LiquidityHandler.java:223)
at ch.ergon.cryptobroker.order.handler.LiquidityHandler.lambda$calculateLongLivedCurrencies$4(LiquidityHandler.java:122)
at io.vertx.core.Future.lambda$compose$1(Future.java:265)
at io.vertx.core.impl.FutureImpl.tryComplete(FutureImpl.java:125)
at io.vertx.core.impl.FutureImpl.complete(FutureImpl.java:86)
at io.vertx.core.Future.lambda$map$2(Future.java:306)
at io.vertx.core.impl.FutureImpl.tryComplete(FutureImpl.java:125)
at io.vertx.core.impl.FutureImpl.complete(FutureImpl.java:86)
at io.vertx.core.Future.lambda$map$2(Future.java:306)
at io.vertx.core.impl.FutureImpl.tryComplete(FutureImpl.java:125)
at io.vertx.core.impl.FutureImpl.complete(FutureImpl.java:86)
at io.vertx.core.Future.lambda$map$2(Future.java:306)
at io.vertx.core.impl.FutureImpl.tryComplete(FutureImpl.java:125)
at io.vertx.core.impl.FutureImpl.complete(FutureImpl.java:86)
at io.vertx.core.Future.lambda$map$2(Future.java:306)
at io.vertx.core.impl.FutureImpl.tryComplete(FutureImpl.java:125)
at io.vertx.core.impl.FutureImpl.complete(FutureImpl.java:86)
at io.vertx.core.impl.FutureImpl.handle(FutureImpl.java:151)
at io.vertx.core.impl.FutureImpl.handle(FutureImpl.java:18)
at io.vertx.ext.web.client.impl.HttpContext.handleDispatchResponse$original$YOr68YPN(HttpContext.java:285)
at io.vertx.ext.web.client.impl.HttpContext.handleDispatchResponse$original$YOr68YPN$accessor$e56Me8Nd(HttpContext.java)
at io.vertx.ext.web.client.impl.HttpContext$auxiliary$RroXPNMO.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at io.vertx.ext.web.client.impl.HttpContext.handleDispatchResponse(HttpContext.java)
at io.vertx.ext.web.client.impl.HttpContext.execute(HttpContext.java:272)
at io.vertx.ext.web.client.impl.HttpContext.next(HttpContext.java:250)
at io.vertx.ext.web.client.impl.predicate.PredicateInterceptor.handle(PredicateInterceptor.java:69)
at io.vertx.ext.web.client.impl.predicate.PredicateInterceptor.handle(PredicateInterceptor.java:32)
at io.vertx.ext.web.client.impl.HttpContext.next(HttpContext.java:247)
at io.vertx.ext.web.client.impl.HttpContext.fire(HttpContext.java:257)
at io.vertx.ext.web.client.impl.HttpContext.dispatchResponse(HttpContext.java:218)
at io.vertx.ext.web.client.impl.HttpContext.lambda$null$2(HttpContext.java:341)
at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320)
at io.vertx.core.impl.EventLoopContext.lambda$executeAsync$0(EventLoopContext.java:38)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:495)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Unknown Source)

ERROR 2020-09-14 09:47:00:008 vert.x-eventloop-thread-3 InstMethodsInter : class[class io.vertx.ext.web.impl.RouteImpl] before method[handleContext] intercept failure
java.lang.IndexOutOfBoundsException: Index: 2, Size: 2
at java.util.ArrayList.rangeCheck(Unknown Source)
at java.util.ArrayList.get(Unknown Source)
at org.apache.skywalking.apm.plugin.vertx3.RouteStateInterceptor.beforeMethod(RouteStateInterceptor.java:72)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:76)
at io.vertx.ext.web.impl.RouteImpl.handleContext(RouteImpl.java)
at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:121)
at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:134)
at ch.ergon.cryptobroker.common.vertex.RequestIdHandler.handle(RequestIdHandler.java:19)
at ch.ergon.cryptobroker.common.vertex.RequestIdHandler.handle(RequestIdHandler.java:8)
at io.vertx.ext.web.impl.RouteImpl.handleContext$original$EftkEtha(RouteImpl.java:232)
at io.vertx.ext.web.impl.RouteImpl.handleContext$original$EftkEtha$accessor$H7VRrNJY(RouteImpl.java)
at io.vertx.ext.web.impl.RouteImpl$auxiliary$s3yhXMY6.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at io.vertx.ext.web.impl.RouteImpl.handleContext(RouteImpl.java)
at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:86)
at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:134)
at io.vertx.ext.web.handler.impl.AuthHandlerImpl.lambda$authorizeUser$3(AuthHandlerImpl.java:219)
at io.vertx.ext.web.handler.impl.AuthHandlerImpl.authorize(AuthHandlerImpl.java:107)
at io.vertx.ext.web.handler.impl.AuthHandlerImpl.authorizeUser(AuthHandlerImpl.java:213)
at io.vertx.ext.web.handler.impl.AuthHandlerImpl.lambda$handle$2(AuthHandlerImpl.java:145)
at ch.ergon.cryptobroker.common.vertex.jwt.CryptoJWTAuthHandler.lambda$null$1(CryptoJWTAuthHandler.java:77)
at io.vertx.ext.web.handler.impl.AuthHandlerImpl.authorize(AuthHandlerImpl.java:107)
at ch.ergon.cryptobroker.common.vertex.jwt.CryptoJWTAuthHandler.lambda$parseCredentials$2(CryptoJWTAuthHandler.java:73)
at ch.ergon.cryptobroker.common.vertex.jwt.CryptoJWTAuthProvider.authenticate_strict(CryptoJWTAuthProvider.java:87)
at ch.ergon.cryptobroker.common.vertex.jwt.CryptoJWTAuthProvider.authenticate(CryptoJWTAuthProvider.java:39)
at ch.ergon.cryptobroker.common.vertex.jwt.CryptoJWTAuthHandler.parseCredentials(CryptoJWTAuthHandler.java:63)
at io.vertx.ext.web.handler.impl.AuthHandlerImpl.handle(AuthHandlerImpl.java:129)
at io.vertx.ext.web.handler.impl.AuthHandlerImpl.handle(AuthHandlerImpl.java:39)
at io.vertx.ext.web.impl.RouteImpl.handleContext$original$EftkEtha(RouteImpl.java:232)
at io.vertx.ext.web.impl.RouteImpl.handleContext$original$EftkEtha$accessor$H7VRrNJY(RouteImpl.java)
at io.vertx.ext.web.impl.RouteImpl$auxiliary$s3yhXMY6.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at io.vertx.ext.web.impl.RouteImpl.handleContext(RouteImpl.java)
at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:121)
at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:134)
at io.vertx.ext.web.handler.impl.CookieHandlerImpl.handle(CookieHandlerImpl.java:66)
at io.vertx.ext.web.handler.impl.CookieHandlerImpl.handle(CookieHandlerImpl.java:42)
at io.vertx.ext.web.impl.RouteImpl.handleContext$original$EftkEtha(RouteImpl.java:232)
at io.vertx.ext.web.impl.RouteImpl.handleContext$original$EftkEtha$accessor$H7VRrNJY(RouteImpl.java)
at io.vertx.ext.web.impl.RouteImpl$auxiliary$s3yhXMY6.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at io.vertx.ext.web.impl.RouteImpl.handleContext(RouteImpl.java)
at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:121)
at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:134)
at io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.doEnd(BodyHandlerImpl.java:296)
at io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.end(BodyHandlerImpl.java:276)
at io.vertx.ext.web.handler.impl.BodyHandlerImpl.lambda$handle$0(BodyHandlerImpl.java:87)
at io.vertx.core.http.impl.HttpServerRequestImpl.onEnd(HttpServerRequestImpl.java:529)
at io.vertx.core.http.impl.HttpServerRequestImpl.handleEnd(HttpServerRequestImpl.java:515)
at io.vertx.core.http.impl.Http1xServerConnection.handleEnd(Http1xServerConnection.java:172)
at io.vertx.core.http.impl.Http1xServerConnection.handleMessage$original$AtuiqNMc(Http1xServerConnection.java:134)
at io.vertx.core.http.impl.Http1xServerConnection.handleMessage$original$AtuiqNMc$accessor$Kcjc0RX8(Http1xServerConnection.java)
at io.vertx.core.http.impl.Http1xServerConnection$auxiliary$78AH8QaY.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java)
at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320)
at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:43)
at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:188)
at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:173)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:102)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:297)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1408)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Unknown Source)

ERROR 2020-09-14 09:47:00:013 vert.x-eventloop-thread-1 InstMethodsInter : class[class io.vertx.ext.web.impl.RouteImpl] after method[handleContext] intercept failure
java.lang.NullPointerException
at org.apache.skywalking.apm.agent.core.context.ContextManager.stopSpan(ContextManager.java:172)
at org.apache.skywalking.apm.plugin.vertx3.RouteStateInterceptor.afterMethod(RouteStateInterceptor.java:108)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:97)
at io.vertx.ext.web.impl.RouteImpl.handleContext(RouteImpl.java)
at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:121)
at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:134)
at io.vertx.ext.web.handler.impl.CookieHandlerImpl.handle(CookieHandlerImpl.java:66)
at io.vertx.ext.web.handler.impl.CookieHandlerImpl.handle(CookieHandlerImpl.java:42)
at io.vertx.ext.web.impl.RouteImpl.handleContext$original$EftkEtha(RouteImpl.java:232)
at io.vertx.ext.web.impl.RouteImpl.handleContext$original$EftkEtha$accessor$H7VRrNJY(RouteImpl.java)
at io.vertx.ext.web.impl.RouteImpl$auxiliary$s3yhXMY6.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at io.vertx.ext.web.impl.RouteImpl.handleContext(RouteImpl.java)
at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:121)
at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:134)
at io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.doEnd(BodyHandlerImpl.java:296)
at io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.end(BodyHandlerImpl.java:276)
at io.vertx.ext.web.handler.impl.BodyHandlerImpl.lambda$handle$0(BodyHandlerImpl.java:87)
at io.vertx.core.http.impl.HttpServerRequestImpl.onEnd(HttpServerRequestImpl.java:529)
at io.vertx.core.http.impl.HttpServerRequestImpl.handleEnd(HttpServerRequestImpl.java:515)
at io.vertx.core.http.impl.Http1xServerConnection.handleEnd(Http1xServerConnection.java:172)
at io.vertx.core.http.impl.Http1xServerConnection.handleMessage$original$AtuiqNMc(Http1xServerConnection.java:134)
at io.vertx.core.http.impl.Http1xServerConnection.handleMessage$original$AtuiqNMc$accessor$Kcjc0RX8(Http1xServerConnection.java)
at io.vertx.core.http.impl.Http1xServerConnection$auxiliary$78AH8QaY.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java)
at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320)
at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:43)
at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:188)
at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:173)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:102)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)

[pantovad]

We upgraded the app to Vert.x v3.9.2 and repeated the test. The memory leak was experienced again.

[xbkaishui]

@pantovad It's better to provider a heap dump file or a simple demo to analysis this, I am interest in the issue.

[pantovad]

I can provide the heap dump generated upon OOM. Please advise where to send the download link ?

[wu-sheng]

@xbkaishui It is better you give @pantovad a private mailbox to get the link. Post here is open to everyone.

[pantovad]

Exactly what I thought, can you send me the e-mail address please ?

[xbkaishui]

Yes, please send to this, [email protected] Thanks

[xbkaishui]

Hi @pantovad @wu-sheng , I can confirm that the OOM is caused by the SkyWalking agent, please check below picture

BTW, I need some time to find the root reason. Thanks for @pantovad 's heap dump

[BFergerson]

@xbkaishui, I had a feeling it would be that class if any. Thanks for the information.

[wu-sheng]

I noticed com.hazelcast, does your app base on that framework? Rather than normal Spring boot.

[xbkaishui]

@BFergerson. I can share you the heap file if you want

[BFergerson]

@pantovad, your logs and heap dump suggests you have a lot of spans that are not being closed. When you view traces in the SkyWalking UI are you seeing any services/messages/endpoints not showing up correctly or at all?

@xbkaishui, sure. Please send to [email protected].

[pantovad]

@BFergerson we do not use Spring boot. I see services/traces/endpoints coming from this service - difficult to confirm thou if they are showing up correctly or not. Specific for this service I observed are the traces with 400+ spans ...

[xbkaishui]

@BFergerson sended by email, please check

[BFergerson]

@xbkaishui, I'm not sure how much of the internal structure of @pantovad's application we should share. I don't think the issue comes from there though. It's definitely coming from Vertx, and it seems to be more specifically coming from something called handleExpiries.

[pantovad]

@BFergerson fully agree - please avoid posting app internals here. @xbkaishui could you please remove the comment with that SQL.

[xbkaishui]

Sorry, removed

[wu-sheng]

Hi, I removed the whole comment, otherwise, people could see the history.

[xbkaishui]

@xbkaishui, I'm not sure how much of the internal structure of @pantovad's application we should share. I don't think the issue comes from there though. It's definitely coming from Vertx, and it seems to be more specifically coming from something called handleExpiries.

Ok, I mean we can slow down the OOM happened time by remove the PostgreSQL plugin, because he has a too bigger sql (7k size per sql)

[BFergerson]

@xbkaishui, I'm not sure how much of the internal structure of @pantovad's application we should share. I don't think the issue comes from there though. It's definitely coming from Vertx, and it seems to be more specifically coming from something called handleExpiries.

Ok, I mean we can slow down the OOM happened time by remove the PostgreSQL plugin, because he has a too bigger sql (7k size per sql)

Ah, I agree it will slow it down. It'll eventually happen again though. Local spans aren't being closed. I think I've missed a place where I need to close spans that are created through Vert.x's EventBus.

@pantovad, if there is anything special happening in the method I mentioned could you let us know? Maybe check out https://github.com/apache/skywalking/tree/master/test/plugin/scenarios/vertx-eventbus-3.x-scenario/src/main/java/org/apache/skywalking/apm/testcase/vertxeventbus/controller and see if you are using the EventBus in a completely different way.

That code tests both local and cluster messages.

[BFergerson]

I'm not sure how much further I can dig into this without at least pseudocode or something but what it looks like to me is that the method handleExpiries is making a PostgreSQL call inside of a Vert.x context and in doing so creates an ExitSpan which is 7k per call. That ExitSpan doesn't appear to be closed which might explain why the LocalSpan is never being closed. I'm still not sure why either is not being closed but each call to handleExpiries requires 7k memory which it never relinquishes.

[wu-sheng]

@BFergerson @xbkaishui I have a feeling, no matter why this OOM happened, we should add a threshold to limit the length of SQL. 7k/SQL is really surprising to me.

[xbkaishui]

I totally agree, you can see below picture , the heap size is all the same, which contains the same sql, it's a little strange

[wu-sheng]

@pantovad Is that possible your codes executing this SQL in high concurrency?

[xbkaishui]

I don't think, the traceId timestamp is discrete for example

b4e775bd0c474b669bf9dc3a0083d6a2.114.15988957870015452
b4e775bd0c474b669bf9dc3a0083d6a2.114.15988922300018326
b4e775bd0c474b669bf9dc3a0083d6a2.114.15988965800027041

[wu-sheng]

Then, I am very curious about the process mode of @pantovad 's app. As I noted, https://hazelcast.com/ product is being used. Could you share a process flow of your codes logically? Whether there is a chance, the process lasts for a long time as hazelcast is a streaming process platform.

[pantovad]

@BFergerson I have just sent you the source of the methods handling handleExpiries event. Please have a look.

[BFergerson]

@pantovad, I'm able to reproduce a memory leak after looking at the source code you sent. However, I am only able to reproduce this memory leak when I use Vert.x EventBus incorrectly. Based on how I'm reproducing it and the small snippet of source code you sent, it seems to me that you're sending messages to handleExpiries and expecting a reply. Based on the source code you sent, it seems by design that there will not be a response sent to handleExpiries messages. This appears to be what keeps these spans open.

Can you tell me what EventBus method you're executing which sends a message to handleExpiries? Are you using one that supplies a non-null replyHandler? If so, I'm not sure this an issue that can be solved on Apache SkyWalking's end. I think the most that could be done is a warning message when a certain threshold is passed. I'm not exactly sure what threshold that would be though considering the amount of memory each un-replied message would require varies wildly (in your case 7k per).

[pantovad]

@BFergerson thx vm for your findings. We will try to fix the issue from our side by either providing reply message or change the sender not to expect the reply.