知识库

解析 JSON 查询日志

有时我们需要检查查询日志,以找出运行时间最长的查询和/或其他问题查询,例如缺少索引的查询或未正确使用参数的查询。

这可以通过解析并排序查询日志的属性来实现;在使用 CSV 格式的查询日志时通常比较直接,但在像 Aura 这样的 JSON 格式日志中,我们可以使用下面的 jq 命令按需获取运行时间最长的查询。

Aura

cat query.log.json |
	jq '. | sort_by(.jsonPayload.elapsedTimeMs) | reverse ' |
	jq '.[] | select(.jsonPayload.event == "success") |
	{ timestamp: .timestamp,
		severity:  .severity,
		event: .jsonPayload.event,
		id: .jsonPayload.id,
		elapsedTimeMs: .jsonPayload.elapsedTimeMs,
		allocatedBytes: .jsonPayload.allocatedBytes,
		pageFaults: .jsonPayload.pageFaults,
		pageHits: .jsonPayload.pageHits,
		waiting: .jsonPayload.waiting,
		planning: .jsonPayload.planning,
		runtime: .jsonPayload.runtime,
		username: .jsonPayload.username,
		query: .jsonPayload.query } |   join(" | ")  '

这将产生以下按行格式化的输出

"2022-10-20T04:51:22.485Z | INFO | success | 13452855 | 1792 | 248 | 0 | 905357 | 0 | 0 | slotted | neo4j | MATCH (n) return n"

本地部署

另一方面,在非 Aura 环境中,我们需要使用下面版本的 jq 脚本,以适配下方所示的略有不同的格式。

{
  "time": "2022-10-23 00:09:37.772+0000",
  "level": "INFO",
  "event": "success",
  "type": "query",
  "elapsedTimeMs": 2,
  "planning": 0,
  "cpu": 2,
  "waiting": 0,
  "allocatedBytes": 176,
  "pageHits": 4,
  "pageFaults": 0,
  "source": "bolt-session\tbolt\tneo4j-browser/v5.0.0\t\tclient/127.0.0.1:49863\tserver/127.0.0.1:11004>",
  "database": "neo4j",
  "username": "neo4j",
  "executingUser": "neo4j",
  "authenticatedUser": "neo4j",
  "query": "MATCH (tom {name: \"Tom Hanks\"}) RETURN tom",
  "queryParameters": "{}",
  "runtime": "pipelined",
  "annotationData": "{type: 'user-direct', app: 'neo4j-browser_v5.0.0'}"
}

因此我们的 jq 命令将如下所示

cat query.log.json |
jq  -s -c 'sort_by(.elapsedTimeMs) | reverse | .[]' |
jq '. | select( .event == "success") |
	{ time: .time,
		level:  .level,
		event: .event,
		type: .type,
		id: .id,
		elapsedTimeMs: .elapsedTimeMs,
		planning: .planning,
		cpu: .cpu,
		waiting: .waiting,
		allocatedBytes: .allocatedBytes,
		pageHits: .pageHits,
		pageFaults: .pageFaults,
		source: .source,
		username: .username,
		executingUser: .executingUser,
		authenticatedUser: .authenticatedUser,
		authenticatedUser: .authenticatedUser,
		runtime: .runtime,
		query: .query,
		queryParameters: .queryParameters }  | join(" | ")  '

输出如下所示

"2022-10-23 00:09:16.352+0000 | INFO | success | query |  | 95 | 62 | 91 | 0 | 0 | 9 | 0 | bolt-session\tbolt\tneo4j-browser/v5.0.0\t\tclient/127.0.0.1:49863\tserver/127.0.0.1:11004> | neo4j | neo4j | neo4j | pipelined | EXPLAIN MATCH (nineties:Movie) WHERE nineties.released >= 1990 AND nineties.released < 2000 RETURN nineties.title | {}"
"2022-10-23 00:09:31.071+0000 | INFO | success | query |  | 27 | 26 | 26 | 0 | 0 | 1 | 0 | bolt-session\tbolt\tneo4j-browser/v5.0.0\t\tclient/127.0.0.1:49863\tserver/127.0.0.1:11004> | neo4j | neo4j | neo4j | pipelined | EXPLAIN MATCH (tom {name: \"Tom Hanks\"}) RETURN tom | {}"

最后需要说明的是,上述命令在运行时会占用大量内存。例如,对一个 7GB(未压缩)且包含约 400 万条记录的文件,内存使用约 60GB,耗时约 10 分钟即可完成。

© . This site is unofficial and not affiliated with Neo4j, Inc.