Yourkit opening sockets in CPU Profiling mode ?

Questions about YourKit Java Profiler
Post Reply
rico
Posts: 3
Joined: Fri Jan 26, 2018 9:50 pm

Yourkit opening sockets in CPU Profiling mode ?

Post by rico »

I am profiling a Tomcat 8.5 application which uses DBCP as standard pool for Neo4j JDBC Driver connections.

What is strange is when I run Yourkit in 'CPU Profiling' mode, I can see in 'Performance charts' that a lot of sockets are opened when database connections are opened, but these sockets are not closed when database connections are closed. This behavior is confirmed by lsof or ls /proc/my_tomcat_pid/fd | wc -l commands, where I can see file descriptors growing and growing for my application.

However, when I don't run Yourkit with 'CPU Profiling' mode, or when I stop it, the number of sockets opened/closed is stable, and behavior is also confirmed by lsof or ls /proc/my_tomcat_pid/fd | wc -l commands.

Is it a normal behavior and should I really worry about my application unreleasing Neo4j JDBC connections ?

I am using Yourkit 2016.02 version.

Thanks by advance.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Yourkit opening sockets in CPU Profiling mode ?

Post by Anton Katilin »

Hi,

We are not aware of this behavior.

Version Yourkit 2016.02 is not supported. Please use the latest version 2017.02 instead.

If this problem is reproducible with version 2017.02, could you please provide a snapshot demonstrating it. You may send the snapshot (a download link) and the output of lsof to [email protected]

Best regards,
Anton
rico
Posts: 3
Joined: Fri Jan 26, 2018 9:50 pm

Re: Yourkit opening sockets in CPU Profiling mode ?

Post by rico »

Hi,

I have downloaded latest version of Yourkit Kava Profiler and I am able to reproduce the problem with a sample code. I have sent an email to [email protected] with a snapshot download link.

Actually the code is really simple : I have a servlet which initialize in a static block a connection to the Tomcat DBCP pool, in order to get connections to Neo4j database via its JDBC driver. The problem is that every time I try to get a connection, a new socket is created (and not closed). I call the servlet with a simple curl command :

Code: Select all

watch -n 2 curl -v http://localhost:8080/socket
.

And I watch the number of sockets created for neo4j db (default port for bolt driver 7687) :

Code: Select all

watch 'lsof -p myTomcatPID | grep "localhost:7687" | wc -l'
The first problem that I can see is that 'Performance charts' and 'Events' dashboards show contradictory informations for Socket open/close. 'Performance chart' show that new sockets are opened and then closed, but in 'Events' we see that open sockets are accumulating. And lsof shows that sockets created are increasing.

After deep investigation, I found out that disabling 'Database' and 'Database LW' probes in the profiler removes the open sockets creation, and the lsof command shows stable number of sockets created. The open sockets creation is back again when I enable again 'Database' probe. After some debugging, I found out some Yourkit instrumentation classes between Tomcat DBCP Pool getConnection method call, and Neo4j JDBC driver classes :

Code: Select all

