0826-5.16.2-如何读取和分析Zookeeper Transaction Log 和Snapshots
0826-5.16.2-如何读取和分析Zookeeper Transaction Log 和Snapshots
作者：周鹏辉
1.文档编写目的
在进行故障排除时，我们可能希望深入了解二进制形式的Zookeeper事务日志和快照，以便从中获取更多可读信息。本文描述了如何通过读取Zookeeper事务日志和快照来排查zookeeper相关问题。
- 文档概述
1.Zookeeper事务日志和快照介绍
2.Zookeeper 事务日志和快照读取方法
3.总结
- 测试环境
1.CDH and CM version：CDH5.16.2 and CM5.16.2
2.集群启用:Kerbeos+OpenLDAP+Sentry
2.Zookeeper事务日志和快照介绍
Zookeeper 的数据先写入数据目录(CDH中默认/var/lib/zookeeper/version-2)的transaction log，当总量达到 10 万条记录的时候会自动做快照(snapshot)【1】。而且数据文件不是根据时间来保存的，没法设置数据保存日期。CDH 默认设置是每天清理这个目录, 并且只保留 5 个快照. 如果想需要保留更多的数据, 可以在CM -> Zookeeper -> Configuration -> Auto Purge Snapshots Retain Count【2】中设置保存更多的快照，不过这对于定位 Zookeeper 导致的问题可能帮助也不是很大, 因为快照生成的时间不一定是发生问题的时候. 所以如果想排查一些因为zookeeper引起的问题, 建议直接把当时的整个数据目录打包来分析。
【1】
【2】
3.Zookeeper 事务日志和快照读取方法
3.1 Zookeeper Transaction Log
1.把集群的/var/lib/zookeepr/vaersion-2目录拷贝到/tmp/zookeeper下进行分析
2.把解析Transaction Log 和Snapshots的jar包拷贝到/tmp/zookeepr，以下是在CDH5.16.2环境相关包的存放路径：
cp /opt/cloudera/parcels/CDH-5.16.2-1.cdh5.16.2.p0.8/jars/zookeeper-3.4.5-cdh5.16.2.jar /tmp/zookeeper/
cp /opt/cloudera/parcels/CDH-5.16.2-1.cdh5.16.2.p0.8/lib/zookeeper/lib/log4j-1.2.16.jar /tmp/zookeeper/
cp /opt/cloudera/parcels/CDH-5.16.2-1.cdh5.16.2.p0.8/lib/zookeeper/lib/slf4j-log4j12.jar /tmp/zookeeper/
cp /opt/cloudera/parcels/CDH-5.16.2-1.cdh5.16.2.p0.8/lib/zookeeper/lib/slf4j-log4j12-1.7.5.jar /tmp/zookeeper/
cp /opt/cloudera/parcels/CDH-5.16.2-1.cdh5.16.2.p0.8/lib/zookeeper/lib/slf4j-api-1.7.5.jar /tmp/zookeeper/
3.解析Zookeeper Transaction Log，比如我们想获取log.740003f499文件下面的更多信息，通过如下命令，我们可以看到此文件下面包含很多 session id号和对应的连接信息：
java -cp /tmp/zookeeper/zookeeper-3.4.5-cdh5.16.2.jar:/tmp/zookeeper/log4j-1.2.16.jar:/tmp/zookeeper/slf4j-log4j12-1.7.5.jar:/tmp/zookeeper/slf4j-api-1.7.5.jar org.apache.zookeeper.server.LogFormatter /tmp/zookeeper/version-2/log.740003f499
4. 如下命令输出此Zookeeper事务日志（log.740003f499）中记录了多少个事务，一共是39510个事务：
java -cp /tmp/zookeeper/zookeeper-3.4.5-cdh5.16.2.jar:/tmp/zookeeper/log4j-1.2.16.jar:/tmp/zookeeper/slf4j-log4j12-1.7.5.jar:/tmp/zookeeper/slf4j-api-1.7.5.jar org.apache.zookeeper.server.LogFormatter /tmp/zookeeper/version-2/log.740003f499 |grep session|wc -l
5. 如果想知道整个集群中哪个服务对Zookeeper的调用最多，其中一种方法是检查“ SetData”调用，比如：
java -cp /tmp/zookeeper/zookeeper-3.4.5-cdh5.16.2.jar:/tmp/zookeeper/log4j-1.2.16.jar:/tmp/zookeeper/slf4j-log4j12-1.7.5.jar:/tmp/zookeeper/slf4j-api-1.7.5.jar org.apache.zookeeper.server.LogFormatter /tmp/zookeeper/version-2/log.740003f499 |grep session|grep setData|awk '{print $12}'|awk -F/ '{print $3}'|sort|uniq -c|sort -n
3.2 Snapshots
1.获取snapshot.740003f497文件中的更多信息，使用如下命令：
java -cp /tmp/zookeeper/zookeeper-3.4.5-cdh5.16.2.jar:/tmp/zookeeper/log4j-1.2.16.jar:/tmp/zookeeper/slf4j-log4j12-1.7.5.jar:/tmp/zookeeper/slf4j-api-1.7.5.jar org.apache.zookeeper.server.SnapshotFormatter /tmp/zookeeper/version-2/snapshot.740003f497
在返回的信息中，我们可以看到各个seesion id对应的详细信息，比如cZxid、dataLength等。
2.想输出znodes列表，只需添加“ grep'/'”即可
java -cp /tmp/zookeeper/zookeeper-3.4.5-cdh5.16.2.jar:/tmp/zookeeper/log4j-1.2.16.jar:/tmp/zookeeper/slf4j-log4j12-1.7.5.jar:/tmp/zookeeper/slf4j-api-1.7.5.jar org.apache.zookeeper.server.SnapshotFormatter /tmp/zookeeper/version-2/snapshot.740003f497 | grep '/'
3.3 结合session ID和transaction Log查看数据长度
1.我们用zookeeper-client 产生一个znode /my_test为例进行说明。用zookeeper-client 产生一个znode如下：
zookeeper-client -server 192.168.0.181:2181
create /my_test my_data
把对应znode的数据目录/var/lib/zookeeper/version-2/ 拷贝到/tmp/zookeeper下进行分析，看到对应的transaction和snapshots文件
cp -r /var/lib/zookeeper/version-2/ .
2.使用如下命令读取最新的事务日志log.1c00000001，可以看到， 这个znode -- my_test被产生了，session id 为 0x3757f69404c0002， 并且它的数据“my_data" 紧随其后 -- “#6d795f64617461”
java -cp /tmp/zookeeper/zookeeper-3.4.5-cdh5.16.2.jar:/tmp/zookeeper/log4j-1.2.16.jar:/tmp/zookeeper/slf4j-log4j12-1.7.5.jar:/tmp/zookeeper/slf4j-api-1.7.5.jar org.apache.zookeeper.server.LogFormatter /tmp/zookeeper/version-2/log.1c00000001 > log.1c00000001.log
grep 'my_test' log.1c00000001.log
11/1/20 12:09:50 AM CST session 0x3757f69404c0002 cxid 0x1 zxid 0x1c00000022 create '/my_test,#6d795f64617461,v{s{31,s{'world,'anyone}}},F,395672
3.通过session id也可以查看到对应的znode信息
grep ' 0x3757f69404c0002' log.1c00000001.log
11/1/20 12:09:29 AM CST session 0x3757f69404c0002 cxid 0x0 zxid 0x1c00000011 createSession 30000
11/1/20 12:09:50 AM CST session 0x3757f69404c0002 cxid 0x1 zxid 0x1c00000022 create '/my_test,#6d795f64617461,v{s{31,s{'world,'anyone}}},F,395672
3.4 结合session ID和Snapshots查看数据长度
1.由于snapshot只是znode tree的一个快照， 所以我必须重启zookeeper 节点以便能产生一个新的snapshot文件来进行测试（因为snapshot文件只是一个当时znode tree的一个快照，如果当时没有执行快照 ，我们目前并没有手动触发产生一个snapshot的命令或者操作，所以未必能在transaction log中找到对应的id）。重启后产生了最新的snapshot文件snapshot.1d00000000。
2.执行如下命令读取最新snapshot.1d00000000
java -cp /tmp/zookeeper/zookeeper-3.4.5-cdh5.16.2.jar:/tmp/zookeeper/log4j-1.2.16.jar:/tmp/zookeeper/slf4j-log4j12-1.7.5.jar:/tmp/zookeeper/slf4j-api-1.7.5.jar org.apache.zookeeper.server.SnapshotFormatter /var/lib/zookeeper/version-2/snapshot.1d00000000 >snapshot.1d00000000.log
3.查看这个结果文件snapshot.1d00000000.log可以看到Create zxid = 0x00000700000032 与之前transaction log解析后的id一致， 数据字节长度是7， 也就是 ”my_data"的字节长度#6d795f64617461。
/my_test
cZxid = 0x00001c00000022
ctime = Sun Nov 01 00:09:50 CST 2020
mZxid = 0x00001c00000022
mtime = Sun Nov 01 00:09:50 CST 2020
pZxid = 0x00001c00000022
cversion = 0
dataVersion = 0
aclVersion = 0
ephemeralOwner = 0x00000000000000
dataLength = 7
3.5 结合zookeeper日志和数据长度排查负载高的应用
上面我们已经通过transaction和snapshot文件查看到了对应的seesion id和数据长度，我们想进一步确定是哪些应用在哪些节点发起的导致zookeeper负载高。我们可以结合transaction和snapshot和zookeeper 日志来分析问题（CDH中zookeeper 日志默认在/varlog/zookeeper下）。
1.先通过seesion id在zookeeper中找到对应的连接信息
grep '0x3757f69404c0002' /var/log/zookeeper/zookeeper-cmf-zookeeper-SERVER-cdh01.hadoop.com.log
2.看到此连接是从192.168.0.181:39352发起，我们就可以到对应的主机和端口查找到对应的连接信息。
lsof -i:39536
ps -aux | grep 18744
确实我们此时没有关闭刚刚创建znode /my_test的连接，已经对应上。
我们close刚刚创建znode /my_test的连接，
发现通过ip和端口已经查找不到对应的zookeeper连接
3.前面我们看到znode /my_test数据片段里面的dataLength =7表示此连接信息的数据长度为7byte，如果此数据长度特别大，容易导致zookeeper的负载，我们可以通过对应的seesion id到对应节点、端口查此链接对应的应用。当dataLengtg的值大于zookeeper的 jute.maxbuffer里面配置的数值，就会在zookeeper中出现Len error异常。从而容易导致需要使用到zookeeper的服务（比如YARN、Kafka、HBase等）出现故障。
4.问题总结
1.当在zookeeper中看到比如Len error 14307055的异常时候，我们可以通过结合zookeeper 日志（/var/log/zookeeper）和zookeeper的数据目录下的Transaction和Snapshots文件（/var/lib/zookeeper/version-2）。确定IP和端口确定是哪些应用导致zookeeper 负载高从而出现Len error异常；
2. zookeeper的数据长度dataLength如果大于zookeeper的jute.maxbuffer里面配置的数值，就会出现Len error异常。可以在Zookeeper日志中找到Len error最大的值, 如果小于 32MB, 那么统一建议把 jute.maxbuffer配置为32MB。如果此数据长度特别大，容易导致zookeeper的负载，我们可以通过对应的seesion id的IP和端口查此链接对应的应用。zookeeper中出现Len error异常,容易导致需要使用到zookeeper的服务（比如YARN、Kafka、HBase等）和zookeeper连接中断，从而出现异常。