论 Apache Kylin SQL 中数据类型的重要性

背景

4月9号的时候，我们一个线上独立查询集群收到 Http 请求500异常的报警，用户也反馈查询严重超时。 当时首先看了下监控的 Dashboard,发现 Kylin QueryServer 的以下指标异常升高：

Kylin.TomcatRequest.processingTime

但是内存，CPU 使用正常，GC 情况也正常，说明不是常见的大查询引起的 OOM，之后我就登录线上机器，发现耗时20多秒的查询请求 HBase 很快，只有几 ms，但是：

在 service.QueryService:356

到 routing.QueryRouter:56 之间

足足耗时21s，根据以往的经验来看，应该是 Calcite 又有问题。于是决定留下 Jstack，先重启机器，恢复服务。

Jstack 分析

分析 Jstack 后发现，大量线程 Block 在 WebappClassLoaderBase loadClass 的地方：

而锁0x0000000580000688被 RUNNABLE 的线程持有

grep 了下发现，等待0x0000000580000688这个锁的线程有93个之多。 所以现在查询线程 blocked 的原因找到了，但是为什么会有大量的查询线程需要 loadClass，loadClass 为什么耗时很久还不清楚。

当时简单谷歌了一下，找到了两个比较相关的问题：

根据这两个 Jira，我判定问题很大可能和 Calcite 有关系。 但是我们是第一次遇到这个问题，而且是两年来第一次遇到，同时我们其他多个查询集群从来没有发生过这个问题，所以我感觉这个问题触发的概率应该很低，同时考虑到即使出了问题我们也可以快速恢复服务，就不准备深究这个问题，因为其他优先级很高的事情很多。

问题复现

但是4月11号这个问题又出现了，说明了这不是一个低概率事件。但是为什么只有一个查询集群有这个问题呢？开始怀疑是不是用户的 SQL 最近有什么改动，导致这两天出现了这个问题，但是和用户确认后，SQL 最近并没有改动。 我也分析了多个导致线程阻塞的 SQL，十分简单，并没有什么特别的地方：

我们从 WW-3902 可以推测这个问题很可能和并发有关。 不过有两点和我已知事实矛盾的地方：

1、这个查询集群的并发并不是很高，QPS 最高只到3。

2、我之前专门压测过 Kylin，Kylin在高并发场景下由于 Calcite 的代码生成的确会有明显的性能下降，但是在并发30多时也没有出现线程阻塞。

但是当时也没有其他复现问题的好思路，所以还是决定先试下并发会不会导致这个问题。 于是用32的并发同时执行上面的 SQL，比较幸运，问题直接复现了。

LoadClass 原理明确

我们现在已经确定这个问题是在高并发情况下 WebappClassLoaderBase loadClass 锁竞争导致的。所以在深入分析之前，我们需要先明确下 WebappClassLoaderBase 的原理，loadClass 什么时候需要同步。

Kylin 中使用的类加载器是 CustomizedWebappClassloader:

CustomizedWebappClassloader 继承自 ParallelWebappClassLoader，ParallelWebappClassLoader 继承自 WebappClassLoaderBase，WebappClassLoaderBase 继承自 ClassLoader。 ParallelWebappClassLoader 是一个并发的类加载器，原理是通过调用 Classloader.registerAsParallelCapable 开启并发加载。这样类名不同的 Class 就可以并发加载，只有类名相同的 Class 才需要同步。

同时 WebappClassLoaderBase 加载类的逻辑如下：

所以我们知道一个应用程序中1个类只会加载一次，第二次加载时会从 Cache 中加载。

调试分析

搞清 LoadClass 的原理后，我们知道多个查询线程阻塞的原因应该是多个查询线程需要去加载同一个类，而且这个类应该加载的比较慢。 于是就决定调试下代码，同时考虑到很大概率和 Calcite 的代码生成有关系，就将 calcite.debug 设置为 true。

根据 Jstack 文件，首先将断点设置到 WebappClassLoaderBase 的1844行。因为程序开始运行时需要加载的类肯定很多，所以我在跑了一遍上面的 SQL 后，正式开启 debug。 debug 过程中发现会多次加载 org,Object,org/apache 这样的类名，这样的类显然是不存在的，无法正确加载，于是根据堆栈分析，发现这些类是 UnitCompiler.findTypeByName 中产生的，再追，发现 IClassLoader loadClass 的逻辑如下：IClassLoader 中对无法加载的类会有 Cache unloadableIClasses。 其 unloadableIClasses 的内容如下： 

既然有 Cache，这些类应该在 WebappClassLoaderBase 只会加载一次，但是 debug 中发现 org 这种类会出现多次。说明这个 Cache 不是全局的，再分析 Jstack，猜测其应该是每个 UnitCompiler 会有一个。

