Production Zookeeper Issue 2: zxid lower 32 bits have rolled over

现象:

应用在某个时间点有5分钟左右的不可用造成了大量业务zookeeper操作失败。

原因分析:

首先观察指标:

检查epoch指标可以确定是否发生了选举:可以看到epoch从91改成了92

检查zxid指标,可以看出发生了溢出: 

根据以上两个指标,基本上可以锁定发生了zxid溢出导致的leader重新选举,而选举时,集群不可用,这点可以参考zk的server日志可以核实。

2023-08-27 17:28:55,806 [myid:37] - INFO [nioEventLoopGroup-7-10:NettyServerCnxn@525] - Closing connection to /10.24.15.252:47146 because the server is not ready
2023-08-27 17:28:55,834 [myid:37] - INFO [nioEventLoopGroup-7-13:NettyServerCnxn@525] - Closing connection to /10.14.12.141:44252 because the server is not ready

那么zxid是什么,为什么它会溢出?溢出后的后果?这里可以简单分析下,在分析之前,登录服务器确认了下确实是zxid溢出问题:

 Shutdown called. For the reason zxid lower 32 bits have rolled over, forcing re-election, and therefore new epoch start 

确认问题无误后,可以解析下这个zxid功能:

为了保证事务的顺序一致性,Zookeeper 采用了递增的事务ID号(即zxid)来标识事务,所有的操作( proposal )都会在被提出时加上zxid,zxid是一个64位的数字:高32位是epoch用来标识leader关系是否发生变化,每当有新的leader 被选举出来,都会有一个新的epoch,标识当前属于多少代领导时期。例如高位为92,则可以简单理解为第92代“皇帝”。这个可以像前文提及的通过JMX的指标epoch变化来看是否发生了选举。后32位可以理解为在这个朝代发生的事务。事务这里其实就是改变zk的行为,所以像读取操作并不是一种事务。

当改变zk行为的请求过来时,zk都是会让Leader来处理,而Leader处理的第一件事就是将这个请求(request)转化为一个“事务”来做。这种转化做的非常重要的一件事就是产生一个Id给通过设置TxnHeader的方式给它(request)(注意下:Follower之类的非leader不会产生zxid)。这样为后续事务的处理的有序性都提供了保障。可以参考下面代码看下请求的zxid设置过程:

