日常Bug排查-集群逐步失去響應
前言
日常Bug排查系列都是一些簡單Bug排查。筆者將在這里介紹一些排查Bug的簡單技巧，同時順便積累素材_
Bug現(xiàn)場
最近碰到一個產(chǎn)線問題，表現(xiàn)為某個應用集群所有的節(jié)點全部下線了。導致上游調(diào)用全部報錯。而且從時間線分析來看。這個應用的節(jié)點是逐步失去響應的。因為請求量較小，直到最后一臺也失去響應后，才發(fā)現(xiàn)這個集群有問題。
線程逐步耗盡
筆者觀察了下監(jiān)控，發(fā)現(xiàn)每臺機器的BusyThread從上次發(fā)布開始就逐步增長，一直到BusyThread線程數(shù)達到200才停止，而這個時間和每臺機器從注冊中心中摘除的時間相同。看了下代碼，其配置的最大處理請求線程數(shù)就是200。
查看線程棧
很容易的，我們就想到去觀察相關機器的線程棧。發(fā)現(xiàn)其所有的的請求處理線程全部Block在com.google.common.util.concurrent.SettableFuture的不同實例上。卡住的堆棧如下所示：
at sun.misc.Unsafe.park (Native Method: )
at java.util.concurrent.locks.LockSupport.park (LockSupport.java: 175)
at com.google.common.util.concurrent.AbstractFuture.get (AbstractFuture.java: 469)
at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get (AbstractFuture.java: 76)
at com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly (Uninterruptibles.java: 142)
at com.google.common.cache.LocalCache$LoadingValueReference.waitForValue (LocalCache.java: 3661)
at com.google.common.cache.LocalCache$Segment.waitForLoadingValue (LocalCache.java: 2315)
at com.google.common.cache.LocalCache$Segment.get (LocalCache.java: 2202)
at com.google.common.cache.LocalCache.get (LocalCache.java: 4053)
at com.google.common.cache.LocalCache.getOrLoad (LocalCache.java: 4057)
at com.google.common.cache.LocalCache$LocalLoadingCache.get (LocalCache.java: 4986)
at com.google.common.cache.ForwardingLoadingCache.get (ForwardingLoadingCache.java: 45)
at com.google.common.cache.ForwardingLoadingCache.get (ForwardingLoadingCache.java: 45)
at com.google.common.cache.ForwardingLoadingCache.get
......
at com.XXX.business.getCache
......
從GuavaCache獲取緩存為什么會被卡住
GuavaCache是一個非常成熟的組件了，為什么會卡住呢？使用的姿勢不對？于是，筆者翻了翻使用GuavaCache的源代碼。其簡化如下：
private void initCache() {
ExecutorService executor = new ThreadPoolExecutor(1, 1,
60, TimeUnit.SECONDS,
new ArrayBlockingQueue<>(50), // 注意這個QueueSize
new NamedThreadFactory(String.format("cache-reload-%s")),
(r, e) -> {
log.warn("cache reload rejected by threadpool!"); // 注意這個reject策略
});
this.executorService = MoreExecutors.listeningDecorator(executor);
cache = CacheBuilder.newBuilder().maximumSize(100) // 注意這個最大值
.refreshAfterWrite(1, TimeUnit.DAYS).build(new CacheLoader<K, V>() {
@Override
public V load(K key) throws Exception {
return innerLoad(key);
}
@Override
public ListenableFuture<V> reload(K key, V oldValue) throws Exception {
ListenableFuture<V> task = executorService.submit(() -> {
try {
return innerLoad(key);
} catch (Exception e) {
LogUtils.printErrorLog(e, String.format("重新加載緩存失敗,key:%s", key));
return oldValue;
}
});
return task;
}
});
}
這段代碼事實上寫的還是不錯的，其通過重載reload方法并在加載后段緩存出問題的時候使用old Value。保證了即使獲取緩存的后段存儲出問題了，依舊不會影響到我們緩存的獲取。邏輯如下所示:
那么為什么會卡住呢？一時間看不出什么問題。那么我們就可以從系統(tǒng)的日志中去尋找蛛絲馬跡。
日志
對應時間點日志空空如也
對于這種逐漸失去響應的，我們尋找日志的時候一般去尋找源頭。也就是第一次出現(xiàn)卡在SettableFuture的時候發(fā)生了什么。由于我們做了定時的線程棧采集，那么很容易的，筆者挑了一臺機器找到了3天之前第一次發(fā)生線程卡住的時候，grep下對應的線程名，只發(fā)現(xiàn)了一個請求過來到了這個線程然后卡住了，后面就什么日志都不輸出了。
異步緩存的日志
繼續(xù)回顧上面的代碼，代碼中緩存的刷新是異步執(zhí)行的，很有可能是異步執(zhí)行的時候出錯了。再grep異步執(zhí)行的相關關鍵詞“重新加載緩存失敗”，依舊什么都沒有。線索又斷了。
繼續(xù)往前追溯
當所有線索都斷了的情況下，我們可以翻看時間點前后的整體日志，看下有沒有異常的點以獲取靈感。往前多翻了一天的日志，然后一條線程池請求被拒絕的日志進入了筆者的視野。
cache reload rejected by threadpool!
看到這條日志的一瞬間，筆者立馬就想明白了。GuavaCache的reload請求不是出錯了，而是被線程池給丟了。在reload請求完成之后，GuavaCache會對相應的SettableFuture做done的動作以喚醒等待的線程。而由于我們的Reject策略只打印了日志，并沒有做done的動作，導致我們請求Cache的線程一直在卡waitForValue上面。如下圖所示，左邊的是正常情況，右邊的是異常情況。
為什么會觸發(fā)線程池拒絕策略
注意我們初始化線程池的源代碼
ExecutorService executor = new ThreadPoolExecutor(1, 1,
60, TimeUnit.SECONDS,
new ArrayBlockingQueue<>(50), // 注意這個QueueSize
new NamedThreadFactory(String.format("cache-reload-%s")),
(r, e) -> {
log.warn("cache reload rejected by threadpool!"); // 注意這個reject策略
});
這個線程池是個單線程線程池，而且Queue只有50，一旦遇到同時過來的請求大于50個，就很容易觸發(fā)拒絕策略。
源碼分析
好了，這時候我們就可以上一下GuavaCache的源代碼了。
V get(K key, int hash, CacheLoader<? super K, V> loader) throws ExecutionException {
checkNotNull(key);
checkNotNull(loader);
try {
if (count != 0) { // read-volatile
// don't call getLiveEntry, which would ignore loading values
ReferenceEntry<K, V> e = getEntry(key, hash);
if (e != null) {
long now = map.ticker.read();
V value = getLiveValue(e, now);
if (value != null) {
recordRead(e, now);
statsCounter.recordHits(1);
// scheduleRefresh中一旦Value不為null，就直接返回舊值
return scheduleRefresh(e, key, hash, value, now, loader);
}
ValueReference<K, V> valueReference = e.getValueReference();
// 如果當前Value還在loading，則等loading完畢
if (valueReference.isLoading()) {
// 這次的Bug就一直卡在loadingValue上
return waitForLoadingValue(e, key, valueReference);
}
}
}
// at this point e is either null or expired;
return lockedGetOrLoad(key, hash, loader);
} catch (ExecutionException ee) {
......
}
為什么沒有直接返回oldValue而是卡住
等等，在上面的GuavaCache源代碼里面。一旦緩存有值之后，肯定是立馬返回了。對應這段代碼。
if (value != null) {
recordRead(e, now);
statsCounter.recordHits(1);
// scheduleRefresh中一旦Value不為null，就直接返回舊值
return scheduleRefresh(e, key, hash, value, now, loader);
}
所以就算異步刷新請求被線程池Reject掉了。它也不會講原來緩存中的值給刪掉。業(yè)務線程也不應該卡住。那么這個卡住是什么原因呢？為什么緩存中沒值沒有觸發(fā)load而是等待valueReference有沒有加載完畢呢。
稍加思索之后，筆者就找到了原因，因為上述那段代碼中設置了緩存的maxSize。一旦超過maxSize，一部分數(shù)據(jù)就被驅(qū)逐掉了，而如果這部分數(shù)據(jù)恰好就是線程池Reject掉請求的數(shù)據(jù)，那么就會進值為空同時需要等待valueReference loading的代碼分支，從而造成卡住的現(xiàn)象。讓我們看一下源代碼：
localCache.put //
|->evictEntries
|->removeEntry
|->removeValueFromChain
ReferenceEntry<K,V> removeValueFromChain(...) {
......
if(valueReference.isLoading()){
// 設置原值為null
valueReference.notifyNewValue(null);
return first;
}else {
removeEntryFromChain(first,entry)
}
}
我們看到，代碼中valueReference.isLoading()的判斷，一旦當前value還處于加載狀態(tài)中，那么驅(qū)逐的時候只會將對應的entry(key)項設置為null而不會刪掉。這樣，在下次這個key的緩存被訪問的時候自然就走到了value為null的分支，然后就看到當前的valueReference還處于loading狀態(tài)，最后就會等待那個由于被線程reject而永遠不會done的future，最后就會導致這個線程卡住。邏輯如下圖所示:
什么是逐漸失去響應
因為業(yè)務的實際緩存key的項目是大于maxSize的。而一開始系統(tǒng)啟動后加載的時候緩存的cache并沒有達到最大值，所以這時候被線程池reject掉相應的刷新請求依舊能夠返回舊值。但一旦出現(xiàn)了大于緩存cache最大Size的數(shù)據(jù)導致一些項被驅(qū)逐后，只要是一個請求去訪問這些緩存項都會被卡住。但很明顯的，能夠被驅(qū)逐出去的舊緩存肯定是不常用的緩存(默認LRU緩存策略)，那么就看這個不常用的數(shù)據(jù)的流量到底是在哪臺機器上最多，那么哪臺機器就是最先失去響應的了。
總結
雖然這是個較簡單的問題，排查的時候也是需要一定的思路的，尤其是發(fā)生問題的時間點并往前追溯到第一個不同尋常的日志這個點，這個往往是我們破局的手段。GuavaCache雖然是個使用非常廣泛的緩存工具，但不合理的配置依舊會導致災難性的后果。
浙公網(wǎng)安備 33010602011771號