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>

以下示例查询在电影数据库上执行

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 线程每次执行查询时的累积值。
计划时间: 指 Cypher 引擎创建查询计划所花费的时间。对于重复的查询，计划可能会被缓存，因此此类查询的计划时间将比先前未计划的查询短。在我们的示例中，这为总执行时间 1550 毫秒贡献了 20 毫秒。
CPU 时间: 指执行查询的单个线程所花费的时间，例如，一个查询在 08:00 提交，使用了 720 毫秒 CPU，然后 CPU 切换到另一个查询，因此第一个查询不再使用 CPU，但在 100 毫秒后，它再次获得/使用 CPU 200 毫秒（客户端通过驱动程序请求加载更多结果），然后在 08:01:30 完成查询，因此总持续时间为 1550 毫秒（包括 2 次往返的一些往返时间），但 CPU 时间是 720+200=920 毫秒。
等待时间: 查询在执行前花费的等待时间（以毫秒为单位），例如，如果现有查询持有锁，新查询必须等待该锁释放。在我们的示例中，这为总执行时间 1550 毫秒贡献了 10 毫秒。

重要的是要注意，客户端仅在其记录缓冲区为空时才从服务器请求数据（从服务器一次往返可能会返回多条记录），如果客户端不及时读取数据，服务器会停止将数据推送到传出缓冲区。因此，这基本上取决于结果集的大小，如果它很小并且可以放入一次往返中，客户端将一次性接收所有结果，并且服务器将完成处理而不会受到任何客户端影响。如果结果集很大，客户端处理时间将影响总时间，因为它直接关联到何时从服务器请求新数据。

一个简单的测试，展示了数据库与客户端之间的检索时间和往返时间如何在 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: 为记录的已执行查询分配的字节数。这是查询生命周期内使用的 HEAP 内存量。日志记录的数字是查询持续时间的累积值，即对于内存密集型或长时间运行的查询，该值可能大于当前内存分配量。
15 page hits: 页面命中意味着结果是从页缓存（pagecache）而不是磁盘返回的。在这种情况下，页缓存被命中 15 次。
0 page faults: 页面错误（page fault）意味着查询结果数据不在 dbms.memory.pagecache 中，因此必须从文件系统获取。在这种情况下，查询结果完全从上面提到的 15 次页缓存命中返回，因此不需要访问磁盘。
bolt-session: 会话类型
bolt: 查询使用的浏览器 ← → 数据库通信协议
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`。参见 https://neo4j.ac.cn/docs/operations-manual/current/monitoring/logging/#query-log-config。

本页有帮助吗？

知识库

query.log 条目说明