Part1問(wèn)題

請(qǐng)求被限流

之前提到過(guò)我們服務(wù)使用 Hystrix 進(jìn)行服務(wù)限流，使用的是信號(hào)量方式，并根據(jù)接口的響應(yīng)時(shí)間和服務(wù)的峰值 QPS 設(shè)置了限流的配額。

限流配額的計(jì)算方式為：

我們接口單機(jī)單個(gè)接口的峰值 QPS 為 1000，平均影響時(shí)長(zhǎng) 15ms，我們認(rèn)為 Hystrix 的信號(hào)量是并發(fā)量，那么一個(gè)信號(hào)量在一秒內(nèi)能允許 1000ms/15ms~66 個(gè)請(qǐng)求通過(guò)，那么服務(wù) 1000QPS 配置 15 個(gè)信號(hào)量就足夠了。

當(dāng)然這是在忽略上下文切換和 GC 時(shí)間的情況下，考慮上這些因素，每個(gè)并發(fā)量每秒能服務(wù)的時(shí)長(zhǎng)約為 900ms，用同樣的公式計(jì)算所需要的信號(hào)量是 17，為了應(yīng)付突發(fā)流量，我將這個(gè)值設(shè)置為了 30。

本以為這樣就高枕無(wú)憂了，沒(méi)想到看錯(cuò)誤日志中偶然發(fā)現(xiàn)了有報(bào)錯(cuò)：

HystrixRuntimeException occurred! , failureType:REJECTED_SEMAPHORE_EXECUTION, message:apiHystrixKey could not acquire a semaphore for execution and fallback failed.

我把信號(hào)量配置提高到了 50，沒(méi)想到還是沒(méi)看到問(wèn)題有明顯好轉(zhuǎn)，這就比較詭異了。

Part2解決

排查步驟

首先我列了一下排查的步驟，也整理一下出現(xiàn)這種問(wèn)題的可能。

1. 看正常請(qǐng)求的平均耗時(shí)，排除真實(shí) block 的可能。接口平均耗時(shí) 17ms，QPS 1000，如果代碼都被 block 在某處，接口耗時(shí)一定會(huì)突增。
2. 查看一下 hystrix 代碼看是否可能有情況導(dǎo)致信號(hào)量未釋放。簡(jiǎn)單掃了一遍 hystrix 相關(guān)代碼，信號(hào)量的釋放在請(qǐng)求結(jié)束的 callback 里，如果有泄漏，一定會(huì)導(dǎo)致可用信號(hào)量越來(lái)越少，最終為 0。
3. 寫(xiě)一個(gè)小 demo，壓測(cè)看是否能復(fù)現(xiàn)。在 demo 里運(yùn)行，問(wèn)題只在剛啟動(dòng)服務(wù)未初始化完成時(shí)復(fù)現(xiàn)，后續(xù)就平穩(wěn)了。

Jdk 的 Bug ？

從整體上看不出來(lái)，就只好從微觀時(shí)間點(diǎn)上看了，可這個(gè)問(wèn)題出現(xiàn)是一瞬間的事，jstack 也無(wú)能為力，雖然 jmc 倒是合適，但它部署有點(diǎn)費(fèi)勁，而且還會(huì)在觀察的時(shí)候影響到服務(wù)，于是優(yōu)先從歷史時(shí)間點(diǎn)上排查。

從錯(cuò)誤日志里找了一個(gè)服務(wù)拒絕數(shù)校多的時(shí)間點(diǎn)，再觀察服務(wù)當(dāng)時(shí)的狀態(tài)。錯(cuò)誤日志上除了一些請(qǐng)求被拒絕的報(bào)錯(cuò)外就沒(méi)有其他的了，但我在 gclog 里發(fā)現(xiàn)了奇怪的日志。

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

我看到連續(xù)發(fā)生了兩次 YGC，它們之間的間隔才 0.0001873s，可以認(rèn)為是進(jìn)行了一次很長(zhǎng)時(shí)間的 GC，總耗時(shí)達(dá)到了 160ms。再仔細(xì)觀察第二次 GC 時(shí)的內(nèi)存分布，可以看到它作為一次 ParNew GC，發(fā)生時(shí) eden 區(qū)的內(nèi)存才使用了 200M，這就不符合常理了。

再看 GC 發(fā)生的原因，日志里標(biāo)識(shí)的是 GCLocker Initiated GC。在使用 JNI 操作字符串或數(shù)組時(shí)，為了防止 GC 導(dǎo)致數(shù)組指針發(fā)生偏移，JVM 實(shí)現(xiàn)了 GCLocker，它會(huì)在發(fā)生 GC 的時(shí)候阻止程序進(jìn)入臨界區(qū)，并在最后一個(gè)臨界區(qū)內(nèi)的線程退出時(shí)，發(fā)生一次 GCLocker GC。

至于這次的 GC，是 JDK 的一個(gè) Bug

而我們的 Java 版本低于修復(fù)版本，出現(xiàn)這種問(wèn)題實(shí)屬正常，可是，這個(gè)問(wèn)題就歸究于 jdk 的 bug 嗎？升級(jí)了 jdk 版本就一定會(huì)好嗎？

歡迎關(guān)注公眾號(hào)"Java學(xué)習(xí)之道"，查看更多干貨！

“平均”的陷阱

