請求量突增一下，系統有效QPS為何下降很多？
原創：扣釘日記（微信公眾號ID：codelogs），歡迎分享，轉載請保留出處。
簡介
最近我觀察到一個現象，當服務的請求量突發的增長一下時，服務的有效QPS會下降很多，有時甚至會降到0，這種現象網上也偶有提到，但少有解釋得清楚的，所以這裡來分享一下問題成因及解決方案。
佇列延遲
目前的Web伺服器，如Tomcat，請求處理過程大概都類似如下：
這是Tomcat請求處理的過程，如下：
- Acceptor執行緒：執行緒名類似http-nio-8080-Acceptor-0，此執行緒用於接收新的TCP連線，並將TCP連線註冊到NIO事件中。
- Poller執行緒：執行緒名類似http-nio-8080-ClientPoller-0，此執行緒一般有CPU核數個，用於輪詢已連線的Socket，接收新到來的Socket事件（如呼叫端發請求資料了），並將活躍Socket放入exec執行緒池的請求佇列中。
- exec執行緒：執行緒名類似http-nio-8080-exec-0，此執行緒從請求佇列中取出活躍Socket，並讀出請求資料，最後執行請求的API邏輯。
這裡不用太關心Acceptor與Poller執行緒，這是nio程式設計時常見的執行緒模型，我們將重點放在exec執行緒池上，雖然Tomcat做了一些優化，但它還是從Java原生執行緒池擴充套件出來的，即有一個任務佇列與一組執行緒。
當請求量突發增長時，會發生如下的情況：
- 當請求量不大時，任務佇列基本是空的，每個請求都能得到及時的處理。
- 但當請求量突發時，任務佇列中就會有很多請求，這時排在佇列後面的請求，就會被處理得越晚，因而請求的整體耗時就會變長，甚至非常長。
可是，exec執行緒們還是在一刻不停歇的處理著請求的呀，按理說服務QPS是不會減少的呀！
簡單想想的確如此，但呼叫端一般是有超時時間設定的，不會無限等待下去，當用戶端等待超時的時候，這個請求實際上Tomcat就不用再處理了，因為就算處理了，使用者端也不會再去讀響應資料的。
因此，當佇列比較長時，佇列後面的請求，基本上都是不用再處理的，但exec執行緒池不知道啊，它還是會一如既往地處理這些請求。
當exec執行緒執行這些已超時的請求時，若又有新請求進來，它們也會排在隊尾，這導致這些新請求也會超時，所以在流量突發的這段時間內，請求的有效QPS會下降很多，甚至會降到0。
這種超時也叫做佇列延遲，但佇列在軟體系統中應用得太廣泛了，比如作業系統排程器維護了執行緒佇列，TCP中有backlog連線佇列，鎖中維護了等待佇列等等。
因此，很多系統也會存在這種現象，平時響應時間挺穩定的，但偶爾耗時很高，這種情況有很多都是佇列延遲導致的。
優化佇列延遲
知道了問題產生的原因，要優化它就比較簡單了，我們只需要讓佇列中那些長時間未處理的請求暫時讓路，讓執行緒去執行那些等待時間不長的請求即可，畢竟這些長時間未處理的請求，讓它們再等等也無防，因為使用者端可能已經超時了而不需要請求結果了，雖然這破壞了佇列的公平性，但這是我們需要的。
對於Tomcat，在springboot中，我們可以如下修改：
使用WebServerFactoryCustomizer自定義Tomcat的執行緒池，如下：
@Component
public class TomcatExecutorCustomizer implements WebServerFactoryCustomizer<TomcatServletWebServerFactory> {
@Resource
ServerProperties serverProperties;
@Override
public void customize(TomcatServletWebServerFactory factory) {
TomcatConnectorCustomizer tomcatConnectorCustomizer = connector -> {
ServerProperties.Tomcat.Threads threads = serverProperties.getTomcat().getThreads();
TaskQueue taskqueue = new SlowDelayTaskQueue(1000);
ThreadPoolExecutor executor = new org.apache.tomcat.util.threads.ThreadPoolExecutor(
threads.getMinSpare(), threads.getMax(), 60L, TimeUnit.SECONDS,
taskqueue, new CustomizableThreadFactory("http-nio-8080-exec-"));
taskqueue.setParent(executor);
ProtocolHandler handler = connector.getProtocolHandler();
if (handler instanceof AbstractProtocol) {
AbstractProtocol<?> protocol = (AbstractProtocol<?>) handler;
protocol.setExecutor(executor);
}
};
factory.addConnectorCustomizers(tomcatConnectorCustomizer);
}
}
注意，這裡還是使用的Tomcat實現的執行緒池，只是將任務佇列TaskQueue擴充套件為了SlowDelayTaskQueue，它的作用是將長時間未處理的任務移到另一個慢佇列中，待當前佇列中無任務時，再把慢佇列中的任務移回來。
為了能記錄任務入佇列的時間，先封裝了一個記錄時間的任務類RecordTimeTask，如下：
@Getter
public class RecordTimeTask implements Runnable {
private Runnable run;
private long createTime;
private long putQueueTime;
public RecordTimeTask(Runnable run){
this.run = run;
this.createTime = System.currentTimeMillis();
this.putQueueTime = this.createTime;
}
@Override
public void run() {
run.run();
}
public void resetPutQueueTime() {
this.putQueueTime = System.currentTimeMillis();
}
public long getPutQueueTime() {
return this.putQueueTime;
}
}
然後佇列的擴充套件實現如下：
public class SlowDelayTaskQueue extends TaskQueue {
private long timeout;
private BlockingQueue<RecordTimeTask> slowQueue;
public SlowDelayTaskQueue(long timeout) {
this.timeout = timeout;
this.slowQueue = new LinkedBlockingQueue<>();
}
@Override
public boolean offer(Runnable o) {
// 將任務包裝一下，目的是為了記錄任務放入佇列的時間
if (o instanceof RecordTimeTask) {
return super.offer(o);
} else {
return super.offer(new RecordTimeTask(o));
}
}
public void pullbackIfEmpty() {
// 如果佇列空了，從慢佇列中取回來一個
if (this.isEmpty()) {
RecordTimeTask r = slowQueue.poll();
if (r == null) {
return;
}
r.resetPutQueueTime();
this.add(r);
}
}
@Override
public Runnable poll(long timeout, TimeUnit unit) throws InterruptedException {
pullbackIfEmpty();
while (true) {
RecordTimeTask task = (RecordTimeTask) super.poll(timeout, unit);
if (task == null) {
return null;
}
// 請求在佇列中長時間等待，移入慢佇列中
if (System.currentTimeMillis() - task.getPutQueueTime() > this.timeout) {
this.slowQueue.offer(task);
continue;
}
return task;
}
}
@Override
public Runnable take() throws InterruptedException {
pullbackIfEmpty();
while (true) {
RecordTimeTask task = (RecordTimeTask) super.take();
// 請求在佇列中長時間等待，移入慢佇列中
if (System.currentTimeMillis() - task.getPutQueueTime() > this.timeout) {
this.slowQueue.offer(task);
continue;
}
return task;
}
}
}
邏輯其實挺簡單的，如下：
- 當任務入佇列時，包裝一下任務，記錄一下入佇列的時間。
- 然後執行緒從佇列中取出任務時，若發現任務等待時間過長，就將其移入慢佇列。
- 而pullbackIfEmpty的邏輯，就是當佇列為空時，再將慢佇列中的任務移回來執行。
為了將請求的佇列延遲記錄在access.log中，我又修改了一下Task，並加了一個Filter，如下：
- 使用ThreadLocal將佇列延遲先存起來
@Getter
public class RecordTimeTask implements Runnable {
private static final ThreadLocal<Long> WAIT_IN_QUEUE_TIME = new ThreadLocal<>();
private Runnable run;
private long createTime;
private long putQueueTime;
public RecordTimeTask(Runnable run){
this.run = run;
this.createTime = System.currentTimeMillis();
this.putQueueTime = this.createTime;
}
@Override
public void run() {
try {
WAIT_IN_QUEUE_TIME.set(System.currentTimeMillis() - this.createTime);
run.run();
} finally {
WAIT_IN_QUEUE_TIME.remove();
}
}
public void resetPutQueueTime() {
this.putQueueTime = System.currentTimeMillis();
}
public long getPutQueueTime() {
return this.putQueueTime;
}
public static long getWaitInQueueTime(){
return ObjectUtils.defaultIfNull(WAIT_IN_QUEUE_TIME.get(), 0L);
}
}
- 再在Filter中將佇列延遲取出來，放入Request物件中
@WebFilter
@Component
public class WaitInQueueTimeFilter extends HttpFilter {
@Override
public void doFilter(HttpServletRequest request, HttpServletResponse response, FilterChain chain) throws
IOException,
ServletException {
long waitInQueueTime = RecordTimeTask.getWaitInQueueTime();
// 將等待時間設定到request的attribute中，給access.log使用
request.setAttribute("waitInQueueTime", waitInQueueTime);
// 如果請求在佇列中等待了太長時間，使用者端大概率已超時，就沒有必要再執行了
if (waitInQueueTime > 5000) {
response.sendError(503, "service is busy");
return;
}
chain.doFilter(request, response);
}
}
- 然後在access.log中設定佇列延遲
server:
tomcat:
accesslog:
enabled: true
directory: /home/work/logs/applogs/java-demo
file-date-format: .yyyy-MM-dd
pattern: '%h %l %u %t "%r" %s %b %Dms %{waitInQueueTime}rms "%{Referer}i" "%{User-Agent}i" "%{X-Forwarded-For}i"'
注意，在access.log中設定%{xxx}r表示取請求xxx屬性的值，所以，%{waitInQueueTime}r就是佇列延遲，後面的ms是毫秒單位。
優化效果
我使用介面壓測工具wrk壓了一個測試介面，此介面執行時間100ms，使用1000個並行去壓，1s的超時時間，如下：
wrk -d 10d -T1s --latency http://localhost:8080/sleep -c 1000
然後，用arthas看一下執行緒池的佇列長度，如下：
[arthas@619]$ vmtool --action getInstances \
--classLoaderClass org.springframework.boot.loader.LaunchedURLClassLoader \
--className org.apache.tomcat.util.threads.ThreadPoolExecutor \
--express 'instances.{ #{"ActiveCount":getActiveCount(),"CorePoolSize":getCorePoolSize(),"MaximumPoolSize":getMaximumPoolSize(),"QueueSize":getQueue().size()} }' \
-x 2
可以看到，佇列長度遠小於1000，這說明佇列中積壓得不多。
再看看access.log，如下：
可以發現，雖然佇列延遲任然存在，但被控制在了1s以內，這樣這些請求就不會超時了，Tomcat的有效QPS保住了。
而最後面那些佇列延遲極長的請求，則是被不公平對待的請求，但只能這麼做，因為在請求量超出Tomcat處理能力時，只能犧牲掉它們，以保全大局。