原创：按钮日记（微信公众号ID：codelogs），欢迎分享，转载请保留出处。简介最近观察到一个现象，当服务的请求量突然变大的时候，服务的有效QPS会下降很多，有时甚至会下降到0。这种现象网上偶尔会提到，但很少给出解释.清楚了，所以在这里分享一下问题的原因和解决方法。队列延迟目前的web服务器，比如Tomcat，请求处理流程大致类似如下：这是Tomcat处理请求的流程，如下：Acceptor线程：线程名称类似于http-nio-8080-Acceptor-0，该线程用于接收新的TCP连接，并将TCP连接注册到NIO事件中。轮询线程：线程名称类似于http-nio-8080-ClientPoller-0。该线程一般有多个CPU核，用于轮询已连接的Socket，接收新传入的Socket事件（如调用者发送请求数据）。并将活动的Socket放入exec线程池的请求队列中。execthread：线程名称类似于http-nio-8080-exec-0。该线程从请求队列中取出活跃的Socket，读取请求数据，最后执行请求的API逻辑。这里的Acceptor和Poller线程不用太担心。这是nio编程中常见的线程模型。我们将重点关注exec线程池。Tomcat虽然做了一些优化，但还是从Java原生的线程池扩展而来，即有一个任务队列和一组线程。当请求量突然增加时，会出现以下情况：当请求量不大时，任务队列基本为空，每个请求都能得到及时的处理。但是当请求量爆棚的时候，任务队列中的请求会很多，排在队列后面的请求会被处理的更晚，所以请求的整体耗时会变长，甚至会很长。但是，exec线程仍在不停地处理请求。按理说服务QPS不会降低！简单想想，确实如此，但是调用方一般都有超时设置，不会无限等待。当client等待超时的时候，Tomcat其实是不需要处理这个请求的，因为即使处理了，client也不会等待。不会再次读取响应数据。所以，当队列比较长的时候，队列后面的请求基本上不需要处理，但是exec线程池并不知道，它还是会一如既往地处理这些请求。exec线程在执行这些超时的请求时，如果有新的请求进来，也会排在队尾，从而导致这些新的请求超时，所以在流量爆发期间，有效QPSoftherequest会下降很多，甚至下降到0。这种超时也称为队列延迟，但是队列在软件系统中被广泛使用。比如操作系统调度器维护线程队列，TCP有积压的连接队列，锁维护等待队列等等。因此，这种现象在很多系统中也存在。通常响应时间是相当稳定的，但偶尔会需要很长时间。其中很多情况都是由排队延误造成的。优化队列延迟知道了问题的原因，优化起来就比较简单了。我们只需要暂时让出队列中那些没有被处理很久的请求，让线程去执行那些没有等待很长时间的请求。毕竟，这些对于长时间没有处理的请求，让它们等待是没有用的，因为客户端可能已经超时，不需要请求结果。虽然这破坏了队列的公平性，但这正是我们所需要的。对于Tomcat，在springboot中，我们可以如下修改：使用WebServerFactoryCustomizer自定义Tomcat的线程池，如下：@ComponentpublicclassTomcatExecutorCustomizerimplementsWebServerFactoryCustomizer@Overridepublicvoidcustomize(TomcatServletWebServerFactoryfactory){TomcatConnectorCustomizertomcatConnectorCustomizer=connector->{ServerProperties.Tomcat.Threadsthreads=serverProperties.getTomcat().getThreads();任务队列taskqueue=newSlowDelayTaskQueue(1000);ThreadPoolExecutor执行器=neworg.apache.tomcat.util.threads.ThreadPoolExecutor(threads.getMinSpare(),threads.getMax(),60L,TimeUnit.SECONDS,taskqueue,newCustomizableThreadFactory("http-nio-8080-exec-"));taskqueue.setParent(执行器);ProtocolHandlerhandler=connector.getProtocolHandler();if(handlerinstanceofAbstractProtocol){AbstractProtocolprotocol=(AbstractProtocol)handler;协议.setExecutor（执行器）；}};factory.addConnectorCustomizers（tomcatConnectorCustomizer）；}}注意，这里仍然使用了Tomcat实现的线程池，只是将任务队列TaskQueue扩展为SlowDelayTaskQueue。它的作用是将长时间未处理的任务移到另一个慢队列中。当当前队列中没有任务时，将慢队列中的任务移回。为了记录任务进入队列的时间，首先封装一个记录时间的任务类RecordTimeTask，如下：@GetterpublicclassRecordTimeTaskimplementsRunnable{privateRunnablerun;私有长创建时间；私人长putQueueTime；publicRecordTimeTask(Runnablerun){这个。运行=运行；this.createTime=System.currentTimeMillis();this.putQueueTime=this.createTime;}@Overridepublicvoidrun(){run.run();}publicvoidresetPutQueueTime(){this.putQueueTime=System.当前时间毫秒();}publiclonggetPutQueueTime(){returnthis.putQueueTime;}}队列的扩展实现如下：publicclassSlowDelayTaskQueueextendsTaskQueue{privatelongtimeout;privateBlockingQueue{slowQueue;publicSlowDelayongTaskQueue(.timeout=timeout;this.slowQueue=newLinkedBlockingQueue<>();}@Overridepublicbooleanoffer(Runnableo){//包装任务记录任务放入队列的时间if(oinstanceofRecordTimeTask){returnsuper.offer(o);}else{returnsuper.offer(newRecordTimeTask(o));}}publicvoidpullbackIfEmpty(){//如果队列为空，从慢队列中取出returnaif(this.isEmpty()){RecordTimeTaskr=slowQueue.poll();如果（r==null）{返回；}r.resetPutQueueTime();这个.add(r);}}@OverridepublicRunnablepoll(longtimeout,TimeUnitunit)throwsInterruptedException{pullbackIfEmpty();while(true){RecordTimeTasktask=(RecordTimeTask)super.poll(timeout,unit);如果（任务==null）{返回null；}//request在队列中等待时间长，移至慢队列继续;}返回任务；}}@OverridepublicRunnabletake()throwsInterruptedException{pullbackIfEmpty();while(true){RecordTimeTasktask=(RecordTimeTask)super.take();//请求在队列中等待时间较长，移至慢队列继续;}返回任务；逻辑其实很简单，如下：当有任务进入队列时，将任务包装起来，记录进入队列的时间，然后当线程从队列中取出任务时，如果发现任务到等待太久，会被移入慢队列。pullbackIfEmpty的逻辑是当队列为空时，将慢队列中的任务移回执行。为了在access.log中记录请求的队列延迟，我修改了Task，增加了一个Filter，如下：先用ThreadLocal保存队列延迟@GetterpublicclassRecordTimeTaskimplementsRunnable{privatestaticfinalThreadLocalWAIT_IN_QUEUE_TIME=newThreadLocal<>();私有Runnable运行；私有长创建时间；私人长putQueueTime；publicRecordTimeTask(Runnablerun){this.run=run;this.createTime=System.currentTimeMillis();这个.putQueueTime=这个。创建时间；}@Overridepublicvoidrun(){try{WAIT_IN_QUEUE_TIME.set(System.currentTimeMillis()-this.createTime);跑跑（）;}最后{WAIT_IN_QUEUE_TIME.remove();}}publicvoidresetPutQueueTime(){this.putQueueTime=System.currentTimeMillis();}publiclonggetPutQueueTime(){returnthis.putQueueTime;}publicstaticlonggetWaitInQueueTime(){returnObjectUtils.defaultIfNull(WAIT_IN_QUEUE_TIME.get(),0L);取出队列延迟，放入Request对象@WebFilter@Componentp公共类WaitInQueueTimeFilter扩展HttpFilter{@OverridepublicvoiddoFilter（HttpServletRequest请求，HttpServletResponse响应，FilterChain链）抛出IOException，ServletException{longwaitInQueueTime=RecordTimeTask.getWaitInQueueTime();//将等候时间设置到request的属性中，给access。日志使用request.setAttribute("waitInQueueTime",waitInQueueTime);//如果请求在队列中等待的时间过长，可能是客户端超时了，可以不用执行if(waitInQueueTime>5000){response.sendError(503,"serviceisbusy");返回;}chain.doFilter（请求，响应）；}}然后在access.log服务器配置队列延迟：tomcat:accesslog:enabled:truedirectory:/home/work/logs/applogs/java-demofile-date-format:.yyyy-MM-ddpattern:'%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-d10d-T1s--latencyhttp://localhost:8080/sleep-c1000然后用arthas看线程池的队列长度，如下：[arthas@619]$vmtool--actiongetInstances\--classLoaderClassorg.springframework.boot.loader.LaunchedURLClassLoader\--classNameorg.apache.tomcat.util.threads.ThreadPoolExecutor\--express'实例。{#{"ActiveCount":getActiveCount(),"CorePoolSize":getCorePoolSize(),"MaximumPoolSize":getMaximumPoolSize(),"QueueSize":getQueue().size()}}'\-x2可以看到队列长度远小于1000，说明队列中积压的不多。再看access.log，如下：可以发现虽然队列延迟依然存在，但是控制在1s以内，这样这些请求就不会超时。Tomcat的有效QPS保持。而那些最后队列延迟极长的请求，都是被不公平对待的请求，但这是唯一的办法，因为当请求量超过Tomcat的处理能力时，只能牺牲它们来保全大局.
