原創:扣釘日記(微信公眾號ID:codelogs),歡迎分享,轉載請保留出處。 簡介 最近我觀察到一個現象,當服務的請求量突發的增長一下時,服務的有效QPS會下降很多,有時甚至會降到0,這種現象網上也偶有提到,但少有解釋得清楚的,所以這裡來分享一下問題成因及解決方案。 隊列延遲 目前的Web伺服器, ...
原創:扣釘日記(微信公眾號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處理能力時,只能犧牲掉它們,以保全大局。