Displaying Query CPU Utilization and Allocated Bytes in Query log
In Neo4j 3.3 and prior versions, when query logging is enabled with the following configuration parameters:
# Log executed queries that takes longer than the configured threshold. Enable by uncommenting this line.
dbms.logs.query.enabled=true
# If the execution of query takes more time than this threshold, the query is logged. If set to zero then all queries
# are logged.
dbms.logs.query.threshold=0
# The file size in bytes at which the query log will auto-rotate. If set to zero then no rotation will occur. Accepts a
# binary suffix "k", "m" or "g".
dbms.logs.query.rotation.size=20m
# Maximum number of history files for the query log.
dbms.logs.query.rotation.keep_number=7
# Include parameters for the executed queries being logged (this is enabled by default).
dbms.logs.query.parameter_logging_enabled=true
# Uncomment this line to include detailed time information for the executed queries being logged:
dbms.logs.query.time_logging_enabled=true
# Uncomment this line to include bytes allocated by the executed queries being logged:
dbms.logs.query.allocation_logging_enabled=true
# Uncomment this line to include page hits and page faults information for the executed queries being logged:
dbms.logs.query.page_logging_enabled=true
The log is written with output as shown below:
2018-10-29 21:07:37.219+0000 INFO 31 ms: (planning: 0, cpu: 29, waiting: 0) - 1969624 B - 0 page hits, 6 page faults - bolt-session bolt neo4j neo4j-javascript/1.5.3 client/127.0.0.1:65274 server/127.0.0.1:7687> neo4j - match (n:Person {name:"Keanu Reeves"})-[:ACTED_IN]->(m) return m - {} - {}
Note that it displays CPU - cpu: 29
and Allocated Bytes - 1969624 B
.
However, starting in Neo4j 3.4, using the above settings will not capture CPU and Allocated Bytes as the tracking is disabled by default.
The default behavior was changed for Neo4j 3.4 due to noticeable overhead when capturing CPU and Allocated Bytes to avoid resource contention.
Thus, even when query logging is enabled with dbms.logs.query.time_logging_enabled=true
and dbms.logs.query.allocation_logging_enabled=true
, the output in the query log will be missing CPU
and allocated bytes
as shown below:
2018-10-29 21:17:29.222+0000 INFO 30 ms: (planning: 0, waiting: 0) - 9 page hits, 0 page faults - bolt-session bolt neo4j neo4j-javascript/1.5.3 client/127.0.0.1:65383 server/127.0.0.1:7687> neo4j - match (n:Person {name:"Keanu Reeves"})-[:ACTED_IN]->(m) return m - {} - {}
In order to capture Query CPU utilization and allocated bytes, the following configuration parameters must be set to true
to override the default (false
).
dbms.track_query_allocation=true
dbms.track_query_cpu_time=true
With those settings, the query.log will display as shown below:
2018-10-29 21:21:04.446+0000 INFO 141 ms: (planning: 124, cpu: 139, waiting: 0) - 19388616 B - 10 page hits, 0 page faults - bolt-session bolt neo4j neo4j-javascript/1.6.1 client/127.0.0.1:65482 server/127.0.0.1:7687> neo4j - EXPLAIN match (n:Person {name:"Keanu Reeves"})-[:ACTED_IN]->(m) return m - {} - {}
Is this page helpful?