請求量突增一下，系統有效QPS為何下降很多？

扣釘日記發表於2023-01-16

原創：扣釘日記（微信公眾號ID：codelogs），歡迎分享，轉載請保留出處。

簡介

最近我觀察到一個現象，當服務的請求量突發的增長一下時，服務的有效QPS會下降很多，有時甚至會降到0，這種現象網上也偶有提到，但少有解釋得清楚的，所以這裡來分享一下問題成因及解決方案。

佇列延遲

目前的Web伺服器，如Tomcat，請求處理過程大概都類似如下：
image_2023-01-15_20230115173654
這是Tomcat請求處理的過程，如下：

  1. Acceptor執行緒：執行緒名類似http-nio-8080-Acceptor-0，此執行緒用於接收新的TCP連線，並將TCP連線註冊到NIO事件中。
  2. Poller執行緒：執行緒名類似http-nio-8080-ClientPoller-0，此執行緒一般有CPU核數個，用於輪詢已連線的Socket，接收新到來的Socket事件（如呼叫端發請求資料了），並將活躍Socket放入exec執行緒池的請求佇列中。
  3. exec執行緒：執行緒名類似http-nio-8080-exec-0，此執行緒從請求佇列中取出活躍Socket，並讀出請求資料，最後執行請求的API邏輯。

這裡不用太關心Acceptor與Poller執行緒，這是nio程式設計時常見的執行緒模型，我們將重點放在exec執行緒池上，雖然Tomcat做了一些最佳化，但它還是從Java原生執行緒池擴充套件出來的，即有一個任務佇列與一組執行緒。

當請求量突發增長時，會發生如下的情況：

  1. 當請求量不大時，任務佇列基本是空的，每個請求都能得到及時的處理。
  2. 但當請求量突發時，任務佇列中就會有很多請求，這時排在佇列後面的請求，就會被處理得越晚，因而請求的整體耗時就會變長，甚至非常長。

可是，exec執行緒們還是在一刻不停歇的處理著請求的呀，按理說服務QPS是不會減少的呀！

簡單想想的確如此，但呼叫端一般是有超時時間設定的，不會無限等待下去，當客戶端等待超時的時候，這個請求實際上Tomcat就不用再處理了，因為就算處理了，客戶端也不會再去讀響應資料的。
image_2023-01-15_20230115175826
因此，當佇列比較長時，佇列後面的請求，基本上都是不用再處理的，但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;
        }
    }
}

邏輯其實挺簡單的，如下：

  1. 當任務入佇列時，包裝一下任務，記錄一下入佇列的時間。
  2. 然後執行緒從佇列中取出任務時，若發現任務等待時間過長，就將其移入慢佇列。
  3. 而pullbackIfEmpty的邏輯，就是當佇列為空時，再將慢佇列中的任務移回來執行。

為了將請求的佇列延遲記錄在access.log中，我又修改了一下Task，並加了一個Filter，如下：

  1. 使用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);
    }
}
  1. 再在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);
    }

}
  1. 然後在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

image_2023-01-16_20230116003607
可以看到，佇列長度遠小於1000，這說明佇列中積壓得不多。

再看看access.log，如下：
image_2023-01-15_20230115233508
可以發現，雖然佇列延遲任然存在，但被控制在了1s以內，這樣這些請求就不會超時了，Tomcat的有效QPS保住了。

而最後面那些佇列延遲極長的請求，則是被不公平對待的請求，但只能這麼做，因為在請求量超出Tomcat處理能力時，只能犧牲掉它們，以保全大局。

相關文章