Delay in executing query with ExecuteRead()

paul.norman · September 12, 2024, 10:44am

Hi,

I'm observing what I believe to be excessive delays between calling ExecuteRead() to run a cypher query and the query actually being run.

My Neo4j (v5.23.0) database is running in a Docker container and contains a small graph - approximately 20 nodes.

I also have a C# service running in another Docker container that sends cypher queries to the database. This service is using the .net Neo4j driver, v5.24.0.

In the C# service I maintain a single driver session using the following code

driver = GraphDatabase.Driver(url, AuthTokens.Basic(login, password), 
                o => o.WithLogger(new Neo4jSerilogLogger())
session = driver.Session();

I then issue cypher queries through this session, and add some logging. This can be seen in the following code snippet.

Log.Information("Start Stopwatch");
var sw = Stopwatch.StartNew();
var result = session.ExecuteRead(tx => {
        Log.Information($"ElapsedTime #1: {sw.ElapsedMilliseconds}");
        tx.Run(query);
        Log.Information($"ElapsedTime #2: {sw.ElapsedMilliseconds}");
    });
}

What I find is that the time to run 'tx.run(query)', i.e. between "ElapsedTime #1" and "ElapsedTime #2" is just a few milliseconds. However, the time between starting the stopwatch and the "ElapsedTime #1" log message can be up to a few seconds.

I have tried to adjust the connection configuration parameters, pool size etc, but this does not seem to make a difference.

I have re-directed the Neo4j drivers logging to the console and set the log level to 'Debug' and I find I get the following type of output

[08:46:15 INF] Start Stopwatch       
[08:46:17 DBG] [bolt-9] C: BEGIN [{bookmarks, [FB:kcwQ8l2KfwuMScuU13Dxj2P/ECmQ]}, {mode, r}]
[08:46:17 DBG] [bolt-9] C: 00 36 B1 11 A2 89 62 6F 6F 6B 6D 61 72 6B 73 91 D0 1F 46 42 3A 6B 63 77 51 38 6C 32 4B 66 77 75 4D 53 63 75 55 31 33 44 78 6A 32 50 2F 45 43 6D 51 84 6D 6F 64 65 81 72 00 00
[08:46:17 DBG] [bolt-9] S: SUCCESS []

This indicates that it takes a considerable time to get to the point where the BOOKMARK is being set up. I am not really familiar with BOOKMARKS and I'm currently reading about them.

Could anyone indicates what might be causing this delay and how I might reduce or eliminate it?

Thanks,
Paul

grant_lodge · September 12, 2024, 11:25am

Hi Paul,
Several things can happen between the start of your Stopwatch and the success of the BEGIN being received.

The driver can open a new connection,
The driver can make a request to discover the server to know which database you are attempting to read/write from.
The server needs to catch up with the state represented by the specified bookmark.

Because we can see the C: BEGIN and S:SUCCESS occur in the same second it rules out item 3.

Specifying the database when opening a session with driver.Session(x => x.WithDatabase("foo")) would help with item 2.

glilienfield · September 12, 2024, 11:48am

Typically you use a singleton driver and get a new session each time you want to query. Sessions aren’t thread safe and and I believe maintain state between queries with bookmarks to ensure causal consistency.

Try getting new session each time, since the work you are doing for each query is unrelated.

paul.norman · September 12, 2024, 12:43pm

Thank you for your feedback.

I now specify the database name and create a new session for each query but I'm still seeing the issue.

One thing I forgot to mention before was that the nature of my application is to issue small bursts of queries at a time (say 10 queries) and the delay appears in the first query of each burst. That would suggest that a connection is being lost between each burst and needs to be created again, or something similar.

However, I still wouldn't expect the setup time to be more than a second.

grant_lodge · September 12, 2024, 2:12pm

Where are the database and application hosted?

Establishing a connection shouldn't take too long. If you want to share any further bolt (DEBUG/ TRACE) logs, I can see if there are any further pointers I can provide.
There are scenarios where the driver must open two connections before a transaction can be processed.

As a note, if you are using single-query transactions, you can use the transaction API exposed on the IDriver interface; because it runs only single-query transactions, it reduces the amount of networking required to complete the transaction.

var config = new QueryConfig(RoutingControl.Writers, database);
var res = await driver
    .ExecutableQuery(query)
    .WithParameters(parameters)
    .WithConfig(config)
    .ExecuteAsync();

This will not aid times when connection initiation is the issue.

glilienfield · September 12, 2024, 2:41pm

Another thing is that queries have to be planned the first time they are presented and after the cache expires. Are using parameters in your query so the query plan can be reused?

paul.norman · September 12, 2024, 3:35pm

The database is running in a container on my local machine, as is the service sending the queries.

Note that the containers are running under WSL on a WIndow PC, if that provides more context.

I tried to attach a log file with more information, but as a new user I'me prohibited from doing that, but more information is attached. I've redacted the actual queries - but they are quite straightforward and do not return many nodes. I've separated out each query and marked those which specifically caused a delay - there are 3 or 4 of them.

Is it more efficient to create a query with parameters? If so, what exactly is meant by parameters in this context?

Thanks again.