重新來(lái)計(jì)算一下，即使 JVM 每秒都有 160ms 在進(jìn)行 GC，可系統(tǒng)有服務(wù)時(shí)間也還有 840ms，使用上文中的公式，信號(hào)量的還是完全足夠的。

一時(shí)想不明白，出去倒了杯水，走了走，忽然想到原來(lái)自己站錯(cuò)了角度。我一直用秒作為時(shí)間的基本單位，用一秒的平均狀態(tài)來(lái)代表系統(tǒng)的整體狀態(tài)，認(rèn)為一整秒內(nèi)如果沒(méi)有問(wèn)題，服務(wù)就不應(yīng)該會(huì)發(fā)生問(wèn)題，可是忽略了時(shí)間從來(lái)不是一秒一秒進(jìn)行的。

試想，如果平穩(wěn)運(yùn)行的服務(wù)，忽然發(fā)生了一次 160ms 的 GC，那么這 160ms 內(nèi)的請(qǐng)求會(huì)平均分配到剩余 840ms 內(nèi)嗎？并不會(huì)，它們會(huì)擠在第 161ms 一次發(fā)送過(guò)來(lái)，而我們?cè)O(shè)置的信號(hào)量限制會(huì)作出什么反應(yīng)呢？

@Override
public boolean tryAcquire() {
    int currentCount = count.incrementAndGet();
    if (currentCount > numberOfPermits.get()) {
        count.decrementAndGet();
        return false;
    } else {
        return true;
    }
}

上面是 Hystrix 源碼中獲取信號(hào)量的代碼，可以發(fā)現(xiàn)，代碼里沒(méi)有任何 block，如果當(dāng)前使用的信號(hào)量大于配置值，就會(huì)直接拒絕。

這樣就說(shuō)得通了，如果進(jìn)行了 160ms 的 GC，再加上請(qǐng)求處理的平均耗時(shí)是 15ms，那系統(tǒng)就有可能在瞬間堆積 1000q/s * 0.175s = 175 的請(qǐng)求，如果信號(hào)量不足，請(qǐng)求就會(huì)被直接拒絕了。

也就是說(shuō)即使 jdk 的 bug 修復(fù)了，信號(hào)量限制最少還是要設(shè)置為 95 才不會(huì)拒絕請(qǐng)求。

Part3限流配額的正確計(jì)算方式

概念

那么限流配額的正確計(jì)算方式是怎樣的呢？

在此之前我們要明確設(shè)置的限流配額都是并發(fā)量，它的單位是 個(gè)，這一點(diǎn)要區(qū)分于我們常用的服務(wù)壓力指標(biāo) QPS，因?yàn)?QPS 是指一秒內(nèi)的請(qǐng)求數(shù)，它的單位是 個(gè)/S，由于單位不同，它們是不能直接比較的，需要并發(fā)量再除以一個(gè)時(shí)間單位才可以。

正確的公式應(yīng)當(dāng)是 并發(fā)量(個(gè))/單個(gè)請(qǐng)求耗時(shí)(s) > QPS(個(gè)/s)。

但由于 Java GC 的特性，我們不得不考慮 GC 期間請(qǐng)求堆積的可能，要處理這種情況，第一種是直接拒絕，像 Hystrix 的實(shí)現(xiàn)（有點(diǎn)坑），第二種是做一些緩沖。

信號(hào)量緩沖

其實(shí)信號(hào)量并不是無(wú)法做緩沖的，只是 Hystrix 內(nèi)的”信號(hào)量”是自己實(shí)現(xiàn)的，比較 low。

比較”正統(tǒng)”的方式是使用 jdk 里的 java.util.concurrent.Semaphore，它獲取信號(hào)量有兩種方式，第一種是 tryAcquire()，這類(lèi)似于 Hystrix 的實(shí)現(xiàn)，是不會(huì) block 的，如果當(dāng)前信號(hào)量被占用或不足，會(huì)返回 false。第二種是使用 acquire() 方法，它沒(méi)有返回值，意思是方法只有在拿到信號(hào)量時(shí)才會(huì)返回，而這個(gè)時(shí)間是不確定的。

我猜想這可能也是 Hystrix 不采用這種方式的原因，畢竟如果使用 FairSync 會(huì)有很多拿到信號(hào)量發(fā)現(xiàn)接口超時(shí)再拋棄的行為，而使用 UnFairSync 又會(huì)使接口的影響時(shí)長(zhǎng)無(wú)法確定。

線程池緩沖

線程池的緩沖比信號(hào)量要靈活得多，設(shè)置更大的 maximumPoolSize 或 BlockingQueue 都可以，設(shè)置 rejectHandler 也是很好的辦法。

只是使用線程池會(huì)有上下文切換的損耗，而且應(yīng)對(duì)突發(fā)流量時(shí)，線程池的擴(kuò)容也比較拙技。

考慮到它的靈活性，以及可以通過(guò) Future.get() 的超時(shí)時(shí)間來(lái)控制接口的最大響應(yīng)時(shí)間，和信號(hào)量比，沒(méi)有哪一種方式更好。

Part4小結(jié)

解決了一個(gè)服務(wù)隱藏了很久的問(wèn)題，又積累了排查此類(lèi)問(wèn)題的經(jīng)驗(yàn)，得到了問(wèn)題不能只從一個(gè)角度看待的教訓(xùn)，還是比較開(kāi)心的。

當(dāng)然，也又一次證明了看源碼的重要性，遇到問(wèn)題追一追源碼，總會(huì)有些收益。