sun.nio.ch.SocketChannelImpl.connect(SocketAddress) SocketChannelImpl.java
sun.nio.ch.SocketAdaptor.connect(SocketAddress, int) SocketAdaptor.java:102
org.neo4j.driver.internal.net.ChannelFactory.connect(SocketChannel, BoltServerAddress, int) ChannelFactory.java:64
org.neo4j.driver.internal.net.ChannelFactory.create(BoltServerAddress, SecurityPlan, int, Logger) ChannelFactory.java:41
org.neo4j.driver.internal.net.SocketClient.start() SocketClient.java:124
org.neo4j.driver.internal.net.SocketConnection.startSocketClient() SocketConnection.java:92
org.neo4j.driver.internal.net.SocketConnection.<init>(BoltServerAddress, SecurityPlan, int, Logging) SocketConnection.java:67
org.neo4j.driver.internal.net.SocketConnector.createConnection(BoltServerAddress, SecurityPlan, int, Logging) SocketConnector.java:77
org.neo4j.driver.internal.net.SocketConnector.connect(BoltServerAddress) SocketConnector.java:50
org.neo4j.driver.internal.net.pooling.SocketConnectionPool$ConnectionSupplier.get() SocketConnectionPool.java:204
org.neo4j.driver.internal.net.pooling.SocketConnectionPool$ConnectionSupplier.get() SocketConnectionPool.java:186
org.neo4j.driver.internal.net.pooling.BlockingPooledConnectionQueue.acquire(Supplier) BlockingPooledConnectionQueue.java:96
org.neo4j.driver.internal.net.pooling.SocketConnectionPool.acquireConnection(BoltServerAddress, BlockingPooledConnectionQueue) SocketConnectionPool.java:137
org.neo4j.driver.internal.net.pooling.SocketConnectionPool.acquire(BoltServerAddress) SocketConnectionPool.java:76
org.neo4j.driver.internal.DirectConnectionProvider.acquireConnection(AccessMode) DirectConnectionProvider.java:45
org.neo4j.driver.internal.NetworkSession.acquireConnection(AccessMode) NetworkSession.java:340
org.neo4j.driver.internal.NetworkSession.beginTransaction(AccessMode) NetworkSession.java:288
org.neo4j.driver.internal.NetworkSession.beginTransaction() NetworkSession.java:175
org.neo4j.jdbc.bolt.BoltDriver.connect(String, Properties) BoltDriver.java:67
org.neo4j.jdbc.Driver.connect(String, Properties) Driver.java:55
java.sql.DriverManager.getConnection(String, Properties, Class) DriverManager.java:664
java.sql.DriverManager.getConnection(String, Properties) DriverManager.java:208
org.neo4j.jdbc.bolt.BoltDatabaseMetaData.<init>(BoltConnection, boolean) BoltDatabaseMetaData.java:51
org.neo4j.jdbc.bolt.BoltDatabaseMetaData.<init>(BoltConnection) BoltDatabaseMetaData.java:42
org.neo4j.jdbc.bolt.BoltConnection.getMetaData() BoltConnection.java:82
org.neo4j.jdbc.bolt.BoltConnection.getMetaData() BoltConnection.java:35
org.apache.tomcat.dbcp.dbcp2.DelegatingConnection.getMetaData() DelegatingConnection.java:421  <2 recursive calls>
com.yourkit.runtime.CallbackProxyImpl.callObjectMethod0(Class, Object, long) CallbackProxyImpl.java:91
com.yourkit.probes.ReflectionUtil.callMethod0(Class, Object, String, CallStatus) ReflectionUtil.java:72
com.yourkit.probes.ReflectionUtil.callMethod0(Object, String) ReflectionUtil.java:117
com.yourkit.probes.builtin.Databases.getConnectionURL(Object) Databases.java:772
com.yourkit.probes.builtin.Databases$1.retrieveResourceName(Object) Databases.java:60
com.yourkit.probes.ResourceRegistry.getResourceName(String, Object) ResourceRegistry.java:303
com.yourkit.probes.ResourceRegistry.openOnExitImpl(long, String, Object, Object, Throwable, FailedEventPolicy) ResourceRegistry.java:150
com.yourkit.probes.MasterResourceRegistry.openOnExit(long, String, Object, Throwable, FailedEventPolicy) MasterResourceRegistry.java:39
com.yourkit.probes.builtin.Databases$DataSource_or_PooledConnection_getConnection_Probe.onExit(long, Object, Object, Throwable) Databases.java:276
org.apache.tomcat.dbcp.dbcp2.PoolingDataSource.getConnection() PoolingDataSource.java:138
org.apache.tomcat.dbcp.dbcp2.BasicDataSource.getConnection() BasicDataSource.java:1543
com.myapp.web.MyServlet.doGet(HttpServletRequest, HttpServletResponse) MyServlet.java:31
javax.servlet.http.HttpServlet.service(HttpServletRequest, HttpServletResponse) HttpServlet.java:635
javax.servlet.http.HttpServlet.service(ServletRequest, ServletResponse) HttpServlet.java:742
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) ApplicationFilterChain.java:231
org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) ApplicationFilterChain.java:166
org.apache.tomcat.websocket.server.WsFilter.doFilter(ServletRequest, ServletResponse, FilterChain) WsFilter.java:52
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) ApplicationFilterChain.java:193
org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) ApplicationFilterChain.java:166
org.apache.catalina.core.StandardWrapperValve.invoke(Request, Response) StandardWrapperValve.java:199
org.apache.catalina.core.StandardContextValve.invoke(Request, Response) StandardContextValve.java:96
org.apache.catalina.authenticator.AuthenticatorBase.invoke(Request, Response) AuthenticatorBase.java:478
org.apache.catalina.core.StandardHostValve.invoke(Request, Response) StandardHostValve.java:140
org.apache.catalina.valves.ErrorReportValve.invoke(Request, Response) ErrorReportValve.java:81
org.apache.catalina.valves.AbstractAccessLogValve.invoke(Request, Response) AbstractAccessLogValve.java:650
org.apache.catalina.core.StandardEngineValve.invoke(Request, Response) StandardEngineValve.java:87
org.apache.catalina.connector.CoyoteAdapter.service(Request, Response) CoyoteAdapter.java:342
org.apache.coyote.http11.Http11Processor.service(SocketWrapperBase) Http11Processor.java:803
org.apache.coyote.AbstractProcessorLight.process(SocketWrapperBase, SocketEvent) AbstractProcessorLight.java:66
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(SocketWrapperBase, SocketEvent) AbstractProtocol.java:868
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun() NioEndpoint.java:1459
org.apache.tomcat.util.net.SocketProcessorBase.run() SocketProcessorBase.java:49
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) ThreadPoolExecutor.java:1149
java.util.concurrent.ThreadPoolExecutor$Worker.run() ThreadPoolExecutor.java:624
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run() TaskThread.java:61
java.lang.Thread.run() Thread.java:748
I wonder if the Yourkit classes are responsible of the Tomcat DBCP pool bypass because it is like we create a new connection every time I ask for it, which is not normal.
Based on these informations, I would like to know if the sockets creation are a consequence of the profiler use, or a real application problem. I can provide the sample code and the Tomcat server libraries if needed.

Thanks by advance.
rico
Posts: 3
Joined: Fri Jan 26, 2018 9:50 pm

Re: Yourkit opening sockets in CPU Profiling mode ?

Post by rico »

I forgot to mention that of course in the sample code the getConnection call is wrapped in a try resources block to auto close it.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Yourkit opening sockets in CPU Profiling mode ?

Post by Anton Katilin »

We've answered your email.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Yourkit opening sockets in CPU Profiling mode ?

Post by Anton Katilin »

FYI: v2017.02 build 75 with the fix is available for download.
Post Reply