记Kylin的第一次夜间生产事故

作者: 康凯森

日期: 2017-05-07

分类: OLAP

事故复盘和原因分析
连续两次Kinit失败的原因
Kerberos认证失败为什么会导致Http请求阻塞
事故的逻辑链条
事故的影响范围
为什么在对Kylin代码有高度掌控力的情况下处理时间长达3个小时
Kylin运维上的改进
Kylin代码上的改进
事故的反思

从2016年7月毕业正式入职美团点评负责Kylin以来，昨天5月6日（星期六）我进行了Kylin的第一次夜间生产故障处理。（我们Kylin的Cube按天生产已经保持连续半年0事故）虽然这次故障的影响范围并不大， 但是这次故障处理暴露出我们运维本身和Kylin代码的几个严重问题，故障处理过程中也有好几处值得深深反思的地方，所以写下此文总结一下。

事故复盘和原因分析

1 5月5日13点我进行了线上JobServer扩容操作，将线上JobServer从2台扩容至3台物理机，并验证没有问题。于是当晚我和平常一样安心的睡觉了，并没有担心什么。

扩容的原因：

1 线上Cube已有260多，JobServer内存压力较大，而JobServer的并发能力受限于内存。

2 Kylin 2.0版本的字典MR构建只能对中小基数列开启，这个其实意义不大，因为真正带来内存压力的都是超高基数列的字典构建，所以即使升级也解决不了问题。

所以我们短期内需要通过物理扩容来缓解JobServer内存压力，长期来看我们需要通过超高基数列的MR构建来彻底释放JobServer内存压力，我应该会在6月份开始进行这个工作。如果超高基数列的字典编码能通过MR来构建，JobServer的并发能力应该会成百上千倍的提升。

2 5月6日凌晨3点01分，dayue 打电话叫醒我，说今天JobServer扩容有问题，好几个Cube构建失败了。（我睡觉比较死，报警都没听见）我内心有点郁闷，我扩个容都能扩出故障，有这么挫吗？！而且我的确进行了认真的验证，怎么会出问题呢？

3 dayue在3点09分下线了JobServer03。

4 我大概在3点10分左右开始分析事故原因，因为我不相信是扩容的问题。

首先并不是所有Cube构建都失败，只是部分Cube构建失败。

其次失败的Cube都是在Cube构建的第3步 Extract Fact Table Distinct Columns失败的，异常如下：

java.lang.IllegalStateException
    at org.apache.kylin.engine.mr.steps.FactDistinctColumnsJob.run(FactDistinctColumnsJob.java:113)
    at org.apache.kylin.engine.mr.MRUtil.runMRJob(MRUtil.java:88)
    at org.apache.kylin.engine.mr.common.MapReduceExecutable.doWork(MapReduceExecutable.java:120)
    at org.apache.kylin.job.execution.AbstractExecutable.execute(AbstractExecutable.java:113)
    at org.apache.kylin.job.execution.DefaultChainedExecutable.doWork(DefaultChainedExecutable.java:57)
    at org.apache.kylin.job.execution.AbstractExecutable.execute(AbstractExecutable.java:113)
    at org.apache.kylin.job.impl.threadpool.DistributedScheduler$JobRunner.run(DistributedScheduler.java:184)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

