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


作者: 康凯森

日期: 2017-05-07

分类: OLAP


从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请求同步!

Http请求同步!

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请求发送方的有问题了。

  1. 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请求足足阻塞了几个小时

事故的逻辑链条

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

事故的影响范围

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

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

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

Kylin运维上的改进

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

Kylin代码上的改进

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

事故的反思

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

评论