Creating/closing a driver takes a long time

[tobias-johansson]

• Neo4j version: Community Neo4j 3.5.3
• Neo4j Mode: Single instance
• Driver version: Java language driver 1.7.2
• Operating system: Ubuntu 18.04.2 LTS
• Steps to reproduce

1. Start local instance of Neo4j 3.5.3
2. Run the following class

import org.neo4j.driver.v1.*;

public class DriverTest {
    public static void main(String[] args) {
        long start = System.currentTimeMillis();
        Driver driver = GraphDatabase.driver("bolt://localhost:7687", AuthTokens.basic("neo4j", "hej"));
        long created = System.currentTimeMillis();
        driver.close();
        long closed = System.currentTimeMillis();
        System.out.println("creation: " + (created - start) + "ms");
        System.out.println("closing: " + (closed - created) + "ms");
    }
}

• Expected behavior

creation: 14ms
closing: 22ms

• Actual behavior

creation: 1478ms
closing: 2248ms

[eastlondoner]

Do you know what the latency between the driver and the neo4j server instance is? The authentication requires round-trips to the server which will depend very much on that

[tobias-johansson]

@eastlondoner Not sure about creation, but it seems that closing always takes ~ 2000 ms, and that shouldn't require round-trips should it?

[technige]

As of 1.7, a graceful shutdown sends a GOODBYE message from client to server. This indicates to the server that the client is deliberately closing the connection, as opposed to when an unexpected network event occurs. No response is sent back though, the server merely closes its side too.

Note that TCP has a graceful shutdown sequence too, so there will definitely be network activity on connection closure.

[tobias-johansson]

@technige That makes sense, thanks! But still seems like we're waiting for some ~2000ms timeout on close right?
The long close times seem to always be present, also in very low latency setups (local docker neo4j and local jvm neo4j)

[zhenlineo]

@tobias-johansson You can just call the async close driver.closeAsync() in your test environment. The blocking close instead will wait for 2s for a more "graceful" shutdown. In your test env, I do not think you need to worry about it.

[tobias-johansson]

@zhenlineo We actually did that in CAPS initially, but since CAPS creates many driver instances, (per test * label * partition) we would instead get errors due to depleted OS resources (can't recall exactly what - too many file handles or sockets) 😄

[rickliao]

Hi, I have a simple program that connects to the database and ran a query "CALL db.labels()". After closing the driver, it just hangs there for a bit then prints the following warnings and error. Are they caused by this issue?

INFO: Closing driver instance 304892136
May 09, 2019 6:13:20 PM org.neo4j.driver.internal.logging.JULogger info
INFO: Closing connection pool towards localhost:7687
[WARNING] thread Thread[ObjectCleanerThread,1,Exporter] was interrupted but is still alive after waiting at least 15000msecs
[WARNING] thread Thread[ObjectCleanerThread,1,Exporter] will linger despite being asked to die via interruption
[WARNING] NOTE: 1 thread(s) did not finish despite being asked to  via interruption. This is not a problem with exec:java, it is a problem with the running code. Although not serious, it should be remedied.
[WARNING] Couldn't destroy threadgroup org.codehaus.mojo.exec.ExecJavaMojo$IsolatedThreadGroup[name=Exporter,maxpri=10]
java.lang.IllegalThreadStateException
    at java.lang.ThreadGroup.destroy (ThreadGroup.java:776)
    at org.codehaus.mojo.exec.ExecJavaMojo.execute (ExecJavaMojo.java:321)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:81)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build (SingleThreadedBuilder.java:56)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute (LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute (DefaultMaven.java:305)
    at org.apache.maven.DefaultMaven.doExecute (DefaultMaven.java:192)
    at org.apache.maven.DefaultMaven.execute (DefaultMaven.java:105)
    at org.apache.maven.cli.MavenCli.execute (MavenCli.java:956)
    at org.apache.maven.cli.MavenCli.doMain (MavenCli.java:288)
    at org.apache.maven.cli.MavenCli.main (MavenCli.java:192)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0 (Native Method)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke (NativeMethodAccessorImpl.java:62)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke (DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke (Method.java:567)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced (Launcher.java:282)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch (Launcher.java:225)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode (Launcher.java:406)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main (Launcher.java:347)

• Neo4j version: Community Neo4j 3.5.2
• Neo4j Mode: Not sure what's the mode. I just installed Neo4j desktop and added a graph.
• Driver version: Java language driver 1.7.2
• Operating system: Win 10

[zhenlineo]

Hi @rickliao How did you used the driver? Did you close the session before you close the driver?

[rickliao]

Hi @zhenlineo, I opened the driver and session inside try-with-resources. Something like this:

try (Driver driver = GraphDatabase.driver(uri, AuthTokens.basic(username, password));
     Session session = driver.session();) {
    StatementResult res = session.run(new Statement("CALL db.labels()"));
    Stream<Record> stream = res.stream();
    stream.forEach((record) -> {
      // use record here  
    });
} catch (Exception e) {
    e.printStackTrace();
} 

I just tried closing session before driver using "finally" but got the same warning/error. In fact, I also got the same error when running the DriverTest class tobias-johansson posted.

[kant111]

driver.closeAsync gave 30% gain compared todriver.close. But the creation of driver instance is still taking time (approx 2 seconds).

[zhenlineo]

Hi @kant111
The close blocking for too long problem has been fix in 2.0 with this PR #576.
For the driver creation takes too long problem, it will be fixed in this PR #609, where you can choose to turn off the connectivity verification on driver creation to avoid a network round trip.

As they are behaviour changes, they will not be back ported to 1.7 drivers.

[kant111]

Thanks @zhenlineo Should I use compile group: 'org.neo4j.driver', name: 'neo4j-java-driver', version: '2.0.0-alpha02' or should I build from source?

[technige]

Closing issue as this has been addressed in #576 and #609.