如何计算服务限流的配额

| 问题

请求被限流

之前的文章提到过我们服务使用Hystrix进行服务限流,使用的是信号量方式,并根据接口的响应时间和服务的峰值QPS设置了限流的配额。

限流配额的计算方式为:

我们接口单机单个接口的峰值QPS为1000,平均影响时长15ms,我们认为Hystrix的信号量是并发量,那么一个信号量在一秒内能允许1000ms/15ms~66个请求通过,那么服务1000QPS配置15个信号量就足够了。

当然这是在忽略上下文切换和GC时间的情况下,考虑上这些因素,每个并发量每秒能服务的时长约为900ms,用同样的公式计算所需要的信号量是17,为了应付突发流量,我将这个值设置为了30。

本以为这样就高枕无忧了,没想到看错误日志中偶然发现了有报错:

代码语言:javascript
复制
HystrixRuntimeException occurred! , failureType:REJECTED_SEMAPHORE_EXECUTION, message:apiHystrixKey could not acquire a semaphore for execution and fallback failed.

我把信号量配置提高到了50,没想到还是没看到问题有明显好转,这就比较诡异了。

| 解决

排查步骤

首先我列了一下排查的步骤,也整理一下出现这种问题的可能。

  1. 看正常请求的平均耗时,排除真实block的可能。接口平均耗时17ms,QPS为1000,如果代码都被block在某处,接口耗时一定会突增。
  2. 查看一下hystrix代码看是否可能有情况导致信号量未释放。简单扫了一遍hystrix相关代码,信号量的释放在请求结束的callback里,如果有泄漏,一定会导致可用信号量越来越少,最终为0。
  3. 写一个小demo,压测看是否能复现。在demo里运行,问题只在刚启动服务未初始化完成时复现,后续就平稳了。
Jdk的Bug ?

从整体上看不出来,就只好从微观时间点上看了,可这个问题出现是一瞬间的事,jstack也无能为力,虽然jmc倒是合适,但它部署有点费劲,而且还会在观察的时候影响到服务,于是优先从历史时间点上排查。

从错误日志里找了一个服务拒绝数较多的时间点,再观察服务当时的状态。错误日志上除了一些请求被拒绝的报错外就没有其他的了,但我在gclog里发现了奇怪的日志。

代码语言:javascript
复制
2020-03-17T13:01:26.281+0800: 89732.109: Application time: 2.1373599 seconds
2020-03-17T13:01:26.308+0800: 89732.136: Total time for which application threads were stopped: 0.0273134 seconds, Stopping threads took: 0.0008935 seconds
2020-03-17T13:01:26.310+0800: 89732.137: Application time: 0.0016111 seconds
2020-03-17T13:01:26.336+0800: 89732.163: [GC (Allocation Failure) 2020-03-17T13:01:26.336+0800: 89732.164: [ParNew
Desired survivor size 429490176 bytes, new threshold 4 (max 4)
- age 1: 107170544 bytes, 107170544 total
- age 2: 38341720 bytes, 145512264 total
- age 3: 6135856 bytes, 151648120 total
- age 4: 152 bytes, 151648272 total
: 6920116K->214972K(7549760K), 0.0739801 secs] 9292943K->2593702K(11744064K), 0.0756263 secs] [Times: user=0.65 sys=0.23, real=0.08 secs]
2020-03-17T13:01:26.412+0800: 89732.239: Total time for which application threads were stopped: 0.1018416 seconds, Stopping threads took: 0.0005597 seconds
2020-03-17T13:01:26.412+0800: 89732.239: Application time: 0.0001873 seconds
2020-03-17T13:01:26.438+0800: 89732.265: [GC (GCLocker Initiated GC) 2020-03-17T13:01:26.438+0800: 89732.265: [ParNew
Desired survivor size 429490176 bytes, new threshold 4 (max 4)
- age 1: 77800 bytes, 77800 total
- age 2: 107021848 bytes, 107099648 total
- age 3: 38341720 bytes, 145441368 total
- age 4: 6135784 bytes, 151577152 total
: 217683K->215658K(7549760K), 0.0548512 secs] 2596413K->2594388K(11744064K), 0.0561721 secs] [Times: user=0.49 sys=0.18, real=0.05 secs]
2020-03-17T13:01:26.495+0800: 89732.322: Total time for which application threads were stopped: 0.0824542 seconds, Stopping threads took: 0.0005238 seconds

