Kylin Memcached IO 线程死亡诊断
故障现象
集群中某 Kylin 实例响应很极慢，日志中出现如下信息：
2019-07-01 15:21:18,024 INFO [Query 3f75c477-9c38-35bf-24a0-656459d9ebb1-212641] v2.CubeHBaseEndpointRPC:188 : Query-3f75c477-9c38-35bf-24a0-656459d9ebb1: try to get segment result from cache for segment:1102_pv_uv_users_di[20150901000000_20160101000000]
2019-07-01 15:21:20,028 INFO [Query 3f75c477-9c38-35bf-24a0-656459d9ebb1-212641] v2.CubeHBaseEndpointRPC:197 : Query-3f75c477-9c38-35bf-24a0-656459d9ebb1: no segment result is cached for segment:1102_pv_uv_users_di[20150901000000_20160101000000], take time:2000ms
初步认定为在 try to get segment result 时，发生超时（2秒正好是超时时间）。但检查 Memcached 各个实例，发现均为可用状态。
该问题在访问分区 Cube 时会被严重放大，因为一个 Segment 访问超时时间是 2 秒，当 Cube 存在 20 个的 Segment 时，一条 SQL 至少要 40 秒才能返回结果。
因此最近几次故障发生时未分区的 Cube 几乎无感知，但分区的 Cube 基本均全处于不可用状态。
此外，异常发生前日志中持续打印下列信息：
2019-07-04 13:59:48.989 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to exception on {QA sa=memcached2/172.16.17.3:11211, #Rops=0, #Wops=2, #iq=0, topRop=null, topWop=Cmd: 1 Opaque: 2297 Key: PROD:query_segment_cache:36b344a063b0f914448b311229db4c4d3a2b30c2 Cas: 0 Exp: 604800 Flags: 2048 Data Length: 350795, toWrite=0, interested=4}
java.lang.NullPointerException
2019-07-04 13:59:48.992 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=memcached2/172.16.17.3:11211, #Rops=0, #Wops=2, #iq=0, topRop=null, topWop=Cmd: 1 Opaque: 2297 Key: PROD:query_segment_cache:36b344a063b0f914448b311229db4c4d3a2b30c2 Cas: 0 Exp: 604800 Flags: 2048 Data Length: 350795, toWrite=0, interested=4}, attempt 0.
2019-07-04 13:59:48.993 INFO net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl: No buffer for current write op, removing
2019-07-04 13:59:50.123 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to exception on {QA sa=memcached1/172.16.16.3:11211, #Rops=1, #Wops=1, #iq=0, topRop=null, topWop=Cmd: -1 Opaque: -1 Keys: , toWrite=0, interested=4}
java.lang.NullPointerException
at net.spy.memcached.protocol.TCPMemcachedNodeImpl.fillWriteBuffer(TCPMemcachedNodeImpl.java:206)
at net.spy.memcached.MemcachedConnection.handleWrites(MemcachedConnection.java:811)
at net.spy.memcached.MemcachedConnection.handleInputQueue(MemcachedConnection.java:596)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423)
at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:1457)
重启后，该故障可 100% 解决。如果不重启，该状态持续一段时间后也会自动触发 OOM 然后被进程管理工具自动重启。
初步确定原因
经过对 Memcached 的多次压测，响应时间最高不超过 50 ms，因此初步排除 Memcached 真的响应过慢导致 Kylin Memcached 客户端 2000 ms 超时的可能。
后开始检查 Kylin 操作 Memcached 的相关逻辑，也并未发现明显异常。
最终开启测试实例加载线上数据，进行 Debug，重复执行生产环境 Kylin 实例发生异常前几十秒正在执行的 SQL，最终成功复现线上 2000 ms 超时的问题。
通过检查测试 Kylin 实例中正在运行的线程，终于发现异常。处理 Memcached IO 的线程竟然不存在了。
然后从断点中观察到 Memcached IO 队列中发现大量积压，无法读出也无法写入。
image_name
且终端打印出异常信息：
Exception in thread "Memcached IO over {MemcachedConnection to ******}" java.lang.NullPointerException
at net.spy.memcached.protocol.TCPMemcachedNodeImpl.fillWriteBuffer(TCPMemcachedNodeImpl.java:206)
at net.spy.memcached.MemcachedConnection.handleWrites(MemcachedConnection.java:811)
at net.spy.memcached.MemcachedConnection.handleInputQueue(MemcachedConnection.java:596)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423)
at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:1457)
所以基本确定，造成故障的原因为负责对 Memcached 进行 IO 操作的线程异常退出。
进一步找出问题根源
通过查看 Memcached 客户端 Spymemcached 的源码，并无法成功找出可能造成 Memcached IO 线程 NPE 退出的原因。正当百思不得其解之际，在 GitHub 中发现了下面这个 Pull Request。
NPE in fillWriteBuffer() with binary protocol
顺便吐槽 spymemcached 的 issue tracker 真心难找，这个 PR 的作者是拿 PR 来报 Issue 的。
读完之后恍然大悟，只有在写入的数据大于等于 1024 * 1024 byte 即 1 MB 时，才可能触发该异常。
但是大于 1 MB 的数据是写不进去的，所以基本可以推测出 Kylin 的客户端一定是大量并发的写入极接近 1 MB 或等于 1 MB 的数据时，触发了这个异常，导致 Memcached IO 线程死亡。
但是查看了 Kylin 的源码发现下面的信息，又使我陷入了沉思。。。
private SegmentQueryCache() {
KylinConfig kylinConfig = KylinConfig.getInstanceFromEnv();
MemcachedCacheConfig memcachedCacheConfig = new MemcachedCacheConfig();
String configHosts = kylinConfig.getMemCachedHosts();
memcachedCacheConfig.setTimeout(kylinConfig.getQuerySegmentCacheTimeout());
// set max object size a little less than 1024 * 1024, because the key of the segment result cache is long
// if set to 1024 * 1024 will cause memcached client exceed max size error
memcachedCacheConfig.setMaxObjectSize(1040000);
memcachedCacheConfig.setHosts(configHosts);
//Reverse the compression setting between Hbase coprocessor and memcached, if Hbase result is compressed, memcached will not compress.
memcachedCacheConfig.setEnableCompression(!kylinConfig.getCompressionResult());
String cacheName = SEG_QUERY_CACHE_NAME;
memcachedCache = new MemcachedChunkingCache(MemcachedCache.create(memcachedCacheConfig, cacheName));
}
看来 Kylin 在操作 Memcached 时已经意识到大并发写入 1 MB 的数据可能会出现问题，所以将 maxObjectSize 置为了 1040000，并不接近 1048576。
最终只能靠实验来测试到底什么样的数据量可能触发这个问题。
import net.spy.memcached.BinaryConnectionFactory;
import net.spy.memcached.MemcachedClient;
import net.spy.memcached.transcoders.SerializingTranscoder;
import java.io.IOException;
import java.net.InetSocketAddress;
import java.util.ArrayList;
import java.util.List;
public class Main2 {
public static void main(String[] args) throws IOException {
List<InetSocketAddress> addrs = new ArrayList<>();
addrs.add(new InetSocketAddress("t1", 12000));
MemcachedClient client = new MemcachedClient(new BinaryConnectionFactory(), addrs);
SerializingTranscoder transcoder = new SerializingTranscoder();
transcoder.setCompressionThreshold(Integer.MAX_VALUE);
byte[] data = new byte[1048000];
while (true) {
String keyS = "test";
client.set(keyS, 60, data, transcoder);
}
}
}
通过上述代码疯狂写入 Memcached，并未出现空指针异常。
但是该例子并不能代表 Kylin 实际向 Memcached 中写入的最大的数据量，因为 Kylin 是通过自己包装的 MemcachedChunkingCache 进行写入操作。
下面只需要算一算什么样的 byte[] 能触发 Kylin 写入极限大小的数据量了。
观察下面这部分代码
public static int getValueSplit(MemcachedCacheConfig config, String keyS, int valueBLen) {
// the number 6 means the chunk number size never exceeds 6 bytes
final int valueSize = config.getMaxObjectSize() - Shorts.BYTES - Ints.BYTES
- keyS.getBytes(Charsets.UTF_8).length - 6;
final int maxValueSize = config.getMaxChunkSize() * valueSize;
Preconditions.checkArgument(valueBLen <= maxValueSize,
"the value bytes length [%d] exceeds maximum value size [%d]", valueBLen, maxValueSize);
return (valueBLen - 1) / valueSize + 1;
}
只要让 valueBLen 是 valueSize 的整数倍即可。我们来个 50 倍试试看。
valueSize 算出是 1047230，再算上序列化操作后的一些字节变化，最后我们只需要保证数据量为 52361473 即可。
测试代码改成如下样子：
import cn.dxy.ops.chaos.cache.memcached.MemcachedCache;
import cn.dxy.ops.chaos.cache.memcached.MemcachedCacheConfig;
import cn.dxy.ops.chaos.cache.memcached.MemcachedChunkingCache;
public class Main3 {
public static void main(String[] args) {
MemcachedCacheConfig memcachedCacheConfig = new MemcachedCacheConfig();
memcachedCacheConfig.setHosts("t1:12000");
memcachedCacheConfig.setEnableCompression(false);
memcachedCacheConfig.setTimeout(2000);
MemcachedCache memcachedCache = new MemcachedChunkingCache(MemcachedCache.create(memcachedCacheConfig, "query_segment_cache"));
byte[] data = new byte[52361473];
while (true) {
String keyS = "test_agg_group_294958b3-1829-cd88-6d01-f44ed1d22067_.org.apache.kylin.cube.gridtable.CubeCodeSystem\\x00\\x04\\x00\\x8F\\x82\\xAC\\xED\\x00\\x05sr\\x00-org.apache.kylin.cube.gridtable.TrimmedDimEnc\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x0C\\x00\\x00xr\\x00,org.apache.kylin.dimension.DimensionEncoding\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x0C\\x00\\x00xpw\\x02\\x00\\x03x\\x00\\x8F\\x82\\xAC\\xED\\x00\\x05sr\\x00-org.apache.kylin.cube.gridtable.TrimmedDimEnc\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x0C\\x00\\x00xr\\x00,org.apache.kylin.dimension.DimensionEncoding\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x0C\\x00\\x00xpw\\x02\\x00\\x03x\\x00\\x8F\\x82\\xAC\\xED\\x00\\x05sr\\x00-org.apache.kylin.cube.gridtable.TrimmedDimEnc\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x0C\\x00\\x00xr\\x00,org.apache.kylin.dimension.DimensionEncoding\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x0C\\x00\\x00xpw\\x02\\x00\\x03x\\x00\\x8F\\x82\\xAC\\xED\\x00\\x05sr\\x00-org.apache.kylin.cube.gridtable.TrimmedDimEnc\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x0C\\x00\\x00xr\\x00,org.apache.kylin.dimension.DimensionEncoding\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x01\\x0C\\x00\\x00xpw\\x02\\x00\\x01x\\x09Cuboid 15\\x06\\x07integer\\xFF\\xFF\\x07integer\\xFF\\xFF\\x07integer\\xFF\\xFF\\x07integer\\xFF\\xFF\\x06bigint\\xFF\\xFF\\x06bigint\\xFF\\xFF\\x00\\x01\\x0F\\x02\\x01\\x0F\\x010\\x00\\x00\\x01\\x0F\\x00\\x01\\x0F\\x00\\x00\\x00\\x08NO_LIMIT\\x8C\\x7F\\xFF\\xFF\\xFF\\x8C\\x7F\\xFF\\xFF\\xFF\\x19SCAN_FILTER_AGGR_CHECKMEM\\x01\\x01";
memcachedCache.put(keyS, data);
}
}
}
执行上面的代码基本基本每次都可以触发空指针异常，有概率触发 Memcached IO 线程死亡。
Exception in thread "Memcached IO over {MemcachedConnection to ******}" java.lang.NullPointerException
at net.spy.memcached.protocol.TCPMemcachedNodeImpl.fillWriteBuffer (TCPMemcachedNodeImpl.java:206)
at net.spy.memcached.MemcachedConnection.handleWrites (MemcachedConnection.java:811)
at net.spy.memcached.MemcachedConnection.handleInputQueue (MemcachedConnection.java:596)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423)
at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:1457)
此时，在对数据进行 UTF-8 编码之后，实际并发写入的数据量为 1048571 byte。
image_name
我们将 Main2 中的数据量从 1048000 改为 1048571 然后再次执行，会发现也有概率触发 Exception in thread "Memcached IO over {MemcachedConnection to ******" java.lang.NullPointerException 的问题了。
结论
越是诡异的问题，改动起来可能越小，这么看来，直接将 maxObjectSize 从 1040000 改为 1000000 可能更保险一些。