这个异常对应的代码如下：

            CubeSegment segment = cube.getSegmentById(segmentID);
            if (segment == null) {
                logger.error("Failed to find {} in cube {}", segmentID, cube);
                throw new IllegalStateException();

也就是说构建这个Segment的JobServer并没有获取对应的Segment。根据segmentID获取Segment的代码如下：

    public CubeSegment getSegmentById(String segmentId) {
        for (CubeSegment segment : segments) {
            if (Objects.equal(segment.getUuid(), segmentId)) {
                return segment;
            }
        }
        return null;
    }

从代码中我们知道获取Segment是从JobServer本地缓存中获取的，并不是直接从HBase中获取的。

那么为什么JobServer本地元数据缓存中没有Segment的元数据呢？

分布式调度的实现中对Segment加锁和释放锁的逻辑都是在DistributedScheduler中，只有成功获取到Segment锁的JobServer才会负责该Segment的构建。也就是说接收Segment构建Http请求的JobServer并不一定是真正构建该Segment的JobServer，比如你的Http请求是发送到JobServer01的，但是有可能是JobServer02构建该Segment。这样做的好处可以提高全部JobServer的资源利用率。比如JobServer01并发量已满时，其他JobServer可以处理提交到JobServer01的Job。在JobServer重启和takeover的时候都十分有用。

而新Segment的元数据生成是在接收该Segment构建Http请求的JobServer上处理的。

JobService.submitJob():

if (buildType == CubeBuildTypeEnum.BUILD) {
          CubeSegment newSeg = getCubeManager().appendSegment(cube, startDate, endDate, startOffset, endOffset);

上面的appendSegment方法会生成新的Segment，并会将Segment元数据通过Http请求同步到其他JobServer和所有QueryServer。

Http请求同步！

所以现在根据代码我们可以解释为什么JobServer本地元数据缓存中没有Segment的元数据，因为新Segment的元数据信息没有成功同步到其他JobServer。这同时也解释了为什么只是部分Cube构建失败，而不是全部Cube构建失败，因为如果接收Segment构建Http请求的JobServer和构建该Segment的JobServer是同一个的话就不会有问题。

在当时除了从代码确认，还花了较长时间从log中确认。我分别仔细看了新扩容的JobServer03上一个构建成功和构建失败的日志，所以我确认今天的Cube构建失败和JobServer扩容没有关系，原因是Cube元数据同步失败。

5 我3点55分在我们大象（公司IM工具）群公布了我的结论。

6 接下来我们需要确认元数据Http请求同步失败的原因。

Http请求同步失败肯定只有3种:
1. Http请求发送方没有成功发送
2. Http请求因为网络原因丢失
3. Http请求接收方没有成功接收

我分析的时候是逆着来的。

我首先确认Http请求的接收方有没有出问题。我看了3台JobServer的Http请求日志，从16台QueryServer中抽看了8台。发现所有节点的Http请求日志一致，所以可以确认不是Http请求接收方的问题。

其次我花了较长时间确认是不是网络的问题（因为近期我们机房出现了多次网络故障，所以我下意识的想先排除这个原因），我查了ping和TCP的监控指标，测了下ping的丢包率。但都没有发现什么明显的异常。

所以下来就只可能是Http请求发送方的有问题了。

5点21分 dayue发现是元数据同步请求失败是因为发送Http请求的线程池是 newFixedThreadPool，且某些元数据同步的Http请求阻塞了，导致新的Http请求无法被执行，所以Cube元数据没有成功同步。dayue将newFixedThreadPool改为newCachedThreadPool，并给元数据同步线程设置了线程名"CacheWiper %s %s", restClient, broadcastEvent"。

显然此处newCachedThreadPool是比newFixedThreadPool更加合理的，因为newCachedThreadPool可以灵活的根据需要新建线程和回收不必要的线程。

当然这里还有一个重要的问题，就是元数据同步的Http请求为什么会阻塞？

这个问题在dayue为元数据同步的线程设置了线程名后找到了原因，有了线程名之后，根据jstack就知道了是发送到3台QueryServer的Http请求阻塞了。

然后我就去重启这3台QueryServer，但是重启的时候重启几次都没起来，看log发现是kerberos认证失败了，然后再klist发现 Ticket的过期时间竟然是 05/06/17 01:10:01，这说明是连续两次Kinit失败导致Ticket过期，最终导致kerberos认证失败。

在重启3台QuerySerever后，JobServer的Cube元数据同步终于正常，此时已经到了凌晨6点。

连续两次Kinit失败的原因

5月6号12点多我们的小伙伴确认了连续两次Kinit失败的原因是我们的krb5.conf文件的第3个KDC Server地址配置有误，最近才出现问题是因为第3个KDC Server最近刚刚下线了。。。krb5.conf文件中的前两个KDC Server是我们数据组自己维护的，第3个是公司维护的，作为备用，请求主要是发往前两个Server的。

Kerberos认证失败为什么会导致Http请求阻塞

当天6点多服务正常后，我就先去补觉了，醒来后我依然没想通的是Kerberos认证失败为什么会导致Http请求阻塞。

正常来讲，Kerberos认证失败最多导致Cube元数据同步时，在请求HBase时多重试几次，但应该在几分钟内失败返回，不至于阻塞几个小时。

其Kylin log应该如下，应该会有对应的失败log。

2017-05-06 01:36:39,274 INFO  [http-bio-8080-exec-39] controller.CacheController:78 : wipe cache type: CUBE event:UPDATE name:work_day_record_ex
2017-05-06 01:36:39,275 INFO  [http-bio-8080-exec-39] service.CacheService:165 : rebuild cache type: CUBE name:work_day_record_ex

2017-05-06 01:38:13,377 ERROR [http-bio-8080-exec-39] cube.CubeManager:877 : Error during load cube instance, skipping : /cube/q.json

2017-05-06 01:40:00,600 WARN  [http-bio-8080-exec-39] service.CacheService:293 : Failed to reset project cache

Tomcat的请求log中也应该有记录

10.16.90.3 - - [06/May/2017:01:40:00 +0800] "PUT /kylin/api/cache/cube/work_day_record_ex/update HTTP/1.1" 200 -

吐槽一下，这失败的不能再失败的请求返回码竟然是200！ reloadCubeLocalAt方法竟然把异常都吞了，弱弱的打了个error。

奇怪的是在Kinit失败的QueryServer上好几个请求都只有前两个log，也就是说Cube元数据同步的代码阻塞住了，而且整整阻塞了几个小时。 最终我分析QueryServer重启前留下的Jstack文件时找到了原因。

在1台QueryServer上BLOCKED的Cube元数据同步线程竟然有16个！，它们都在等待锁 0x00000005e8bd2100。

"http-bio-8080-exec-633" #22516721 daemon prio=5 os_prio=0 tid=0x0000000004ccc000 nid=0x48fe waiting for monitor entry [0x00007ffe
46f80000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.kylin.cube.CubeManager.reloadCubeLocalAt(CubeManager.java:844)
        - waiting to lock <0x00000005e8bd2100> (a org.apache.kylin.cube.CubeManager)
        at org.apache.kylin.cube.CubeManager.reloadCubeLocal(CubeManager.java:614)
        at org.apache.kylin.rest.service.CacheService.rebuildCubeCache(CacheService.java:230)
        at org.apache.kylin.rest.service.CacheService.rebuildCache(CacheService.java:169)
        at org.apache.kylin.rest.controller.CacheController.wipeCache(CacheController.java:83)

而持有锁 0x00000005e8bd2100的线程却在等待锁 0x00000005e890d918

"http-bio-8080-exec-670" #22517031 daemon prio=5 os_prio=0 tid=0x0000000004de0800 nid=0x4a40 waiting for monitor entry [0x00007ffe3102e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegionInMeta(HConnectionManager.java:1263)
        - waiting to lock <0x00000005e890d918> (a java.lang.Object)
        at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegion(HConnectionManager.java:1162)
        at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegion(HConnectionManager.java:1119)
        at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.getRegionLocation(HConnectionManager.java:960)
        at org.apache.hadoop.hbase.client.RegionServerCallable.prepare(RegionServerCallable.java:74)
        at org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithRetries(RpcRetryingCaller.java:114)
        - locked <0x00000005f5f8e1a0> (a org.apache.hadoop.hbase.client.RpcRetryingCaller)
        at org.apache.hadoop.hbase.client.HTable.get(HTable.java:835)
        at org.apache.hadoop.hbase.client.HTable.get(HTable.java:812)
        at org.apache.kylin.storage.hbase.HBaseResourceStore.internalGetFromHTable(HBaseResourceStore.java:335)
        at org.apache.kylin.storage.hbase.HBaseResourceStore.getFromHTable(HBaseResourceStore.java:315)
        at org.apache.kylin.storage.hbase.HBaseResourceStore.getResourceImpl(HBaseResourceStore.java:223)
        at org.apache.kylin.common.persistence.ResourceStore.getResource(ResourceStore.java:140)
        at org.apache.kylin.cube.CubeManager.reloadCubeLocalAt(CubeManager.java:848)
        - locked <0x00000005e8bd2100> (a org.apache.kylin.cube.CubeManager)
        at org.apache.kylin.cube.CubeManager.reloadCubeLocal(CubeManager.java:614)

而等待锁0x00000005e890d918 的线程足足有335个！有这么多线程是因为请求HBase的线程都需要获得这个锁。 至此我们就清楚了为什么Cube元数据同步的Http请求足足阻塞了几个小时。

事故的逻辑链条

krb5.conf文件的KDC Server配置有误
3台QueryServer连续两次Kinit失败
3台QueryServer Kerberos认证失败
QueryServer Cube元数据同步的线程因为等待HBase的锁而阻塞，且被唤醒的概率只有300分之一
JobServer的元数据同步线程池是newFixedThreadPool，所有线程均被阻塞，无法处理新的线程
JobServer的Cube元数据无法成功同步
部分Job在Cube构建的第3步失败

事故的影响范围

本次事故其实影响并不大，事故发生的时间凌晨1点到6点是Cube按天生产的低峰期，而且只有部分Cube会失败，而且一般在3次重试后都会成功构建。

为什么在对Kylin代码有高度掌控力的情况下处理时间长达3个小时

当天我进行了JobServer扩容，所以开始以为是和JobServer扩容有关。
我起来后没有看完所有报警，直接分析Cube构建失败的原因。如果我注意到QueryServer的报警，去看下QueryServer的log，可能很快就会定位是Kerberos的原因。
我在分析元数据同步Http请求失败原因的时候，应该按照可能性大小去分析，当时大脑逻辑好像有些不太清晰（难道是没睡醒。。。），感觉浪费了较多时间。
Kylin代码元数据同步这块logg太少。
我当时忘记了分析Jstack。
Kerberos服务没有可用性探针，所以Kerberos认证失败几个小时我们竟然不知道。

Kylin运维上的改进

更新所有节点的Krb5.conf。
更新Kinit策略，加上重试和报警。
增加Kerberos探针。
提高KDC服务的稳定性。

Kylin代码上的改进

dayue做的用newCachedThreadPool代替newFixedThreadPool，完善log，使用更有意义的线程名。
Http请求应该加上超时机制。分布式系统中无超时机制的RPC请求和Http请求肯定是有问题的。
reloadCubeLocalAt 应该抛出异常，失败的请求返回200太不合理。
reloadCubeLocalAt 标记为 synchronized 我认为是不必要的，reloadCubeLocalAt本质上只是元数据的读取操作，整个方法没有什么操作是不能并发的，除了usedStorageLocation这个Multimap的put操作。而我认为usedStorageLocation使用Multimap也是不必要的，完全可以用ConcurrentMap代替掉，只需把key从CubeName改为SegmentName。

事故的反思

系统中坚决不能容许失败的运维操作我们都应该有重试机制和报警。
线上事故在处理前我们应该保留现场（log，jstack，jmap，监控截图等）
线上事故发生时的所有报警都有可能是有关联性的，无论报警是什么等级，我们都应该关注。
一个易维护系统的log必须是充足的，合理的，有意义的，人可读的；其中所有线程都应该有极具标志性的线程名。 Kylin现在有些代码log就打的很烂，该打的log不打，不该打的log打一大堆。
稳定压倒一切，我们无法保证生产环境的稳定，我们就没法玩了。一个高可靠的系统源自可靠的系统设计，优秀的代码实现，充分的测试，可靠的运维，任何一个环节出现问题，都有可能导致事故的产生。
我们必须从事故处理，日常运维，日常客服这类工作中解脱出来，才会有更多精力满足我们用户更多的需求，才有可能打造一个高效，稳定，易用的平台。能解脱出来的前提是我们的系统是高可靠的，运维是自动化和高效的，我们的用户接入文档，使用文档，FAQ文档等是十分完善的，用户的对接和沟通过程应该是高度流程化和规范化的。
分布式系统必须考虑容错和局部失败；必须认为网络是不可靠的，物理时钟是不可靠的；有并发读写的场景就必须考虑分布式一致性问题。 Kylin 2.0版本的Segment并发构建就没有考虑分布式一致性问题。

《OLAP 性能优化指南》欢迎 Star&共建

《OLAP 性能优化指南》