org.apache.zookeeper.server.PrepRequestProcessor#pRequestHelper:
private void pRequestHelper(Request request) {
    try {
        switch (request.type) {
        case OpCode.createContainer:
        case OpCode.create:
        case OpCode.create2:
            CreateRequest create2Request = request.readRequestRecord(CreateRequest::new);
            pRequest2Txn(request.type, zks.getNextZxid(), request, create2Request);
            break;

其中zks.getNextZxid()即为取递增的Id:
org.apache.zookeeper.server.ZooKeeperServer#getNextZxid:
long getNextZxid() {
    return hzxid.incrementAndGet();
}

这个id本身是递增的,所以一定会溢出,当溢出后,在leader处理到会发生溢出的请求时会遇到抛出异常

org.apache.zookeeper.server.quorum.Leader#propose:
public Proposal propose(Request request) throws XidRolloverException {
 
    if ((request.zxid & 0xffffffffL) == 0xffffffffL) {
        String msg = "zxid lower 32 bits have rolled over, forcing re-election, and therefore new epoch start";
        shutdown(msg);
        throw new XidRolloverException(msg);
    }

而一旦抛出异常,最后代码的处理是关闭leader,然后触发重新选举。从而新的一轮选举就此发生。在选举成功这段期间,服务并不可用,最终成功时会输出下面这样的日志:


2023-08-27 17:34:23,137 [myid:37] - INFO [QuorumPeer[myid=37](plain=[0:0:0:0:0:0:0:0]:2181)(secure=[0:0:0:0:0:0:0:0]:2281):ZooKeeperServer@361] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 clientPortListenBacklog -1 datadir /data/zooke
eper/version-2 snapdir /data/zookeeper/version-2
2023-08-27 17:34:23,138 [myid:37] - INFO [QuorumPeer[myid=37](plain=[0:0:0:0:0:0:0:0]:2181)(secure=[0:0:0:0:0:0:0:0]:2281):Leader@584] - LEADING - LEADER ELECTION TOOK - 342465 MS

通过这个日志可以看出选举花了多久,例如上面花了约6分钟,这也意味着服务不可用达6分钟。

问题解决:

通过上面的分析可知,zk的zxid是必然发生的问题,那么遇到这个问题的时候,我们可以先做两个方面的评估:

(1)每次影响时间是多少,上面已经统计这点可以通过日志直接获取这样的数据;本应用约为6分钟。

(2)发生的频率是多少,通过原理分析,很容易知道,这取决于业务的请求量大小。例如对于本应用,可以通过查询最近2次发生的日志的时间来推断,如果日志没有保存很久,也可以通过zxid指标的增长速度来估算。


例如取1周的变化数据(不考虑业务的月/季度变化):

time: 2023-09-01 03:00:00 zxid {host: ip-10-0-4-123}: 280105949.2
time: 2023-09-08 00:00:00 zxid {host: ip-10-0-4-123}: 692368820.8
由上述数据可以:一周4.2亿,每天0.6亿。

以zxid最多承接多少id,除以每天即为粗略的溢出间隔4294967296 ÷ 60000000 = 约71(天)

综合评估下,就是每2-3月会发生一次,每次影响约5-6分钟。

那么如何解决或者说缓和这个问题呢,无非以下思路:

(1)延缓发生的时间,例如可以减少必须要的业务请求量。再则网上也有人做过一种改进,修改zookeeper的代码重新打包,具体修改是将64位的后32位Id调整为更多位数,可行性是基于选举是小概率事件,不需要前32位那么多。不过个人认为,这种修改对以后的升级维护很不友好。

(2)减少影响的时间,也就是考虑如何减少选举的时间,例如对本应用而言,其实是7个Node,都是Follower角色,是不是可以将少许Follower转化为Observer来启动,这样参与选举的节点就少了,选举自然也会快些。这里还需要验证下。

当然,除了直接的方法外,还有一些其他间接的方法,例如减少对zk的依赖或者换其他存储,这里不做过多展开。

题外:

这里再补充一些这个问题定位时的弯路分析,在开始遇到这个问题时,实际上通过流量的变化(org.apache.zookeeper.server.ServerStats#packetsReceived对应的JMX指标)发现的,例如下图:

当时可视化系统也没有展示上文描述的2个重要指标,所以当时的第一感觉肯定是服务器发生了重启,因为这个统计指标表明的是zk接受到的包的总和,正常都是一直持续增加的,忽然归0,就很容易觉得是重启了。但是通过linux的last命令查看发生问题的世间点并没有人来操作,系统的日志也没有提示任何重启:

//last执行效果:

[root@ip-10-0-0-247 user]# last |more
user pts/1 38.99.100.2 Mon Sep 11 01:06 still logged in
user pts/1 38.99.100.2 Fri Sep 8 06:15 - 10:25 (04:09)
stroller. pts/3 38.99.100.2 Thu Sep 7 02:24 - 06:40 (04:16)

后来经过源码研究发现,其实这个指标归0除了zk重启外,还有2种情况,这2种情况不会重启zk:

(1) 四字命令srst的执行:

public static class StatResetCommand extends GetCommand {

    public StatResetCommand() {
        super(Arrays.asList("stat_reset", "srst"));
    }

    @Override
    public CommandResponse runGet(ZooKeeperServer zkServer, Map<String, String> kwargs) {
        CommandResponse response = initializeResponse();
        zkServer.serverStats().reset();
        return response;
    }

}

(2)遇到zxid溢出等错误,导致shutdown并引发重新选举,就本案例而言,这个时候,相当于把leader给先关闭了,然后重新获取一个新的角色提供服务(LeaderZooKeeperServer/FollowerZooKeeperServer等)。这个新服务对像的指标数据存储对象(父类对象ZooKeeperServer#serverStats)就是初始化状态。总体来说:这里就等于在不关闭java进程的情况下做了“重启”。

这点也可以从前面贴出的两条日志得到严重,先shutdown,后重新创建了zk server:

//新的server:
2023-08-27 17:34:23,137 [myid:37] - INFO [QuorumPeer[myid=37](plain=[0:0:0:0:0:0:0:0]:2181)(secure=[0:0:0:0:0:0:0:0]:2281):ZooKeeperServer@361] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 clientPortListenBacklog -1 datadir /data/zookeeper/version-2 snapdir /data/zookeeper/version-2

另外,ServerStats#packetsReceived很可能被理解为数据包个数,从而发生这样的误会:例如,一个请求可能拆分成两个数据包,那么packetsReceived是2,实际上,packetsReceived可以理解为请求数。参考代码 NettyServerCnxn#receiveMessage:

receiveMessage中的关键逻辑:
if (bb.remaining() == 0) { //请求的数据读完整时(读取了len长度)符合条件。
    bb.flip();
   //调用metrics
   packetReceived(4 + bb.remaining());
   //转化为请求然后进行后续处理
   RequestHeader h = new RequestHeader();
   ByteBufferInputStream.byteBuffer2Record(bb, h);
   RequestRecord request = RequestRecord.fromBytes(bb.slice());
   zks.processPacket(this, h, request);
     
}

//metris调用方法
protected void packetReceived(long bytes) {
    ServerStats serverStats = serverStats();
    if (serverStats != null) {
         serverStats().incrementPacketsReceived();
      //调用packetsReceived.incrementAndGet(),对应packetsReceived
     }
ServerMetrics.getMetrics().BYTES_RECEIVED_COUNT.add(bytes);
      //对应bytes_received_count
}

 

所以虽然查看问题,绕了弯路,但是也可以学习到更多知识。对出现问题的时如何看懂各种数据有了很多帮忙。

 

 

Production Zookeeper Issue 1: Len error cause outage

问题现象

产线服务器Outage若干分钟,且重启后无法启动,检查错误日志显示如下:

2023-06-15 03:35:54.556[][ERROR][nioEventLoopGroup-16-1][ClientCnxnSocketNetty:522]Unexpected throwable
java.io.IOException: Packet len 1048603 is out of range!

通过日志可知这是由Zookeeper客户端抛出的“接受包大小”超过阈值导致,  后续分析可知当遇到这种错误时,连接会断开错误。而当Zookeeper连接被断开后,服务无法正常工作,重启又无法启动。

问题原因

根据错误提示地方,我们可以找到出错的代码如下,

/**
 * This buffer is only used to read the length of the incoming message.
 */
protected final ByteBuffer lenBuffer = ByteBuffer.allocateDirect(4);

/**
 * After the length is read, a new incomingBuffer is allocated in
 * readLength() to receive the full message.
 */
protected ByteBuffer incomingBuffer = lenBuffer;


void readLength() throws IOException {
  int len = incomingBuffer.getInt();
  if (len < 0 || len > packetLen) {
   throw new IOException("Packet len " + len + " is out of range!");
  }
  incomingBuffer = ByteBuffer.allocate(len);
}

分析代码可知,ZK的消息格式是使用基于自定义TCP定义自己的PDU,具体而言,这种PDU采用了基于固定4字节字段存取报文长度分帧的方式。所以在接受消息时,在继续读取具体内容之前,如果发现长度已经不符合预期,就可以直接做一些特殊的处理,例如抛出异常(此处是IOException),抛出异常后,Zookeeper Client针对这种异常采取了断开连接的方式来保护自身。

@Override
public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) {
    LOG.error("Unexpected throwable", cause);
    cleanup();
}

private void cleanup() {
    if (!channelClosed.compareAndSet(false, true)) {
        return;
    }
    disconnected.set(true);
    onClosing();
}

那么,什么情况下会出现读取的响应包的Size超过最大允许的值,最大的允许值又是多少?很明显,只要有响应的请求都可能会触发这种情况,另外这个最大允许的值默认是1M,可以通过配置参数来调整。

public static final int CLIENT_MAX_PACKET_LENGTH_DEFAULT = 0xfffff; /* 1 MB */
private int packetLen = ZKClientConfig.CLIENT_MAX_PACKET_LENGTH_DEFAULT;

//org.apache.zookeeper.ClientCnxnSocket#initProperties
//初始化时,会根据配置("jute.maxbuffer")来修改生效:
packetLen = clientConfig.getInt(
        ZKConfig.JUTE_MAXBUFFER,
        ZKClientConfig.CLIENT_MAX_PACKET_LENGTH_DEFAULT);

当一个系统使用Zookeeper的操作很多时,且又是产线时,找出这样的请求并不方便,实际上,网上搜索这种错误,大多也都会提醒是某个node大了,然后访问这个node引发的错误,实际上这个是一个巨大的误导,因为在大多情况下,客户端保护了最大size数据包的控制,Zookeeper的服务端肯定也有这样的保护,那如果一个大的node都写不进去,何来去读这样的Node的情况发生。这里我们不妨验证下服务器端对Size的保护:

org.apache.zookeeper.server.NettyServerCnxn#receiveMessage
if (len < 0 || len > BinaryInputArchive.maxBuffer) {
    throw new IOException("Len error " + len);
}

public static final int maxBuffer = Integer.getInteger("jute.maxbuffer", 0xfffff);

可以看出,代码类似,基本逻辑也是类似,最终也是会断掉连接,测试可以得出日志再次验证:


Closing connection to /38.99.100.2:36532
java.io.IOException: Len error 1441850

综合以上分析,可以看出Node本身大小绝对不应该重点排除的方向,除非服务器端设置的jute.maxbuffer和客户端设置的不同,让服务端接受了大数据的写,然后读又读不出来,这种情况确实存在,毕竟属于人为配置,但是作为本应用,排查所有配置可以轻松排除这种情况。

那么还有什么情况,可以引发一个大响应,其实很容易想到的是一个情况:一个节点,下面含有太多子节点,那么这个时候去getChildren获取所有子节点时,返回的所有子节点的名称列表可能会超过限制的1M. 这里可以直接模仿产线数据进行测试,例如创建一个节点,然后创建很多名称为随机UUID的子节点,子节点内容不限制。

考虑UUID为36字节,结合Json格式为“”包围字符串,我们可以按38字节进行估算,看起来虽然很小的字节数,但是只要计算下就会发现如果当Node超过2万多时,此时光返回Node名称的列表就已经超过了1M限制。

复盘当前出现问题的实际,当天子节点因业务拓展新的环境,一次性创建了上前Node,刚好超过了所能容纳的Node数量。所以引发问题。而重启后,仍然不能解决问题。实际上,Zookeeper并没有限制你去新建2万或者3万甚至更多节点,而是你可以去建,也可以去getData但是你不要去做getChildren,因为这样的返回的子节点名称列表的Size就会超过数据包的最大读取Size。

有了问题的思路,也模拟出怀疑的对象,那么最后一步是找出代码中,会执行getChildren的地方,实际上,最后发现,代码中并没有任何代码调用过这个方法,但是都是通过TreeCache来访问。这里不详细介绍TreeCache的功能,可以直接使用下面的代码使用它来复现问题:

String ZOOKEEPER_CONNECTION_STRING = "10.30.0.13:2181"; // ZooKeeper服务器地址

CuratorFramework client = CuratorFrameworkFactory.newClient(
        ZOOKEEPER_CONNECTION_STRING,
        new ExponentialBackoffRetry(1000, 3));

client.start();

TreeCache treeCache = new TreeCache(client, "/test/pathWithHugeChild");
treeCache.start();

TreeCache看起来使用很简单方便,但是实际上,它消费了很大资源来维持本地缓存和Zookeeper数据的同步,而且它在启动时,会访问缓存的path,然后遍历所有的节点,并获取所有的数据。关键的错误就发生在遍历所有的子节点:

//org.apache.curator.framework.recipes.cache.TreeCache.TreeNode#doRefreshChildren
private void doRefreshChildren() throws Exception
{
    if ( treeState.get() == TreeState.STARTED )
    {
        maybeWatch(client.getChildren()).forPath(path);
    }
}

问题解决方案

分析完问题的原因,可以讨论下如何解决这个问题,首先问题出现的根本还是在于对Zookeeper的误用:完全当数据库来使用存取了大量数据到一个节点下,且使用了TreeCache,而TreeCache存在一次请求节点的所有子节点名称(实际)的操作。这个时候就会引发问题。所以不考虑使用其他的存储方案,如果坚持使用Zookeeper, 这里可以提供两种方式来修复问题:

(1)修改“jute.maxbuffer”到更大的值,这种方案只是一个临时方案,数据继续增长后还是会遇到问题,只是时间问题,不过临时使用的话,也能凑效,注意服务端和客户端最好同时修改,以避免以后挖坑给后人。

(2)避免一个节点下存在太多子节点的设计,例如可以采用分库分表的方式进行,例如根据不同特性建立二级子节点,例如从path/node1…..nodeN改成path/subPath/node1…..nodeN。然后对于针对二级子节点,分别采用TreeCache。如果没有分布均匀的业务特性,可以直接建立1….N个folder,然后业务关键字取余的方式来分着放:

//二级Folder名称:每个Folder创建一个TreeCache.
private String getTreeCachePathByKey(String key){
    final int index = Math.abs(key.hashCode()) % shardNumber;
    return String.format("%s/%d", STORE, index);
}

这种方式会额外带来一个好处,例如新建子节点时,原来会触发父节点的path的getChildren,获取到了所有的子节点的名称列表,而修改后,只会触发二级父节点path/subPath的getChildren,返回的子节点名称列表要小很多(取决于建立多少个subPath)。不过要注意的是,每常见一个TreeCache会创建一个线程来完成本地“数据”的更新同步。所以当TreeCache被拆分成很多时,一定要去使用共享的线程,例如采用下面的代码:

private static final ExecutorService EXECUTE_SERVICE = Executors.newFixedThreadPool(5, ThreadUtils.newThreadFactory("tree-cache-for-dedicated") );
//创建要给共享的,线程数可以根据情况做调整,然后所有的拆开后的TreeCache共享。如果不指定ExecutorService来共享,每个新TreeCache会默认使用一个新线程。

TreeCache treeCache = executorService == null? TreeCache.newBuilder(client, storePath).build():
TreeCache.newBuilder(client, storePath).setExecutor(executorService).build();

以上即为这个问题的3W分析,追根溯源,还是业务初期,数据量小时不管对采用的开源组件是否了解,无论如何用,都不会出问题,但是如果数据量大时,就会暴露设计的可扩展性缺陷。

 

题外:

查看启动时间:

[root@ip-10-0-1-85 zookeeper]# echo mntr |nc localhost 2181 |grep time

zk_leader_uptime 6251602595
zk_uptime 6251602802

查看选举时间:

echo mntr |nc localhost 2181 |grep election

zk_avg_election_time 1818.0 
zk_min_election_time 20 
zk_max_election_time 4437 
zk_cnt_election_time 3
zk_sum_election_time 5454