Neo4j知识库:初识Neo4j查询日志分析器

原文链接: https://medium.com/neo4j/meet-the-query-log-analyzer-30b3eb4b1d6

查询日志分析器是一个Neo4j桌面应用，用于帮助了解Neo4j企业版服务器查询日志文件。

query_log_1_0_7tFnDq1UGM38qN2t.png

当Neo4j突然变慢、或者查询效率过低、再或者查询负载过高时，这时最好的办法就是查看查询日志。而查询日志通过neo4j.conf文件配置的。

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
dbms.logs.query.threshold=100ms
dbms.logs.query.parameter_logging_enabled=true
dbms.logs.query.time_logging_enabled=true
dbms.logs.query.allocation_logging_enabled=true
dbms.logs.query.page_logging_enabled=true
dbms.track_query_cpu_time=true
dbms.track_query_allocation=true

一般情况下，设置一个阈值，当请求超过这个时间（示例是100ms,或者设置为0，代表所有请求）时，就会被记录下来。这也意味着，查询日志中记录的请求并不是服务器上的所有查询。但是这个工具仍然可以为你提供一个快速定位可能造成查询瓶颈的方向。
在后续的文章中我将会做详细的介绍。
当在开发项目时，最好要经常在开发服务器和测试服务器上分别去分析你的查询日志，以便发现问题。

工欲善，必先利其器。接下来，先看一下如何安装查询日志分析器。
下面是在Neo4j Desktop 1.1.10+安装查询日志分析器。

query_log_2_0_3nVuAjpMNxIiFhj6.png

query_log_3_0_Fqj8EFyTPRptm0F7.png

query_log_4_0_rqu8kMAuV8xvXaAR.png

下面我来重点解释一下查询日志分析器。

查询日志分析器

查询日志分析器需要一个query.log文件。你将文件上传到工具中，然后它就开始分析。分析文件完成后，将显示下信息：

query_log_5_0_v4X2wyOTzI-fPjlS.png

在上面的示例中的日志文件中，有17341行数据(一行一请求），有249个查询被发现。这些查询会显示在“Query Analysis"标签页中，你可以看到每个查询的统计数据。

查询分析

在Query Analysis标签页中，不同的查询是按 查询次数*平均时间 降序排列的。这样的排序可以将最耗时的查询排在最前面。

query_log_6_0_31_-x7LViVvbgRF4.png

在Query Analysis标签页中，有以下字段和功能：

• The Query(在AvgTime — Avg Mem值的下面）
  这是实际的查询语句

• Query Count
  日志文件中查询的次数，对于这个查询，还有下面一些功能可以使用:

  • Filter
    在Query Log标签内中，只显示这个查询的查询纪录。
  • Highlight
    在Query Log标签内中，高亮显示这个查询。当要看同时发到服务器的查询时，会更便于查看。
  • Timline
    实验性的！在Query Timeline标签中今次显示查询

• Avg Time, Min Tim, Max Time
  这里的时间是查询执行的累积时间（查询+执行计划+等待）。

• Avg CPU
  实际请求执行所占CPU时间。当详细时间日志被禁用时，这里显示0.
  设置项：

  dbms.logs.query.time_logging_enabled=true
  dbms.track_query_cpu_time=true
  

• Max Planning
  这是执行计划阶段所花费的最大时间，当鼠标悬停在该值上时，将会显示最小时间和平均时间。一般一个查询第一次被触发时，查询生成执行计划，然后这个执行计划被放到查询缓存中，当查询再次被执行时，生成执行计划的时间几乎为0。当执行计划被从缓存中移除时，下一个请求才会再次编译成执行计划。当Time logging被禁用时，此值显示0.设置项：

  dbms.logs.query.time_logging_enabled=true
  

• Avg Waiting
  查询被执行前的平均等待时间。这个等待可能是由于数据库负载过重造成，也可能是由于数据库锁造成的。当Time logging被禁用时，此值显示为0。设置项：

  dbms.logs.query.time_logging_enabled=true
  

• Cache Hits %
  代表这个请求的数据有百分之多少是从缓存中读取的。100%意味着所有数据都是从缓存中读取的。设置项：

  dbms.logs.query.page_logging_enabled=true
  

• Avg Mem
  代表这个请求分配了多少内存。注意，这是一个累积值，表明了查询的内存占用情况。设置项：

  dbms.logs.query.allocation_logging_enabled=true
  dbms.track_query_allocation=true
  

• Protocol + Clients
  在请求的上下文中你可以看到所使用的协议。其值有：

  • bolt
    一个blot客户端连到数据库。
  • http
    http客户端使用Neo4j的rest接口。（Neo4j老版本使用）
  • embedded
    来自数据库内部的调用，像存储过程或函数。

  此外，还有一个客户端列表显示，它列出了当前有多少个不同IP向Neo4j服务器发出请求。注意，blot驱动是使用连接池连接数据库的，所以，你能看到1个IP会有多个客户端。

查询日志

Query Log标签页，使用查询日志行作为了标头。更多的信息则需要拖动水平滚动条才能看到。在第一个Query Analysis标签页里选择一个查询点击“Highlight"，再点击Filter时，就会跳到这个页面，且只显示你选中的请求日志记录。这时，你可以拷贝这个标签页中的请求和参数去分析一个请求。

query_log_7_0_FSruFqbBqkPbD3HV.png

Query Timeline

Query Timeline是一个实验性的功能，它绘制出了每时间段（默认5分钟）查询总量和每秒种平均查询次数。它是基于日志文件中记录的时间，而不是查询开始时间。通过这张图，可以快速的了解到服务器是什么什么时候请求最多。

query_log_8_0_6Dr2-Ix-Ex7ZxKOw.png

相关链接

查询日志分析器的源码在github的 kvegter/query-analyzer-app(https://github.com/kvegter/query-analyzer-app) 上，可以在那里阅读文档和报bug.
如果你有任何关于查询性能的问题，可以前往Neo4j Users Slack或Neo4j Community上#help-cypher频道咨询。