#
# No delay on this query
#
[14:33:01 INF] Query time: Query: ######## RETURN node
[14:33:01 DBG] [conn-kb-instance-service:7687-1] ~~ [CONNECT] bolt://kb-instance-service:7687/
[14:33:01 DBG] [conn-kb-instance-service:7687-1] C: [HANDSHAKE] 60 60 B0 17 00 06 06 05 00 02 04 04 00 00 01 04 00 00 00 03
[14:33:01 DBG] [conn-kb-instance-service:7687-1] S: [HANDSHAKE] 5.6
[14:33:01 DBG] [conn-kb-instance-service:7687-1] C: HELLO [{user_agent, neo4j-dotnet/5.24}, {routing, NULL}, {bolt_agent, [{product, neo4j-dotnet/5.24.34}, {platform, Linux 5.15.153.1-microsoft-standard-WSL2 #1 SMP Fri Mar 29 23:14:13 UTC 2024;X64}, {language_details, .NET 7.0.19}]}]
[14:33:01 DBG] [conn-kb-instance-service:7687-1] C: LOGON [{scheme, basic}, {principal, neo4j}, {credentials, ******}]
[14:33:01 DBG] [conn-kb-instance-service:7687-1] C: 00 CD B1 01 A3 8A 75 73 65 72 5F 61 67 65 6E 74 D0 11 6E 65 6F 34 6A 2D 64 6F 74 6E 65 74 2F 35 2E 32 34 87 72 6F 75 74 69 6E 67 C0 8A 62 6F 6C 74 5F 61 67 65 6E 74 A3 87 70 72 6F 64 75 63 74 D0 14 6E 65 6F 34 6A 2D 64 6F 74 6E 65 74 2F 35 2E 32 34 2E 33 34 88 70 6C 61 74 66 6F 72 6D D0 50 4C 69 6E 75 78 20 35 2E 31 35 2E 31 35 33 2E 31 2D 6D 69 63 72 6F 73 6F 66 74 2D 73 74 61 6E 64 61 72 64 2D 57 53 4C 32 20 23 31 20 53 4D 50 20 46 72 69 20 4D 61 72 20 32 39 20 32 33 3A 31 34 3A 31 33 20 55 54 43 20 32 30 32 34 3B 58 36 34 D0 10 6C 61 6E 67 75 61 67 65 5F 64 65 74 61 69 6C 73 8B 2E 4E 45 54 20 37 2E 30 2E 31 39 00 00 00 3A B1 6A A3 86 73 63 68 65 6D 65 85 62 61 73 69 63 89 70 72 69 6E 63 69 70 61 6C 85 6E 65 6F 34 6A 8B 63 72 65 64 65 6E 74 69 61 6C 73 8D 74 65 73 74 5F 64 61 74 61 62 61 73 65 00 00



#
# No delay on this query
#
[14:33:01 DBG] [conn-kb-instance-service:7687-1] S: SUCCESS [{server, Neo4j/5.23.0}, {connection_id, bolt-9}, {hints, [{connection.recv_timeout_seconds, 120}]}]
[14:33:01 DBG] [conn-kb-instance-service:7687-1] Connection 'conn-kb-instance-service:7687-1' renamed to 'bolt-9'. The new name identifies the connection uniquely both on the client side and the server side.
[14:33:01 DBG] [bolt-9] S: SUCCESS []
[14:33:01 DBG] [bolt-9] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:01 DBG] [bolt-9] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:01 DBG] [bolt-9] S: SUCCESS []
[14:33:01 DBG] [bolt-9] C: RUN `##############`, [] []
[14:33:01 DBG] [bolt-9] C: PULL [{n, 1000}]
[14:33:01 DBG] [bolt-9] C: 00 24 B3 10 D0 1E 4D 41 54 43 48 20 28 6E 6F 64 65 3A 45 76 65 6E 74 29 20 52 45 54 55 52 4E 20 6E 6F 64 65 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:01 DBG] [bolt-9] S: SUCCESS [{t_first, 28}, {fields, [node]}, {qid, 0}]
[14:33:01 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:01 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:01 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:01 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:01 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:01 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:01 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:01 DBG] [bolt-9] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 5}, {db, neo4j}]
[14:33:01 DBG] [bolt-9] C: COMMIT
[14:33:01 DBG] [bolt-9] C: 00 02 B0 12 00 00
[14:33:01 DBG] [bolt-9] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:01 DBG] [bolt-9] C: RESET
[14:33:01 DBG] [bolt-9] C: 00 02 B0 0F 00 00
[14:33:01 DBG] [bolt-9] S: SUCCESS []



#
# No delay on this query
#
[14:33:02 INF] Query time: Query: ############# RETURN node
[14:33:02 DBG] [bolt-9] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:02 DBG] [bolt-9] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:02 DBG] [bolt-9] S: SUCCESS []
[14:33:02 DBG] [bolt-9] C: RUN `#################`, [] []
[14:33:02 DBG] [bolt-9] C: PULL [{n, 1000}]
[14:33:02 DBG] [bolt-9] C: 00 25 B3 10 D0 1F 4D 41 54 43 48 20 28 6E 6F 64 65 3A 41 63 74 69 6F 6E 29 20 52 45 54 55 52 4E 20 6E 6F 64 65 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:02 DBG] [bolt-9] S: SUCCESS [{t_first, 26}, {fields, [node]}, {qid, 0}]
[14:33:02 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:02 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:02 DBG] [bolt-9] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:02 DBG] [bolt-9] C: COMMIT
[14:33:02 DBG] [bolt-9] C: 00 02 B0 12 00 00
[14:33:02 DBG] [bolt-9] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:02 DBG] [bolt-9] C: RESET
[14:33:02 DBG] [bolt-9] C: 00 02 B0 0F 00 00
[14:33:02 DBG] [bolt-9] S: SUCCESS []