我看到连续发生了两次YGC,它们之间的间隔才0.0001873s,可以认为是进行了一次很长时间的GC,总耗时达到了160ms。再仔细观察第二次GC时的内存分布,可以看到它作为一次ParNew GC,发生时eden区的内存才使用了200M,这就不符合常理了。

再看GC发生的原因,日志里标识的是GCLocker Initiated GC。在使用 JNI操作字符串或数组时,为了防止GC导致数组指针发生偏移,JVM实现了GCLocker,它会在发生GC的时候阻止程序进入临界区,并在最后一个临界区内的线程退出时,发生一次GCLocker GC。

至于这次的GC,是JDK的一个Bug,JDK-8048556,具体原因可以看这篇博客:一次不必要的GCLocker-initiated young GC。

而我们的Java版本低于修复版本,出现这种问题实属正常,可是,这个问题就归究于jdk的bug吗?升级了jdk版本就一定会好吗?

“平均”的陷阱

重新来计算一下,即使JVM每秒都有160ms在进行GC,可系统有服务时间也还有840ms,使用上文中的公式,信号量的还是完全足够的。

一时想不明白,出去倒了杯水,走了走,忽然想到原来自己站错了角度。我一直用秒作为时间的基本单位,用一秒的平均状态来代表系统的整体状态,认为一整秒内如果没有问题,服务就不应该会发生问题,可是忽略了时间从来不是一秒一秒进行的。

试想,如果平稳运行的服务,忽然发生了一次160ms的GC,那么这 160ms内的请求会平均分配到剩余840ms内吗?并不会,它们会挤在第161ms一次发送过来,而我们设置的信号量限制会作出什么反应呢?

代码语言:javascript
复制
    @Override
    public boolean tryAcquire() {
        int currentCount = count.incrementAndGet();
        if (currentCount > numberOfPermits.get()) {
            count.decrementAndGet();
            return false;
        } else {
            return true;
        }
    }

上面是Hystrix源码中获取信号量的代码,可以发现,代码里没有任何block,如果当前使用的信号量大于配置值,就会直接拒绝。

这样就说得通了,如果进行了160ms的GC,再加上请求处理的平均耗时是15ms,那系统就有可能在瞬间堆积1000q/s * 0.175s = 175的请求,如果信号量不足,请求就会被直接拒绝了。

也就是说即使jdk的bug修复了,信号量限制最少还是要设置为95才不会拒绝请求。

| 限流配额的正确计算方式

概念

那么限流配额的正确计算方式是怎样的呢?

在此之前我们要明确设置的限流配额都是并发量,它的单位是:个,这一点要区分于我们常用的服务压力指标QPS,因为QPS是指一秒内的请求数,它的单位是 个/S,由于单位不同,它们是不能直接比较的,需要并发量再除以一个时间单位才可以。

正确的公式应当是:并发量(个)/单个请求耗时(s) > QPS(个/s)。

但由于Java GC的特性,我们不得不考虑GC期间请求堆积的可能,要处理这种情况,第一种是直接拒绝,像Hystrix的实现(有点坑),第二种是做一些缓冲。

信号量缓冲

其实信号量并不是无法做缓冲的,只是Hystrix 内的”信号量”是自己实现的,比较low。

比较”正统”的方式是使用jdk里的java.util.concurrent.Semaphore,它获取信号量有两种方式,第一种是tryAcquire(),这类似于Hystrix的实现,是不会block的,如果当前信号量被占用或不足,会返回false。第二种是使用acquire()方法,它没有返回值,意思是方法只有在拿到信号量时才会返回,而这个时间是不确定的。

我猜想这可能也是Hystrix不采用这种方式的原因,毕竟如果使用FairSync会有很多拿到信号量发现接口超时再抛弃的行为,而使用UnFairSync又会使接口的影响时长无法确定。

线程池缓冲

线程池的缓冲比信号量要灵活得多,设置更大的maximumPoolSize或BlockingQueue都可以,设置rejectHandler也是很好的办法。

只是使用线程池会有上下文切换的损耗,而且应对突发流量时,线程池的扩容也比较捉急。

考虑到它的灵活性,以及可以通过Future.get()的超时时间来控制接口的最大响应时间,和信号量比,没有哪一种方式更好。

| 小结

解决了一个服务隐藏了很久的问题,又积累了排查此类问题的经验,得到了问题不能只从一个角度看待的教训,还是比较开心的。

当然,也又一次证明了看源码的重要性,遇到问题追一追源码,总会有些收益。