这时候我去看了这个 SQL 对应的 Calcite 生成的代码，发现了大量的：

这时候 UnitCompiler，大量 apply 代码片段， Integer.toString(xxx) 这几个因素，让我脑海中联想到问题莫非是和数据类型有关，于是在 Kylin web 上确认了下 SQL 中 id 和 price 的类型，的确是 String。于是我就把 SQL 中的 Int 改成了 String。用32的并发测试了下，果然没有了线程阻塞，而且每个查询的耗时比之前还短。

至此，我们整个问题的原因已经明确并同时有了解决方案。

刚才 apply 代码和 UnitCompiler 有关只是从代码命名和堆栈上的猜测，之后在代码中也确认了下，每个代码片段的确对应一个 UnitCompiler。

其代码中的调用链如下：

这里还有一个问题，为什么 Calcite 会产生 org,Object,org/apache 等这样奇怪的，并不存在的类名。

如上图，应该是 UnitCompiler 的 reclassifyName(Location location, Scope scope, final String[] identifiers, int n)或者 reclassifyName(Location location, Scope scope, final String identifier) 这个方法有 Bug。对于 org.apache.calcite.runtime.SqlFunctions.truncate 这个方法，UnitCompiler 会当成6个 identifier，然后递归调用 reclassifyName 生成类名，但显然 org，org.apache，org.apache.calcite 并不是合法的类名。

逻辑链梳理

1、Table 中的 id 和 dt_name 都是 String 类型，但是在 SQL 中用户写的是 Int

2、SQL 中大量的 In 导致 Calcite 生成的代码有大量的 Integer.toString 代码片段

3、UnitCompiler 在编译代码片段时会生成较多不合法的类名

4、由于不合法的类名每次都需要加载，1个 SQL 会生成30多个(甚至更多)代码片段，加上并发，就会造成相同类名的类在加载时争抢锁，一旦有一次处理的慢了，就会形成恶性循环，锁竞争越来越严重，进而形成90多个查询线程 Blocked 的情况，造成查询服务不可用。

Kylin 中 SQL 数据类型的重要性

1、SQL 中数据类型和实际类型不一致，在并发情况下很容易导致 Kylin QueryServer 大量查询线程 Blocked，进而导致查询服务不可用。

2、SQL 中数据类型和实际类型一致，比不一致时的性能有明显提升。（具体提升多少就看 HBase 处理时间和 Kylin QueryServer 处理时间的占比，假如 HBase 的处理时间在几十毫秒左右，查询时延应该可以提升一个数量级，从几秒提升到几百毫秒）

如何排查和解决问题

我们计算机工程师在平时必然会遇到很多的线上，开发问题需要解决，下面我根据我最近解决一些问题的经历，浅谈下我们解决问题的常规思路和手段，想的时间比较短，不是很完善：

1.确认真实的代码和你预期的代码是完全一致的

相信大家都经历过分析了大半天问题，最终发现代码没更新的情况。 预防这种问题可以在代码仓库或者发布系统中中加上 Commit 号，这样我们就可以快速判断我们的代码版本是否正确，但是这个措施只能保证我们当前系统的代码是没有问题的，并不能保证我们系统依赖的其他系统代码也是最新的。

例如：我在开发 Kylin On Druid POC 时，需要先修改 Druid 代码，发布到我们公司 Maven 仓库，然后再编译 Kylin 代码进行发布。 开始测试时我发现改的 Druid 代码有 Bug，就更新发布 Druid 代码后，再重新编译发布 Kylin 代码，但是我发现更新后还是有问题，开始我一直以为是我改的 Druid 代码逻辑有问题，反复确认几次后，想到先确认下代码到底是不是最新的。

最后经过 Google 后才明确，Maven 对于 SNAPSHOT 的依赖库并不保证每次都下载最新版本的，需要加上 -U 参数才能保证每次使用最新版本。

2.确认服务的环境是符合预期的，配置是正确的

服务的环境包括操作系统版本，核心参数，JDK 版本，环境变量，依赖的 Jar 包等。 检查配置我们不仅要确认配置本身没问题，还要确认下配置的优先级，配置的作用和生效范围。配置还包括依赖系统的配置，像 Kylin 这种依赖系统的话还需要考虑 HBase，Hadoop，Hive，Spark 等的配置。

例如：我去年在搞 Kylin 跨机房迁移时，就遇到 Kylin Spark Cubing 执行失败的情况，最后经过排查，确认是 Kylin 本身的 bug，而触发这个 Bug 的因素就是环境和配置的变化。 具体可以参考 KYLIN-2995：

3.分析变量

