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

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

簡介

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

佇列延遲

目前的Web服務器，如Tomcat，請求處理程序大概都類似如下：
image_2023-01-15_20230115173654
這是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就不用再處理了，因為就算處理了，客戶端也不會再去讀回應資料的，
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;
        }
    }
}

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

當任務入佇列時，包裝一下任務，記錄一下入佇列的時間，
然后執行緒從佇列中取出任務時，若發現任務等待時間過長，就將其移入慢佇列，
而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

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

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

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

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/542062.html

標籤：其他

上一篇：CF1779C Least Prefix Sum 題解

下一篇：pycharm下載安裝與基本配置