Knowledge Base

An explanation of entries in query.log

This document aims to provide descriptions of components of the query.log logfile located at $NEO4J_HOME/logs. Note that the following configs in conf/neo4j.conf need to be uncommented for the query log to include mentions of the useful parameters described in this article:

  • dbms.logs.query.enabled=true

  • dbms.logs.query.allocation_logging_enabled=true

  • dbms.logs.query.page_logging_enabled=true

  • dbms.logs.query.parameter_logging_enabled=true

  • dbms.logs.query.time_logging_enabled=true

  • dbms.logs.query.threshold=<appropriate value>

The following sample query was executed on the movies database:

match (n:Person {name:'Tom Hanks'})-[:ACTED_IN]->(n1:Movie)<-[:DIRECTED]-(n2:Person {name:"Tom Hanks"}) return n1.title

The corresponding query log in [.file}_query.log_ is shown below:

2017-11-23 12:44:56.973+0000 INFO  1550 ms: (planning: 20, cpu: 920, waiting: 10) - 13792 B - 15 page hits, 0 page faults - bolt-session	bolt	neo4j	neo4j-javascript/1.4.1		client/127.0.0.1:58189	server/127.0.0.1:7687>	neo4j - match (n:Person {name:'Tom Hanks'})-[:ACTED_IN]->(n1:Movie)<-[:DIRECTED]-(n2:Person {name:"Tom Hanks"}) return n1.title; - {} - {}

An obvious but essential point of note when examining parameters of a particular query, is to ensure to analyse only the entries relevant to that to the particular query plan, as opposed to e.g. cpu, time, bytes etc. for each log entry in sequence.

Following is a breakdown of resource usage parameters, with descriptions, corresponding to the above qurey:

2017-11-23 12:44:56.973+0000

log timestamp.

INFO

log category.

1550 ms

Total elapsed cumulative wall time spent in query execution. It is the total of planning time + cpu + waiting (see below for individual descriptions) + any other processing time e.g. taken to acquire execution threads. This figure is cumulative for every time a cpu thread works on executing the query.

Planning

refers to the time taken by the cypher engine to create a query plan. Plans may be cached for repetitive queries and therefore planning times for such queries will be shorter than those for previously unplanned ones. In our example, this contributed 20ms to the total execution time 1550ms.

CPU time

refers to the time taken by individual threads thread executing the query, e.g. a query is submitted at 08:00, it uses CPU for 720ms but then the CPU swaps out to another query, so the first query is no longer using the CPU, but then after 100ms it then gets/uses the cpu again for 200ms, (more results to be loaded, requested by the client via the driver), then the query completes at 08:01:30, so the total duration is 1550ms (includes some round-trip time for 2 round-trips) but CPU is 720+200=920ms.

Waiting

time a query spent waiting prior to execution (in ms) e.g. if an existing query has a lock which the new query must wait on to release. In our example, this contributed 10ms to the total execution time 1550ms.

Importantly, note that the client requests data from the server only when it’s record buffer is empty (one round-trip from the server may end-up with several records), and server stops pushing data into outgoing buffers if client doesn’t read them in a timely fashion. So, it basically depends on the size of the result set, if it is fairly small and will fit in a single round-trip - the client will receive all the results at once and server would have finish processing without any client-side effect. If the result set is large, client side processing time will affect the overall time as it is directly connected to when new data is requested from the server.

A simple test which shows how retrieval and roud-trip times between db and client are reflected in query.log, we can try the following transaction:

public void iterateWithoutDelay() throws Exception {
  final Session session = driver.session(AccessMode.READ);
  Transaction tx = session.beginTransaction();
  final long startTime = System.currentTimeMillis();
  final StatementResult result = tx.run("MATCH (n) return n");
  while (result.hasNext()) {
    result.next();
  }
  tx.close();
}

results in this entry in the log:

…​ INFO 3896 ms: bolt-session bolt null neo4j-java/dev client/127.0.0.1:52935 server/127.0.0.1:7687> - MATCH (n) return n - {} - {} …​

While this code
public void iterateWithDelay() throws Exception {
  final Session session = driver.session(AccessMode.READ);
  Transaction tx = session.beginTransaction();
  final long startTime = System.currentTimeMillis();
  final StatementResult result = tx.run("MATCH (n) return n");
  while (result.hasNext()) {
    result.next();
    Thread.sleep(5);
  }
  tx.close();
}

results in this entry:

INFO 135171 ms: bolt-session bolt null neo4j-java/dev client/127.0.0.1:52935 server/127.0.0.1:7687> - MATCH (n) return n - {} - {}

Notice that the only difference here is the delay added to the client processing hence showing it contributing to logged times.

So based on this, if total time is T, planning time P, CPU time C, waiting time W then:

x = T - (C + W + P)

represents the time spent either transferring results to the client (round-trip time), or time spent waiting for the client to pull results, or both.

13792 B

The allocated bytes for the executed queries being logged. This is the amount of HEAP memory used during the life of the query. The logged number is cumulative over the duration of the query, i.e. for memory intense or long-running queries the value may be larger than the current memory allocation.

15 page hits

Page hit means the result was returned from pagecahce as opposed to disk. In this case, pagecache was hit 15 times.

0 page faults

Page fault means that the query result data wasnt in the dbms.memory.pagecache and therefore had to be fetched from the file system. In this case, query results were returned entirely from the 8 pagecache hits mentioned above therefore there were 0 hits on the disk required.

bolt-session

session type

bolt

browser ← → db communication protocol used by the query

neo4j

process id

neo4j-javascript/1.4.1

driver version

client/127.0.0.1:52935

query client outbound IP:port used

server/127.0.0.1:7687>

server listening IP:port used

neo4j

username of the query executioner

match (n:Person {name:'Tom Hanks'})-[:ACTED_IN]→(n1:Movie)←[:DIRECTED]-(n2:Person {name:"Tom Hanks"}) return n1.title

the executed query.

The last two parenthesis {} {} are for query params and txMetaData. See https://neo4j.com/docs/operations-manual/current/monitoring/logging/#query-log-config.