#
# No delay on this query
#
[14:33:02 INF] Query time: Query: ############## RETURN node
[14:33:02 DBG] [bolt-9] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:02 DBG] [bolt-9] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:02 DBG] [bolt-9] S: SUCCESS []
[14:33:02 DBG] [bolt-9] C: RUN `###################`, [] []
[14:33:02 DBG] [bolt-9] C: PULL [{n, 1000}]
[14:33:02 DBG] [bolt-9] C: 00 25 B3 10 D0 1F 4D 41 54 43 48 20 28 6E 6F 64 65 3A 41 63 74 69 6F 6E 29 20 52 45 54 55 52 4E 20 6E 6F 64 65 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:02 DBG] [bolt-9] S: SUCCESS [{t_first, 2}, {fields, [node]}, {qid, 0}]
[14:33:02 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:02 DBG] [bolt-9] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:02 DBG] [bolt-9] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:02 DBG] [bolt-9] C: COMMIT
[14:33:02 DBG] [bolt-9] C: 00 02 B0 12 00 00
[14:33:02 DBG] [bolt-9] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:02 DBG] [bolt-9] C: RESET
[14:33:02 DBG] [bolt-9] C: 00 02 B0 0F 00 00
[14:33:02 DBG] [bolt-9] S: SUCCESS []



