Kylin Memcached IO 線(xiàn)程死亡診斷

Kylin Memcached IO 線(xiàn)程死亡診斷

故障現(xiàn)象

集群中某 Kylin 實(shí)例響應(yīng)很極慢，日志中出現(xiàn)如下信息：

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

初步認(rèn)定為在 try to get segment result 時(shí)，發(fā)生超時(shí)（2秒正好是超時(shí)時(shí)間）。但檢查 Memcached 各個(gè)實(shí)例，發(fā)現(xiàn)均為可用狀態(tài)。

該問(wèn)題在訪問(wèn)分區(qū) Cube 時(shí)會(huì)被嚴(yán)重放大，因?yàn)橐粋€(gè) Segment 訪問(wèn)超時(shí)時(shí)間是 2 秒，當(dāng) Cube 存在 20 個(gè)的 Segment 時(shí)，一條 SQL 至少要 40 秒才能返回結(jié)果。

因此最近幾次故障發(fā)生時(shí)未分區(qū)的 Cube 幾乎無(wú)感知，但分區(qū)的 Cube 基本均全處于不可用狀態(tài)。

此外，異常發(fā)生前日志中持續(xù)打印下列信息：

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% 解決。如果不重啟，該狀態(tài)持續(xù)一段時(shí)間后也會(huì)自動(dòng)觸發(fā) OOM 然后被進(jìn)程管理工具自動(dòng)重啟。

初步確定原因

經(jīng)過(guò)對(duì) Memcached 的多次壓測(cè)，響應(yīng)時(shí)間最高不超過(guò) 50 ms，因此初步排除 Memcached 真的響應(yīng)過(guò)慢導(dǎo)致 Kylin Memcached 客戶(hù)端 2000 ms 超時(shí)的可能。

后開(kāi)始檢查 Kylin 操作 Memcached 的相關(guān)邏輯，也并未發(fā)現(xiàn)明顯異常。

最終開(kāi)啟測(cè)試實(shí)例加載線(xiàn)上數(shù)據(jù)，進(jìn)行 Debug，重復(fù)執(zhí)行生產(chǎn)環(huán)境 Kylin 實(shí)例發(fā)生異常前幾十秒正在執(zhí)行的 SQL，最終成功復(fù)現(xiàn)線(xiàn)上 2000 ms 超時(shí)的問(wèn)題。

通過(guò)檢查測(cè)試 Kylin 實(shí)例中正在運(yùn)行的線(xiàn)程，終于發(fā)現(xiàn)異常。處理 Memcached IO 的線(xiàn)程竟然不存在了。

然后從斷點(diǎn)中觀察到 Memcached IO 隊(duì)列中發(fā)現(xiàn)大量積壓，無(wú)法讀出也無(wú)法寫(xiě)入。

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)

所以基本確定，造成故障的原因?yàn)樨?fù)責(zé)對(duì) Memcached 進(jìn)行 IO 操作的線(xiàn)程異常退出。

進(jìn)一步找出問(wèn)題根源

通過(guò)查看 Memcached 客戶(hù)端 Spymemcached 的源碼，并無(wú)法成功找出可能造成 Memcached IO 線(xiàn)程 NPE 退出的原因。正當(dāng)百思不得其解之際，在 GitHub 中發(fā)現(xiàn)了下面這個(gè) Pull Request。

NPE in fillWriteBuffer() with binary protocol

順便吐槽 spymemcached 的 issue tracker 真心難找，這個(gè) PR 的作者是拿 PR 來(lái)報(bào) Issue 的。

讀完之后恍然大悟，只有在寫(xiě)入的數(shù)據(jù)大于等于 1024 * 1024 byte 即 1 MB 時(shí)，才可能觸發(fā)該異常。

但是大于 1 MB 的數(shù)據(jù)是寫(xiě)不進(jìn)去的，所以基本可以推測(cè)出 Kylin 的客戶(hù)端一定是大量并發(fā)的寫(xiě)入極接近 1 MB 或等于 1 MB 的數(shù)據(jù)時(shí)，觸發(fā)了這個(gè)異常，導(dǎo)致 Memcached IO 線(xiàn)程死亡。

但是查看了 Kylin 的源碼發(fā)現(xiàn)下面的信息，又使我陷入了沉思。。。

    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));
    }

看來(lái) Kylin 在操作 Memcached 時(shí)已經(jīng)意識(shí)到大并發(fā)寫(xiě)入 1 MB 的數(shù)據(jù)可能會(huì)出現(xiàn)問(wèn)題，所以將 maxObjectSize 置為了 1040000，并不接近 1048576。

最終只能靠實(shí)驗(yàn)來(lái)測(cè)試到底什么樣的數(shù)據(jù)量可能觸發(fā)這個(gè)問(wèn)題。

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);
        }
    }
}

通過(guò)上述代碼瘋狂寫(xiě)入 Memcached，并未出現(xiàn)空指針異常。

但是該例子并不能代表 Kylin 實(shí)際向 Memcached 中寫(xiě)入的最大的數(shù)據(jù)量，因?yàn)?Kylin 是通過(guò)自己包裝的 MemcachedChunkingCache 進(jìn)行寫(xiě)入操作。

下面只需要算一算什么樣的 byte[] 能觸發(fā) Kylin 寫(xiě)入極限大小的數(shù)據(jù)量了。

觀察下面這部分代碼

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 的整數(shù)倍即可。我們來(lái)個(gè) 50 倍試試看。

valueSize 算出是 1047230，再算上序列化操作后的一些字節(jié)變化，最后我們只需要保證數(shù)據(jù)量為 52361473 即可。

測(cè)試代碼改成如下樣子：

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);
        }
    }
}

執(zhí)行上面的代碼基本基本每次都可以觸發(fā)空指針異常，有概率觸發(fā) Memcached IO 線(xiàn)程死亡。

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)

此時(shí)，在對(duì)數(shù)據(jù)進(jìn)行 UTF-8 編碼之后，實(shí)際并發(fā)寫(xiě)入的數(shù)據(jù)量為 1048571 byte。

image_name

我們將 Main2 中的數(shù)據(jù)量從 1048000 改為 1048571 然后再次執(zhí)行，會(huì)發(fā)現(xiàn)也有概率觸發(fā) Exception in thread "Memcached IO over {MemcachedConnection to ******" java.lang.NullPointerException 的問(wèn)題了。

結(jié)論

越是詭異的問(wèn)題，改動(dòng)起來(lái)可能越小，這么看來(lái)，直接將 maxObjectSize 從 1040000 改為 1000000 可能更保險(xiǎn)一些。

色偷偷精品伊人,欧洲久久精品,欧美综合婷婷骚逼,国产AV主播,国产最新探花在线,九色在线视频一区,伊人大交九欧美,1769亚洲,黄色成人av

Kylin Memcached IO 線(xiàn)程死亡診斷