Fully featured low overhead profiler for Java EE and Java SE platforms.
Ultimate profiling and monitoring solution for Gradle, Maven, Ant, JUnit and TestNG.
Easy to use performance and memory profiler for .NET framework.

Yourkit opening sockets in CPU Profiling mode ?

Moderators: Vladimir Kondratyev, Anton Katilin

Yourkit opening sockets in CPU Profiling mode ?

Postby rico » Fri Jan 26, 2018 10:11 pm

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.
rico
 
Posts: 3
Joined: Fri Jan 26, 2018 9:50 pm

Re: Yourkit opening sockets in CPU Profiling mode ?

Postby Anton Katilin » Sun Jan 28, 2018 7:51 am

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 support@yourkit.com

Best regards,
Anton
Anton Katilin
 
Posts: 5675
Joined: Wed Aug 11, 2004 8:37 am

Re: Yourkit opening sockets in CPU Profiling mode ?

Postby rico » Sun Feb 04, 2018 5:56 pm

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 support@yourkit.com 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 ?

Postby rico » Sun Feb 04, 2018 6:51 pm

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.
rico
 
Posts: 3
Joined: Fri Jan 26, 2018 9:50 pm

Re: Yourkit opening sockets in CPU Profiling mode ?

Postby Anton Katilin » Mon Feb 05, 2018 7:41 am

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

Re: Yourkit opening sockets in CPU Profiling mode ?

Postby Anton Katilin » Sat Feb 10, 2018 3:52 pm

FYI: v2017.02 build 75 with the fix is available for download.
Anton Katilin
 
Posts: 5675
Joined: Wed Aug 11, 2004 8:37 am


Return to Java Profiler

Who is online

Users browsing this forum: No registered users and 11 guests