query.log 条目的解释

本文旨在说明位于 $NEO4J_HOME/logs 目录下的 query.log 日志文件中各组件的含义。请注意，以下配置项需要在 conf/neo4j.conf 中取消注释，才能在查询日志中记录本篇文章所述的有用参数。

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>

以下示例查询在 movies 数据库上执行。

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

对应的查询日志（_query.log_）如下所示。

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; - {} - {}

在检查特定查询的参数时，一个明显但关键的注意点是只分析与该查询计划相关的条目，而不是对每个日志条目依次查看 cpu、时间、字节等信息。

以下对资源使用参数进行逐项拆解并给出说明，对应上述查询。

2017-11-23 12:44:56.973+0000: 日志时间戳。
INFO: 日志类别。
1550 ms: 查询执行过程中的累计实际墙钟时间总计。它等于计划时间 + CPU 时间 + 等待时间（见下文各项说明）+ 其他任何处理时间，例如获取执行线程的时间。该数值在每次 CPU 线程参与查询执行时都会累计。
规划（Planning）: 指 Cypher 引擎创建查询计划所耗费的时间。对于重复查询，计划可能会被缓存，因此这类查询的计划时间会短于首次出现的查询。在本例中，计划时间为 20 ms，占总执行时间 1550 ms 的一部分。
CPU 时间: 指执行查询的各线程实际占用 CPU 的时间。例如，一个查询在 08:00 提交，CPU 使用了 720 ms 后被切换到其他查询，随后在 100 ms 后再次得到 CPU 并使用 200 ms（因为客户端通过驱动请求加载更多结果），最终在 08:01:30 完成。整个持续时间为 1550 ms（包含两次往返的网络延迟），其中 CPU 时间为 720 ms + 200 ms = 920 ms。
等待: 查询在执行前因等待而消耗的时间（单位：ms），例如已有查询持有锁，需要等待该锁释放才能继续。在本例中，等待时间为 10 ms，占总执行时间 1550 ms 的一部分。

重要提示：客户端仅在记录缓冲区为空时向服务器请求数据（一次服务器往返可能返回多条记录），若客户端未及时读取，服务器将停止向输出缓冲区推送数据。因此，整体耗时在很大程度上取决于结果集的大小：若结果集较小且能在一次往返中返回，客户端会一次性收到全部结果，服务器也会在没有客户端影响的情况下完成处理；若结果集较大，客户端的处理时间会直接影响整体耗时，因为服务器只有在客户端再次请求时才会继续发送数据。

下面的简单测试展示了数据库与客户端之间的检索及往返时间是如何体现在 query.log 中的，我们可以尝试如下事务。

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();
}

这将在日志中产生如下条目。

… 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 - {} - {} …

而下面的代码

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();
}

则会产生此条目。

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 - {} - {}

请注意，这里唯一的区别是客户端处理时添加了延迟，从而在日志时间中体现出来。

因此根据上述情况，若总时间为 T，计划时间为 P，CPU 时间为 C，等待时间为 W，则

x = T - (C + W + P)

代表了将结果传输给客户端的时间（往返时间），或者等待客户端拉取结果的时间，亦或两者兼有。

13792 B: 已执行查询所分配的字节数。该数值表示查询生命周期内使用的堆内存量。日志中记录的是查询期间的累计使用量，即对于内存密集型或长时间运行的查询，此值可能会大于查询结束时实际占用的内存。
15 page hits: Page hit 表示结果是从页面缓存（pagecache）返回的，而非磁盘读取。本例中页面缓存被命中 15 次。
0 page faults: Page fault 表示查询结果数据不在 dbms.memory.pagecache 中，需要从文件系统读取。由于本例的查询结果全部来自前面提到的 15 次页面缓存命中，因此磁盘读取次数为 0。
bolt-session: 会话类型
bolt: browser ← → db 通信协议（用于本次查询）
neo4j: 进程 ID
neo4j-javascript/1.4.1: 驱动版本
client/127.0.0.1:52935: 查询客户端对外使用的 IP:端口
server/127.0.0.1:7687>: 服务器监听的 IP:端口
neo4j: 执行查询的用户名
match (n:Person {name:'Tom Hanks'})-[:ACTED_IN]→(n1:Movie)←[:DIRECTED]-(n2:Person {name:"Tom Hanks"}) return n1.title: 执行的查询语句。

最后的两个大括号 {} {} 分别对应查询 params 与 txMetaData。详情请参见 /docs/operations-manual/current/monitoring/logging/#query-log-config。

此页面有帮助吗？

知识库

query.log 条目的解释