深度解析 dubbo 服务调用异常：The service using threads greater than ＜dubbo:service executes=“128“ /＞ limited

背景介绍

服务在上线一段时间后，就出现了 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 方法。

总结

经过上面的一系列分析，最终发现清除上下文时要写结果来完成一次完整的链路调用。这也提醒我们在做相关资源的缓存时，清除缓存前要做好相关的结尾处理。