背景介紹
服務在上線一段時間後,就出現了 Dubbo 調用異常,異常資訊為: The service using threads greater than <dubbo:service executes=“128” /> limited。這樣就導緻功能不可用,由于該接口在實際中的并發量并不高,是以很詭異,在經過一段分析後,最終得以解決。
問題分析
dubbo:service executes=“128” 表示:服務提供者每服務每方法最大可并行執行請求數,可以通過 dubbo.provider.executes=128 或者 dubbo.service.executes=128 來配置,差別在于應用範圍不同。也就是說某一個方法的并行請求數已經達到了 128 個,但是實際情況下該接口并沒有太大的并發,而且後面的每次請求都會失敗。由于是對外暴露是 HTTP 接口,通過 kong 的請求日志也驗證了并發量也并沒有達到 128。于是就要從線程、堆 dump 檔案和源碼等方面詳細的分析了。
線程 dump 檔案分析
看服務線程 dump 檔案的目的是為了看是否有線程在這個方法上處于阻塞或運作狀态。通過指令: jstack pid 輸出線程資訊,經過檢視發現并沒有線程在這個方法上阻塞或運作,是以也印證了問題并不是由于并發請求數超過了128 導緻的。
源碼分析
線上程資訊上并不能找到太多有用資訊,是以要深入源碼解析看異常是如何産生的。通過異常資訊可以定位到源碼類 ExecuteLimitFilter 中的 invoke 方法:
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
URL url = invoker.getUrl();
String methodName = invocation.getMethodName();
int max = url.getMethodParameter(methodName, EXECUTES_KEY, 0);
if (!RpcStatus.beginCount(url, methodName, max)) {
throw new RpcException(RpcException.LIMIT_EXCEEDED_EXCEPTION,
"Failed to invoke method " + invocation.getMethodName() + " in provider " +
url + ", cause: The service using threads greater than <dubbo:service executes=\"" + max +
"\" /> limited.");
}
invocation.put(EXECUTELIMIT_FILTER_START_TIME, System.currentTimeMillis());
try {
return invoker.invoke(invocation);
} catch (Throwable t) {
if (t instanceof RuntimeException) {
throw (RuntimeException) t;
} else {
throw new RpcException("unexpected exception when ExecuteLimitFilter", t);
}
}
}
具體的判斷是在
RpcStatus.beginCount(url, methodName, max)
語句,再進入具體的方法:
public static boolean beginCount(URL url, String methodName, int max) {
max = (max <= 0) ? Integer.MAX_VALUE : max;
RpcStatus appStatus = getStatus(url);
RpcStatus methodStatus = getStatus(url, methodName);
if (methodStatus.active.get() == Integer.MAX_VALUE) {
return false;
}
if (methodStatus.active.incrementAndGet() > max) {
methodStatus.active.decrementAndGet();
return false;
} else {
appStatus.active.incrementAndGet();
return true;
}
}
通過代碼我們可以得出,程式主要是判斷
AtomicInteger active
變量的值是否大于設定的門檻值,如果大于的話就傳回 false,上層調用就會抛出
The service using threads greater than <dubbo:service executes=“128“ /> limited
異常。
既然方法調用的并發數并沒有超過設定值,那麼就有可能是方法正在請求數 active 變量出了問題,就需要檢視下 active 值現在是多少。
堆轉儲快照 dump 檔案分析
要想檢視 active 的值,就需要堆轉儲快照 dump 檔案,通過指令
jmap -dump:format=b,file=eclipes.bin pid
導出 dump 檔案。然後使用 Eclipse 的 MAT(Memory Analyzer Tool) 工具分析檔案。
先通過 RpcStatus 類名搜尋,可以看到下圖中左邊類中的兩個靜态變量 METHOD_STATISTICS、SERVICE_STATISTICS。 METHOD_STATISTICS map中就存着每個方法調用狀态。
然後在 METHOD_STATISTICS 右鍵 -> List objects -> with outgoing references 檢視變量的具體内容,再通過方法名找到對應的方法的 active,如下:
從圖中看出 active = 128,确實已經達到設定的門檻值了,是以調用方法會直接抛出異常。那問題是為什麼這個值沒有降下去呢?再看代碼,每次方法調用完都會調用 endCount 方法來減少 active 值。
private static void endCount(RpcStatus status, long elapsed, boolean succeeded) {
status.active.decrementAndGet();
status.total.incrementAndGet();
status.totalElapsed.addAndGet(elapsed);
if (status.maxElapsed.get() < elapsed) {
status.maxElapsed.set(elapsed);
}
if (succeeded) {
if (status.succeededMaxElapsed.get() < elapsed) {
status.succeededMaxElapsed.set(elapsed);
}
} else {
status.failed.incrementAndGet();
status.failedElapsed.addAndGet(elapsed);
if (status.failedMaxElapsed.get() < elapsed) {
status.failedMaxElapsed.set(elapsed);
}
}
}
active 值沒有減少就有可能是沒有調用 endCount 方法,沒有調用 endCount 方法就可能是 RPC 遠端調用整個流程沒有走完。再分析業務代碼後找到了問題的關鍵,服務提供方是異步處理請求的,在接收到 RPC 遠端請求後,會存儲異步上下文 AsyncContext,然後等待擷取結果後才異步寫回請求放。如果結果一直沒有得到,超過了一定的時間會清除 AsyncContext。問題就出在了清除 AsyncContext 緩存這一步,清除緩存時要寫結果回去
asyncContext.write(object);
,然後就會調用到 endCount 方法。
總結
經過上面的一系列分析,最終發現清除上下文時要寫結果來完成一次完整的鍊路調用。這也提醒我們在做相關資源的緩存時,清除緩存前要做好相關的結尾處理。