#
# There was a significamt delay on this query > 1 sec
#
[14:33:56 INF] Query time: Query: #################### RETURN node
[14:33:57 DBG] [bolt-9] C: GOODBYE
[14:33:57 DBG] [bolt-9] C: 00 02 B0 02 00 00
[14:33:57 DBG] [conn-kb-instance-service:7687-2] ~~ [CONNECT] bolt://kb-instance-service:7687/
[14:33:57 DBG] [conn-kb-instance-service:7687-2] C: [HANDSHAKE] 60 60 B0 17 00 06 06 05 00 02 04 04 00 00 01 04 00 00 00 03
[14:33:57 DBG] [conn-kb-instance-service:7687-2] S: [HANDSHAKE] 5.6
[14:33:57 DBG] [conn-kb-instance-service:7687-2] C: HELLO [{user_agent, neo4j-dotnet/5.24}, {routing, NULL}, {bolt_agent, [{product, neo4j-dotnet/5.24.34}, {platform, Linux 5.15.153.1-microsoft-standard-WSL2 #1 SMP Fri Mar 29 23:14:13 UTC 2024;X64}, {language_details, .NET 7.0.19}]}]
[14:33:57 DBG] [conn-kb-instance-service:7687-2] C: LOGON [{scheme, basic}, {principal, neo4j}, {credentials, ******}]
[14:33:57 DBG] [conn-kb-instance-service:7687-2] C: 00 CD B1 01 A3 8A 75 73 65 72 5F 61 67 65 6E 74 D0 11 6E 65 6F 34 6A 2D 64 6F 74 6E 65 74 2F 35 2E 32 34 87 72 6F 75 74 69 6E 67 C0 8A 62 6F 6C 74 5F 61 67 65 6E 74 A3 87 70 72 6F 64 75 63 74 D0 14 6E 65 6F 34 6A 2D 64 6F 74 6E 65 74 2F 35 2E 32 34 2E 33 34 88 70 6C 61 74 66 6F 72 6D D0 50 4C 69 6E 75 78 20 35 2E 31 35 2E 31 35 33 2E 31 2D 6D 69 63 72 6F 73 6F 66 74 2D 73 74 61 6E 64 61 72 64 2D 57 53 4C 32 20 23 31 20 53 4D 50 20 46 72 69 20 4D 61 72 20 32 39 20 32 33 3A 31 34 3A 31 33 20 55 54 43 20 32 30 32 34 3B 58 36 34 D0 10 6C 61 6E 67 75 61 67 65 5F 64 65 74 61 69 6C 73 8B 2E 4E 45 54 20 37 2E 30 2E 31 39 00 00 00 3A B1 6A A3 86 73 63 68 65 6D 65 85 62 61 73 69 63 89 70 72 69 6E 63 69 70 61 6C 85 6E 65 6F 34 6A 8B 63 72 65 64 65 6E 74 69 61 6C 73 8D 74 65 73 74 5F 64 61 74 61 62 61 73 65 00 00
[14:33:57 DBG] [conn-kb-instance-service:7687-2] S: SUCCESS [{server, Neo4j/5.23.0}, {connection_id, bolt-10}, {hints, [{connection.recv_timeout_seconds, 120}]}]
[14:33:57 DBG] [conn-kb-instance-service:7687-2] Connection 'conn-kb-instance-service:7687-2' renamed to 'bolt-10'. The new name identifies the connection uniquely both on the client side and the server side.
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################' RETURN node`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 41 B3 10 D0 3B 4D 41 54 43 48 20 28 6E 6F 64 65 3A 45 76 65 6E 74 29 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 3D 27 53 74 61 72 74 20 45 78 61 6D 27 20 52 45 54 55 52 4E 20 6E 6F 64 65 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 2}, {fields, [node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN node
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################' RETURN node`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 41 B3 10 D0 3B 4D 41 54 43 48 20 28 6E 6F 64 65 3A 45 76 65 6E 74 29 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 3D 27 53 74 61 72 74 20 45 78 61 6D 27 20 52 45 54 55 52 4E 20 6E 6F 64 65 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 A8 B3 10 D0 A2 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 45 76 65 6E 74 29 2D 5B 3A 69 6E 64 69 63 61 74 65 73 5F 73 74 61 72 74 5F 6F 66 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 53 74 61 72 74 20 45 78 61 6D 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 0}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 A8 B3 10 D0 A2 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 3C 2D 5B 3A 69 73 5F 66 6F 6C 6C 6F 77 65 64 5F 62 79 5D 2D 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 50 72 65 70 61 72 61 74 69 6F 6E 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 02000}, {status_description, note: no data}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 A8 B3 10 D0 A2 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 45 76 65 6E 74 29 2D 5B 3A 69 6E 64 69 63 61 74 65 73 5F 73 74 61 72 74 5F 6F 66 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 53 74 61 72 74 20 45 78 61 6D 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 AC B3 10 D0 A6 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 2D 5B 3A 69 73 5F 73 75 70 70 6F 72 74 65 64 5F 62 79 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 53 75 70 70 6F 72 74 49 74 65 6D 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 50 72 65 70 61 72 61 74 69 6F 6E 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 9}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 A3 B3 10 D0 9D 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 2D 5B 3A 73 74 61 72 74 73 5F 77 69 74 68 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 41 63 74 69 6F 6E 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 50 72 65 70 61 72 61 74 69 6F 6E 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 8}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 AC B3 10 D0 A6 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 2D 5B 3A 69 73 5F 73 75 70 70 6F 72 74 65 64 5F 62 79 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 53 75 70 70 6F 72 74 49 74 65 6D 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 50 72 65 70 61 72 61 74 69 6F 6E 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 A8 B3 10 D0 A2 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 45 76 65 6E 74 29 2D 5B 3A 69 6E 64 69 63 61 74 65 73 5F 73 74 61 72 74 5F 6F 66 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 53 74 61 72 74 20 45 78 61 6D 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 AC B3 10 D0 A6 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 2D 5B 3A 69 73 5F 73 75 70 70 6F 72 74 65 64 5F 62 79 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 53 75 70 70 6F 72 74 49 74 65 6D 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 50 72 65 70 61 72 61 74 69 6F 6E 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 A3 B3 10 D0 9D 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 2D 5B 3A 73 74 61 72 74 73 5F 77 69 74 68 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 41 63 74 69 6F 6E 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 50 72 65 70 61 72 61 74 69 6F 6E 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []


#
# No delay on this query
#
[14:33:57 INF] Query time: Query: #################### RETURN other_node        
[14:33:57 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []
[14:33:57 DBG] [bolt-10] C: RUN `####################`, [] []
[14:33:57 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:33:57 DBG] [bolt-10] C: 00 AC B3 10 D0 A6 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 57 6F 72 6B 66 6C 6F 77 29 2D 5B 3A 69 73 5F 73 75 70 70 6F 72 74 65 64 5F 62 79 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 53 75 70 70 6F 72 74 49 74 65 6D 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 50 72 65 70 61 72 61 74 69 6F 6E 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:33:57 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 0}, {db, neo4j}]
[14:33:57 DBG] [bolt-10] C: COMMIT
[14:33:57 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:33:57 DBG] [bolt-10] C: RESET
[14:33:57 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:33:57 DBG] [bolt-10] S: SUCCESS []



#
# There was a significamt delay on this query > 1 sec
#
[14:34:07 INF] Query time: Query: #################### RETURN other_node        
[14:34:09 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:34:09 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:34:09 DBG] [bolt-10] S: SUCCESS []
[14:34:09 DBG] [bolt-10] C: RUN `####################`, [] []
[14:34:09 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:34:09 DBG] [bolt-10] C: 00 B0 B3 10 D0 AA 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 41 63 74 69 6F 6E 29 2D 5B 3A 69 73 5F 73 75 70 70 6F 72 74 65 64 5F 62 79 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 53 75 70 70 6F 72 74 49 74 65 6D 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 53 65 74 20 56 4C 20 53 63 61 6E 20 50 61 72 61 6D 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:34:09 INF] Query time: ReadNodeResult Stop: 1973
[14:34:09 DBG] [bolt-10] S: SUCCESS [{t_first, 33}, {fields, [other_node]}, {qid, 0}]
[14:34:09 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:34:09 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:34:09 DBG] [bolt-10] C: COMMIT
[14:34:09 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:34:09 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:34:09 DBG] [bolt-10] C: RESET
[14:34:09 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:34:09 DBG] [bolt-10] S: SUCCESS []



#
# There was a significamt delay on this query > 1 sec
#
[14:34:21 INF] Query time: Query: #################### RETURN node
[14:34:23 DBG] [bolt-10] C: BEGIN [{mode, r}, {db, neo4j}]
[14:34:23 DBG] [bolt-10] C: 00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00
[14:34:23 DBG] [bolt-10] S: SUCCESS []
[14:34:23 DBG] [bolt-10] C: RUN `#######################`, [] []
[14:34:23 DBG] [bolt-10] C: PULL [{n, 1000}]
[14:34:23 DBG] [bolt-10] C: 00 49 B3 10 D0 43 4D 41 54 43 48 20 28 6E 6F 64 65 3A 45 76 65 6E 74 29 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 3D 27 54 45 45 20 61 6E 64 20 43 61 74 68 20 6F 6E 20 56 4C 27 20 52 45 54 55 52 4E 20 6E 6F 64 65 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00
[14:34:23 DBG] [bolt-10] S: SUCCESS [{t_first, 29}, {fields, [node]}, {qid, 0}]
[14:34:23 DBG] [bolt-10] S: RECORD [Neo4j.Driver.Internal.Types.Node]
[14:34:23 DBG] [bolt-10] S: SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]
[14:34:23 DBG] [bolt-10] C: COMMIT
[14:34:23 DBG] [bolt-10] C: 00 02 B0 12 00 00
[14:34:23 DBG] [bolt-10] S: SUCCESS [{bookmark, FB:kcwQnI1vkERGT+63xoqkQfGlHymQ}]
[14:34:23 DBG] [bolt-10] C: RESET
[14:34:23 DBG] [bolt-10] C: 00 02 B0 0F 00 00
[14:34:23 DBG] [bolt-10] S: SUCCESS []

grant_lodge · September 12, 2024, 3:50pm

Thanks for the extra context and nice logs.

This is entirely unexpected, to confirm, there are no logs between these lines? it might be worth setting the minimum log level to trace.

paul.norman · September 12, 2024, 6:20pm

No, there's nothing between those log lines.

Does the .Net driver have log messages at the Trace level? I'm using Serilog to redirect the logs and have set it to the Verbose level, but do not see lower level logs. Should I use another logger?

What Trace logs would I expect to see?

I feel it's something obvious I'm missing but can't think what.

dana_canzano · September 12, 2024, 6:39pm

@paul.norman

regarding

Is it more efficient to create a query with parameters? If so, what exactly is meant by parameters in this context?

To execute a Cypher Query, the query text is required along with an optional 
set of named parameters. The text can contain parameter placeholders that
 are substituted with the corresponding values at runtime. While it is possible
 to run non-parameterized Cypher Queries, good programming practice is to 
use parameters in Cypher Queries whenever possible. This allows for the 
caching of queries within the Cypher Engine, which is beneficial for 
performance. Parameter values should adhere to Cypher values.

in the code snippet provided further down in the doc it does include

// Create an employment relationship to a pre-existing company node.
// This relies on the person first having been created.
private IResultSummary Employ(IQueryRunner tx, string personName, string companyName)
{
    return tx.Run(
            @"MATCH (person:Person {name: $personName})
                 MATCH (company:Company {name: $companyName})
                 CREATE (person)-[:WORKS_FOR]->(company)",
            new { personName, companyName })
        .Consume();
}

and to which the paramters are defined via new { personName, companyName } and thus referenced in the cypher stmt via $ syntax, and this $personName and $companyName

grant_lodge · September 13, 2024, 9:39am

Hi Paul,
if you could share your Neo4jSerilogLogger class I can highlight the changes to make to see the trace logs.
Otherwise, the ILogger interface exposes 2 methods to enable trace logs: bool IsTraceEnabled() and void Trace(string, object[])

Please also ensure that IsDebugEnabled is also returning true.

paul.norman · September 13, 2024, 12:15pm

Hi Grant,

The class looks like the following. Looking at it again, I think I see that the Trace() method should contain Log.Verbose() not Log.Debug(). Though when I change that I still don't see additional logging.

using Serilog;

namespace re_algorithm.Controller;

public class Neo4jSerilogLogger : Neo4j.Driver.ILogger {
    public void Error(Exception cause, string message, params object[] args) {
        Log.Error(cause, message, args);
    }

    public void Info(string message, params object[] args) {
        Log.Information(message, args);
    }

    public void Warn(Exception cause, string message, params object[] args) {
        Log.Warning(message, args);
    }

    public void Debug(string message, params object[] args) {
        Log.Debug(message, args);
    }

    public void Trace(string message, params object[] args) {
        Log.Debug(message, args);
    }

    public bool IsTraceEnabled() {
        return true;
    }

    public bool IsDebugEnabled() {
        return true;
    }
}

grant_lodge · September 13, 2024, 1:03pm

Looks good.

#
# There was a significamt delay on this query > 1 sec
#
[14:33:56 INF] Query time: Query: #################### RETURN node
[14:33:57 DBG] [bolt-9] C: GOODBYE
[14:33:57 DBG] [bolt-9] C: 00 02 B0 02 00 00
[14:33:57 DBG] [conn-kb-instance-service:7687-2] ~~ [CONNECT] bolt://kb-instance-service:7687/
[14:33:57 DBG] [conn-kb-instance-service:7687-2] C: [HANDSHAKE] 60 60 B0 17 00 06 06 05 00 02 04 04 00 00 01 04 00 00 00 03
[14:33:57 DBG] [conn-kb-instance-service:7687-2] S: [HANDSHAKE] 5.6

Could you increase the precision of the log time to milliseconds, as the minimum resolution of 1 second is quite large.

This part of the logs interests me; since you are connecting to a local instance, this connection should be rock solid. Do you have any driver config settings for max connection lifetimes, etc.?

paul.norman · September 13, 2024, 1:48pm

Running it again I don't get the GOODBYE etc. with any of the queries.

I've tried various settings, as seen in the commented out sections of the code below, but I'm currently running on defaults.

string customTemplate = "[{Timestamp: HH:mm:ss.fff} {Level:u3}]\t{Message}{NewLine}{Exception}";
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Verbose()
    .WriteTo.Console(outputTemplate: customTemplate)
    .CreateLogger();

driver = GraphDatabase.Driver(url, AuthTokens.Basic(login, password), 
    o => o.WithLogger(new Neo4jSerilogLogger())
         //   .WithMaxConnectionPoolSize(200)
         //   .WithMaxIdleConnectionPoolSize(200)
         //   .WithConnectionAcquisitionTimeout(TimeSpan.FromSeconds(30))
         //   .WithConnectionTimeout(Neo4j.Driver.Config.InfiniteInterval)
         //   .WithSocketKeepAliveEnabled(true)
         //   .WithConnectionIdleTimeout(TimeSpan.FromSeconds(30))
         //   .WithMaxConnectionLifetime(TimeSpan.FromMinutes(10))
);

Running with the higher resolution times the following shows an over 3 sec delay.

[ 13:29:35.423 INF]	Query time: Query: MATCH (node:Action)-[:is_supported_by]->(other_node:SupportItem) WHERE node.name = '#####' RETURN other_node        

[ 13:29:39.383 DBG]	[bolt-3] C: "BEGIN [{mode, r}, {db, neo4j}]"
[ 13:29:39.383 DBG]	[bolt-3] C: "00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00"
[ 13:29:39.385 DBG]	[bolt-3] S: "SUCCESS []"
[ 13:29:39.386 INF]	Query time: ReadNodeResult Start: 3962
[ 13:29:39.386 DBG]	[bolt-3] C: "RUN `MATCH (node:Action)-[:is_supported_by]->(other_node:SupportItem) WHERE node.name = '#####' RETURN other_node\r\n        `, [] []"
[ 13:29:39.386 DBG]	[bolt-3] C: "PULL [{n, 1000}]"
[ 13:29:39.386 DBG]	[bolt-3] C: "00 B0 B3 10 D0 AA 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 3A 41 63 74 69 6F 6E 29 2D 5B 3A 69 73 5F 73 75 70 70 6F 72 74 65 64 5F 62 79 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 3A 53 75 70 70 6F 72 74 49 74 65 6D 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 27 53 65 74 20 56 4C 20 53 63 61 6E 20 50 61 72 61 6D 27 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A0 A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00"
[ 13:29:39.386 INF]	Query time: ReadNodeResult Stop: 3963
[ 13:29:39.490 DBG]	[bolt-3] S: "SUCCESS [{t_first, 102}, {fields, [other_node]}, {qid, 0}]"
[ 13:29:39.493 DBG]	[bolt-3] S: "RECORD [Neo4j.Driver.Internal.Types.Node]"
[ 13:29:39.493 DBG]	[bolt-3] S: "SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 2}, {db, neo4j}]"
[ 13:29:39.495 DBG]	[bolt-3] C: "COMMIT"
[ 13:29:39.495 DBG]	[bolt-3] C: "00 02 B0 12 00 00"
[ 13:29:39.499 DBG]	[bolt-3] S: "SUCCESS [{bookmark, FB:kcwQ4//bptBeQxWa/ZsCULxM7imQ}]"
[ 13:29:39.500 DBG]	[bolt-3] C: "RESET"
[ 13:29:39.500 DBG]	[bolt-3] C: "00 02 B0 0F 00 00"
[ 13:29:39.502 DBG]	[bolt-3] S: "SUCCESS []"

To be honest I'm suspicious of other parts of my app cutting in at these points, though I'm not sure how and it's something I need to look at further.

If you have advice on what connections setting would help that would be great. But we're using a single, local database and a fairly synchronous workflow so I feel the defaults should suffice.

Thanks once more for your feedback. It's just about the weekend here so I'll revisit this next week, hopefully with a clear mind

grant_lodge · September 13, 2024, 3:31pm

I just noticed you are using the synchronous extension for the driver. Could you try to use the driver without the extension?

using var session = driver.AsyncSession(x => x.WithDatabase("neo4j"));
Log.Information("Start Stopwatch");
var sw = Stopwatch.StartNew();
var result = session.ExecuteReadAsync(async tx => {
        Log.Information($"ElapsedTime #1: {sw.ElapsedMilliseconds}");
        var c = await tx.RunAsync(query);
        await c.ConsumeAsync();
        Log.Information($"ElapsedTime #2: {sw.ElapsedMilliseconds}");
}).GetAwaiter().GetResult();

One for next week, so have a lovely weekend.

paul.norman · September 16, 2024, 12:22pm

Hi, well it's a new week!

I've changed to the async version using the following code, althogh I'm still seeing the delays.

using (var session = driver.AsyncSession(x => x.WithDatabase("neo4j"))) {
	Log.Information($"Query time: ReadNodeResult Start: {sw.ElapsedMilliseconds}");
	var result = session.ExecuteReadAsync(async tx => {
		var result = (parameters == null) ? await tx.RunAsync(query) : await tx.RunAsync(query, parameters);
		var record = await result.ToListAsync();
		nodes = record.Select(p => new Node(p[0].As<INode>())).ToList();
		return nodes;
	}).GetAwaiter().GetResult();
	Log.Information($"Query time: ReadNodeResult Stop: {sw.ElapsedMilliseconds}");

	return result;
}

And I've managed to get the trace logs to work.

So the following gives a number of queries that are taking longer than expected.

Do they provide any more insights?

#
# Query
#
[ 12:01:12.513 INF]	Query time: Query:             MATCH (node)-[rel]->(other_node)            WHERE node.name = $node_name AND $node_label in labels(node) AND $relationship_name = type(rel) AND $other_node_label in labels(other_node)            RETURN other_node        
[ 12:01:12.513 INF]	Query time: ReadNodeResult Start: 0
[ 12:01:12.513 DBG]	[bolt-9] C: "BEGIN [{mode, r}, {db, neo4j}]"
[ 12:01:12.513 VRB]	[bolt-9] C: "00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00"
[ 12:01:13.492 DBG]	[bolt-9] S: "SUCCESS []"
[ 12:01:13.492 DBG]	[bolt-9] C: "RUN `\r\n            MATCH (node)-[rel]->(other_node)\r\n            WHERE node.name = $node_name AND $node_label in labels(node) AND $relationship_name = type(rel) AND $other_node_label in labels(other_node)\r\n            RETURN other_node\r\n        `, [{node_name, Set VL Scan Param}, {node_label, Action}, {relationship_name, is_supported_by}, {other_node_label, SupportItem}] []"
[ 12:01:13.492 DBG]	[bolt-9] C: "PULL [{n, 1000}]"
[ 12:01:13.492 VRB]	[bolt-9] C: "01 66 B3 10 D0 F0 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 29 2D 5B 72 65 6C 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 24 6E 6F 64 65 5F 6E 61 6D 65 20 41 4E 44 20 24 6E 6F 64 65 5F 6C 61 62 65 6C 20 69 6E 20 6C 61 62 65 6C 73 28 6E 6F 64 65 29 20 41 4E 44 20 24 72 65 6C 61 74 69 6F 6E 73 68 69 70 5F 6E 61 6D 65 20 3D 20 74 79 70 65 28 72 65 6C 29 20 41 4E 44 20 24 6F 74 68 65 72 5F 6E 6F 64 65 5F 6C 61 62 65 6C 20 69 6E 20 6C 61 62 65 6C 73 28 6F 74 68 65 72 5F 6E 6F 64 65 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A4 89 6E 6F 64 65 5F 6E 61 6D 65 D0 11 53 65 74 20 56 4C 20 53 63 61 6E 20 50 61 72 61 6D 8A 6E 6F 64 65 5F 6C 61 62 65 6C 86 41 63 74 69 6F 6E D0 11 72 65 6C 61 74 69 6F 6E 73 68 69 70 5F 6E 61 6D 65 8F 69 73 5F 73 75 70 70 6F 72 74 65 64 5F 62 79 D0 10 6F 74 68 65 72 5F 6E 6F 64 65 5F 6C 61 62 65 6C 8B 53 75 70 70 6F 72 74 49 74 65 6D A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00"
[ 12:01:14.493 DBG]	[bolt-9] S: "SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]"
[ 12:01:14.493 DBG]	[bolt-9] S: "RECORD [Neo4j.Driver.Internal.Types.Node]"
[ 12:01:14.493 DBG]	[bolt-9] S: "SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]"
[ 12:01:14.493 DBG]	[bolt-9] C: "COMMIT"
[ 12:01:14.493 VRB]	[bolt-9] C: "00 02 B0 12 00 00"
[ 12:01:14.494 DBG]	[bolt-9] S: "SUCCESS [{bookmark, FB:kcwQ0IzUBAD/ShOD5//bfb72WymQ}]"
[ 12:01:14.494 DBG]	[bolt-9] C: "RESET"
[ 12:01:14.494 VRB]	[bolt-9] C: "00 02 B0 0F 00 00"
[ 12:01:14.495 DBG]	[bolt-9] S: "SUCCESS []"
[ 12:01:14.495 INF]	Query time: ReadNodeResult Stop: 1982


#
# Query
#
[ 12:01:18.737 INF]	Query time: Query: MATCH (node) WHERE $node_type in labels(node) AND node.name=$node_name RETURN node
[ 12:01:18.737 INF]	Query time: ReadNodeResult Start: 0
[ 12:01:18.738 DBG]	[bolt-9] C: "BEGIN [{mode, r}, {db, neo4j}]"
[ 12:01:18.738 VRB]	[bolt-9] C: "00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00"
[ 12:01:19.729 DBG]	[bolt-9] S: "SUCCESS []"
[ 12:01:19.729 DBG]	[bolt-9] C: "RUN `MATCH (node) WHERE $node_type in labels(node) AND node.name=$node_name RETURN node`, [{node_type, Event}, {node_name, TEE and Cath on VL}] []"
[ 12:01:19.729 DBG]	[bolt-9] C: "PULL [{n, 1000}]"
[ 12:01:19.729 VRB]	[bolt-9] C: "00 86 B3 10 D0 52 4D 41 54 43 48 20 28 6E 6F 64 65 29 20 57 48 45 52 45 20 24 6E 6F 64 65 5F 74 79 70 65 20 69 6E 20 6C 61 62 65 6C 73 28 6E 6F 64 65 29 20 41 4E 44 20 6E 6F 64 65 2E 6E 61 6D 65 3D 24 6E 6F 64 65 5F 6E 61 6D 65 20 52 45 54 55 52 4E 20 6E 6F 64 65 A2 89 6E 6F 64 65 5F 74 79 70 65 85 45 76 65 6E 74 89 6E 6F 64 65 5F 6E 61 6D 65 D0 12 54 45 45 20 61 6E 64 20 43 61 74 68 20 6F 6E 20 56 4C A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00"
[ 12:01:19.754 DBG]	[bolt-9] S: "SUCCESS [{t_first, 24}, {fields, [node]}, {qid, 0}]"
[ 12:01:19.755 DBG]	[bolt-9] S: "RECORD [Neo4j.Driver.Internal.Types.Node]"
[ 12:01:19.755 DBG]	[bolt-9] S: "SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 1}, {db, neo4j}]"
[ 12:01:19.756 DBG]	[bolt-9] C: "COMMIT"
[ 12:01:19.756 VRB]	[bolt-9] C: "00 02 B0 12 00 00"
[ 12:01:19.756 DBG]	[bolt-9] S: "SUCCESS [{bookmark, FB:kcwQ0IzUBAD/ShOD5//bfb72WymQ}]"
[ 12:01:19.756 DBG]	[bolt-9] C: "RESET"
[ 12:01:19.756 VRB]	[bolt-9] C: "00 02 B0 0F 00 00"
[ 12:01:19.757 DBG]	[bolt-9] S: "SUCCESS []"
[ 12:01:19.757 INF]	Query time: ReadNodeResult Stop: 1019


#
# Query
#
[ 12:01:22.128 INF]	Query time: Query:             MATCH (node)-[rel]->(other_node)            WHERE node.name = $node_name AND $node_label in labels(node) AND $relationship_name = type(rel) AND $other_node_label in labels(other_node)            RETURN other_node        
[ 12:01:22.128 INF]	Query time: ReadNodeResult Start: 0
[ 12:01:22.128 DBG]	[bolt-9] C: "BEGIN [{mode, r}, {db, neo4j}]"
[ 12:01:22.128 VRB]	[bolt-9] C: "00 13 B1 11 A2 84 6D 6F 64 65 81 72 82 64 62 85 6E 65 6F 34 6A 00 00"
[ 12:01:23.123 DBG]	[bolt-9] S: "SUCCESS []"
[ 12:01:23.124 DBG]	[bolt-9] C: "RUN `\r\n            MATCH (node)-[rel]->(other_node)\r\n            WHERE node.name = $node_name AND $node_label in labels(node) AND $relationship_name = type(rel) AND $other_node_label in labels(other_node)\r\n            RETURN other_node\r\n        `, [{node_name, Set VL Scan Param}, {node_label, Action}, {relationship_name, is_supported_by}, {other_node_label, SupportItem}] []"
[ 12:01:23.124 DBG]	[bolt-9] C: "PULL [{n, 1000}]"
[ 12:01:23.124 VRB]	[bolt-9] C: "01 66 B3 10 D0 F0 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 4D 41 54 43 48 20 28 6E 6F 64 65 29 2D 5B 72 65 6C 5D 2D 3E 28 6F 74 68 65 72 5F 6E 6F 64 65 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 57 48 45 52 45 20 6E 6F 64 65 2E 6E 61 6D 65 20 3D 20 24 6E 6F 64 65 5F 6E 61 6D 65 20 41 4E 44 20 24 6E 6F 64 65 5F 6C 61 62 65 6C 20 69 6E 20 6C 61 62 65 6C 73 28 6E 6F 64 65 29 20 41 4E 44 20 24 72 65 6C 61 74 69 6F 6E 73 68 69 70 5F 6E 61 6D 65 20 3D 20 74 79 70 65 28 72 65 6C 29 20 41 4E 44 20 24 6F 74 68 65 72 5F 6E 6F 64 65 5F 6C 61 62 65 6C 20 69 6E 20 6C 61 62 65 6C 73 28 6F 74 68 65 72 5F 6E 6F 64 65 29 0D 0A 20 20 20 20 20 20 20 20 20 20 20 20 52 45 54 55 52 4E 20 6F 74 68 65 72 5F 6E 6F 64 65 0D 0A 20 20 20 20 20 20 20 20 A4 89 6E 6F 64 65 5F 6E 61 6D 65 D0 11 53 65 74 20 56 4C 20 53 63 61 6E 20 50 61 72 61 6D 8A 6E 6F 64 65 5F 6C 61 62 65 6C 86 41 63 74 69 6F 6E D0 11 72 65 6C 61 74 69 6F 6E 73 68 69 70 5F 6E 61 6D 65 8F 69 73 5F 73 75 70 70 6F 72 74 65 64 5F 62 79 D0 10 6F 74 68 65 72 5F 6E 6F 64 65 5F 6C 61 62 65 6C 8B 53 75 70 70 6F 72 74 49 74 65 6D A0 00 00 00 08 B1 3F A1 81 6E C9 03 E8 00 00"
[ 12:01:24.124 DBG]	[bolt-9] S: "SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]"
[ 12:01:24.124 DBG]	[bolt-9] S: "RECORD [Neo4j.Driver.Internal.Types.Node]"
[ 12:01:24.124 DBG]	[bolt-9] S: "SUCCESS [{statuses, [[{gql_status, 00000}, {status_description, note: successful completion}]]}, {type, r}, {t_last, 0}, {db, neo4j}]"
[ 12:01:24.124 DBG]	[bolt-9] C: "COMMIT"
[ 12:01:24.124 VRB]	[bolt-9] C: "00 02 B0 12 00 00"
[ 12:01:24.125 DBG]	[bolt-9] S: "SUCCESS [{bookmark, FB:kcwQ0IzUBAD/ShOD5//bfb72WymQ}]"
[ 12:01:24.125 DBG]	[bolt-9] C: "RESET"
[ 12:01:24.126 VRB]	[bolt-9] C: "00 02 B0 0F 00 00"
[ 12:01:24.126 DBG]	[bolt-9] S: "SUCCESS []"
[ 12:01:24.126 INF]	Query time: ReadNodeResult Stop: 1997

In these logs you can actually see where the time is being used up.

In the last query, which takes 1997ms, it's interesting that there is almost exactly a 1 second gap between the adjacent logs at 12:01:22.128 and 12:01:23.123, and also between the logs at 12:01:23.124 and 12:01:24.124.

grant_lodge · September 16, 2024, 1:38pm

These are great; yes, you get a 1-second delay between your driver sending something and the server responding consistently. Unfortunately, it is going to be very hard to point out why.

Could you possibly try this for me?

    /// <summary>
    ///     Use this to understand the cost of network round trips.
    /// </summary>
    /// <returns></returns>
    public async Task<long> EstimateRoundtripLatency()
    {
        await driver.VerifyConnectivityAsync();
        await using var session = driver.AsyncSession();

        return await session.ExecuteReadAsync(async tx =>
        {
            for (var i = 0; i < 50; i++)
            {
                var warmup = await tx.RunAsync("RETURN 1");
                await warmup.ConsumeAsync();
            }

            var sw = Stopwatch.StartNew();
            for (var i = 0; i < 100; i++)
            {
                var c = await tx.RunAsync("RETURN 1");
                await c.ConsumeAsync();
            }

            return sw.ElapsedMilliseconds / 100;
        });
    }

paul.norman · September 16, 2024, 2:23pm

Thanks. Running that code a few time I get a latency of around 7ms.

grant_lodge · September 16, 2024, 2:26pm

That's certainly more in the ballpark for a local connection and the requisite
machinery to encode/decode messages.

So in your previous logs we have:

[ 12:01:13.492 DBG]	[bolt-9] C: "RUN ...."

The response to the RUN is

[ 12:01:14.493 DBG]	[bolt-9] S: "SUCCESS [{t_first, 1}, {fields, [other_node]}, {qid, 0}]"

In my test, we are effectively measuring that time, which was 7ms, but at times, it spikes to >100x that.
we know the server doesn't take long to process the request as t_first, 1

grant_lodge · September 16, 2024, 2:49pm

All I can think of is a resource issue in the way the neo4j instance is running.

Topic		Replies	Views
Wait for cypher query execution completion in Neo4j C# driver .NET cypher , import	12	510	February 14, 2023
Why is executing Cypher with Java so slow? Cypher cypher	5	323	September 21, 2023
Intermittent issue in query execution time Neo4j Graph Platform migrated	6	214	July 4, 2022
Execute a cypher query using .NET Driver Neo4j Graph Platform neo4j-driver , cypher	1	278	March 25, 2023
Node.js api driver takes too much of time to execute Neo4j Graph Platform migrated	0	147	November 21, 2022

Delay in executing query with ExecuteRead()

Related topics