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=<适当的值>

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

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

相应的查询日志在 [.file}_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 毫秒: 查询执行中花费的总累积挂钟时间。它是计划时间 + cpu + 等待（请参见下文对各个描述）+ 任何其他处理时间（例如获取执行线程所花费的时间）的总和。此数字是每次 cpu 线程处理执行查询时的累积值。
计划: 指的是 Cypher 引擎创建查询计划所花费的时间。对于重复查询，计划可能会被缓存，因此此类查询的计划时间将短于以前未计划的查询。在我们的示例中，这为 1550 毫秒的总执行时间贡献了 20 毫秒。
CPU 时间: 指的是执行查询的各个线程线程所花费的时间，例如，查询于 08:00 提交，它使用 CPU 720 毫秒，但随后 CPU 切换到另一个查询，因此第一个查询不再使用 CPU，但在 100 毫秒后，它再次获取/使用 cpu 200 毫秒（客户端通过驱动程序请求加载更多结果），然后查询在 08:01:30 完成，因此总持续时间为 1550 毫秒（包括 2 个往返行程的一些往返时间），但 CPU 为 720+200=920 毫秒。
等待: 查询在执行之前花费的等待时间（以毫秒为单位），例如，如果现有查询具有新查询必须等待释放的锁。在我们的示例中，这为 1550 毫秒的总执行时间贡献了 10 毫秒。

重要的是，请注意客户端仅在其记录缓冲区为空时从服务器请求数据（从服务器的一个往返行程最终可能会获得多个记录），并且如果客户端没有及时读取数据，服务器将停止将数据推送到输出缓冲区。因此，它基本上取决于结果集的大小，如果它相当小并且适合单个往返行程，则客户端将立即收到所有结果，并且服务器将在没有任何客户端影响的情况下完成处理。如果结果集很大，客户端的处理时间将影响总时间，因为它直接与何时从服务器请求新数据相关联。

一个简单的测试，它显示了 db 和客户端之间检索和往返时间如何在 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 毫秒：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 次页面命中: 页面命中表示结果是从页面缓存而不是磁盘返回的。在这种情况下，页面缓存命中了 15 次。
0 次页面错误: 页面错误表示查询结果数据不在 dbms.memory.pagecache 中，因此必须从文件系统中获取。在这种情况下，查询结果完全从上面提到的 8 次页面缓存命中返回，因此不需要对磁盘进行 0 次命中。
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 文件条目的解释