点击上方“朱小厮的博客”，选择“设为星标”
后台回复"书"，获取
后台回复“k8s”，可领取k8s资料
| 问题
请求被限流
之前的文章提到过我们服务使用Hystrix进行服务限流，使用的是信号量方式，并根据接口的响应时间和服务的峰值QPS设置了限流的配额。
限流配额的计算方式为：
我们接口单机单个接口的峰值QPS为1000，平均影响时长15ms，我们认为Hystrix的信号量是并发量，那么一个信号量在一秒内能允许1000ms/15ms~66个请求通过，那么服务1000QPS配置15个信号量就足够了。
当然这是在忽略上下文切换和GC时间的情况下，考虑上这些因素，每个并发量每秒能服务的时长约为900ms，用同样的公式计算所需要的信号量是17，为了应付突发流量，我将这个值设置为了30。
本以为这样就高枕无忧了，没想到看错误日志中偶然发现了有报错：
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里发现了奇怪的日志。
2020
-
03
-
17
T13:
01
:
26.281
+
0800
: 
89732.109
: Application time: 
2.1373599
 seconds

2020
-
03
-
17
T13:
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
-
17
T13:
01
:
26.310
+
0800
: 
89732.137
: Application time: 
0.0016111
 seconds

2020
-
03
-
17
T13:
01
:
26.336
+
0800
: 
89732.163
: [GC (Allocation Failure) 
2020
-
03
-
17
T13:
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

: 
6920116
K->
214972
K(
7549760
K), 
0.0739801
 secs] 
9292943
K->
2593702
K(
11744064
K), 
0.0756263
 secs] [Times: user=
0.65
 sys=
0.23
, real=
0.08
 secs]

2020
-
03
-
17
T13:
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
-
17
T13:
01
:
26.412
+
0800
: 
89732.239
: Application time: 
0.0001873
 seconds

2020
-
03
-
17
T13:
01
:
26.438
+
0800
: 
89732.265
: [GC (GCLocker Initiated GC) 
2020
-
03
-
17
T13:
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

: 
217683
K->
215658
K(
7549760
K), 
0.0548512
 secs] 
2596413
K->
2594388
K(
11744064
K), 
0.0561721
 secs] [Times: user=
0.49
 sys=
0.18
, real=
0.05
 secs]

2020
-
03
-
17
T13:
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一次发送过来，而我们设置的信号量限制会作出什么反应呢？
@Override
publicbooleantryAcquire()
{

int
 currentCount = count.incrementAndGet();

if
 (currentCount > numberOfPermits.get()) {

            count.decrementAndGet();

returnfalse
;

        } 
else
 {

returntrue
;

        }

    }

上面是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()的超时时间来控制接口的最大响应时间，和信号量比，没有哪一种方式更好。

| 小结

解决了一个服务隐藏了很久的问题，又积累了排查此类问题的经验，得到了问题不能只从一个角度看待的教训，还是比较开心的。
当然，也又一次证明了看源码的重要性，遇到问题追一追源码，总会有些收益。
文章来源：https://zhenbianshu.github.io/2020/03/how_to_cal_isolation_limit.html
想知道更多？扫描下面的二维码关注我
后台回复"技术"，加入技术群
后台回复“k8s”，可领取k8s资料
【精彩推荐】
继续阅读
阅读原文
关键词
问题
接口
状态
线程池
时间点