很多时候，我们正常的服务变得不正常，都是由变量引起的，一般是我们内部本身的变量导致了问题，或者是外部的变量触发了我们内部的 Bug。

我们在分析问题时，首先应该确定内部和外部的变量（比如我们代码改了哪些地方，用户的查询模式有什么变化，出问题服务的环境和正常服务的环境有什么区别），然后再分析确认每个变量是不是导致我们此次问题的因素。很多时候，经过这一步，我们就可以找出问题的原因。

比如文中这个 Case 的变量就是用户的 SQL 数据类型，这个变量也是触发 Calcite Bug 的因素，所以我们其他查询集群都没有发生过这个问题，

4.保留现场

有些线上问题的发生有其偶然性和必需条件，线上服务有问题，我们必须马上恢复服务，一般不会立即分析问题，所以我们必须保留现场。 这些现场包括完善的监控指标：机器本身和服务本身的监控，Thead dump，Heap dump，Core Dump，关键的 Log 等。

比如文中的这个 Case 的分析处理就利用了监控指标和 Thead dump。 我们利用监控指标和 Thead dump 分析出问题的原因是大量线程在 LoadClass 时 Block，并根据线程堆栈可以判断出问题可能和 Calcite 有关。

5.梳理处理问题需要的背景和最少知识

工作中随意给个问题让我们进行处理时，我们必然需要明确这个问题相关的整个背景，问题中涉及的概念，涉及的系统原理。搞清原理可以帮助我们快速，正确的分析问题，不会盲目的走弯路。

比如文中的这个 Case 我们就应该明确 Tomcat 类加载到底是串行还是并行，是什么粒度的并行。

再举个例子。 在进行 Kylin On Druid 开发时，我发现 Druid 的 Segment Load 进 Druid 时会很慢。 这个时候我要去优化 Druid Segment Load 的速度，就必须首先搞清楚 Druid 的 Coordinator 怎么知道有新 Segment 生成了？Druid 的 Coordinator 多久会处理一次 Segment Load？Druid 的 Coordinator 如何和 Historical 节点交互？ Historical Load Segment 的逻辑？ 官方的并发 Load 配置为何不生效（实际是串行 Load）？ 只有这些问题明确后，我才可以进行优化。

6.复现问题

在我们排除了代码因素，环境因素，配置因素，变量因素之后，问题相关的原理也明确了，我们可以首先尝试去复现问题，因为如果问题可以通过某种方式稳定复现的话，那么导致问题出现的因素基本就确定了，我们就可以开始通过各种手段分析问题了

7.Debug

当代码逻辑比较复杂，或者看代码怎么也看不出问题时，或者是系统依赖的第三方系统有问题时 debug 往往会比较有用。文中 Case 的原因明确主要靠的就是 debug。一般分析 Kylin 查询问题时，debug 十分有用，而且 Kylin 查询的问题一般 debug 都可以解决。

8. Log

当我们要进行一些耗时分析或者无法直接 debug 时（比如 Hadoop 集群上运行的 MR Job），我们就可以直接加些 log，帮助我们快速分析。

9.直接根据异常本身进行代码分析

有时候，我们的系统会抛出一些和我们系统本身无关的异常，这个时候我们可以尝试下从异常本身出发，分析下异常产生的原因。

例如，前一阵我们有台 Kylin 的 JobServer 每隔24小时就会出现访问 Hive MetaStore Kerberos 认证失败的问题，但是其他 JobServer 都没有问题。我们负责 Kerberos 的同学追查了几次也没查到什么原因。

前几天我就决定追一下，但是我一开始也没什么好思路，我就决定先看 JDK8 的源码，先明确下这个异常的直接原因是什么。通过看 JDK8 的源码，首先明确这个异常的直接原因是获取的 Ticket 是 null:

然后追踪代码又发现Krb5Util.getTicket会首先尝试从当前AccessControlContext的Subject中获取ticket，如果ticket是null且javax.security.auth.useSubjectCredsOnly是false，则会通过HadoopLoginModule重新登录的方式来获取Subject，简单理解，就是多了一次重试的机会。

所以最终通过设置 javax.security.auth.useSubjectCredsOnly 为 false  解决了这个问题

10.逻辑分析

我们在复杂问题时一定要头脑清楚，逻辑清晰，有条理地分析和推断，综合利用综合法和分析法。因为一个问题再复杂，我们都可以不断拆解，层层推进，直到我们熟悉的已知问题；同时问题的许多现象和因素之间都有关联，我们在分析问题时，也要注意各种现象和因素的关联性。

总结

本文通过一次线上事故的分析过程，说明了 Apache Kylin 中 SQL 数据类型的重要性，并简单总结了下我们如何排查和解决问题。