如何读取和分析Zookeeper Transaction Log 和Snapshots

发布日期:2020-12-25 14:38
微信图片_20201225123947
在进行故障排除时,我们可能希望深入了解二进制形式的Zookeeper事务日志和快照,以便从中获取更多可读信息。本文描述了如何通过读取Zookeeper事务日志和快照来排查zookeeper相关问题。
  • 文档概述
1.Zookeeper事务日志和快照介绍
2.Zookeeper 事务日志和快照读取方法
3.总结
  • 测试环境
1.CDH and CM version:CDH5.16.2 and CM5.16.2
2.集群启用:Kerbeos+OpenLDAP+Sentry

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】


Zookeeper 事务日志和快照读取方法:
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



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 '/'


结合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

结合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

结合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等)出现故障。


问题总结
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连接中断,从而出现异常。
分享到:
推荐精彩博文