问题描述
我有一个在AWS Beanstalk（Tomcat 8.5 + Apache httpd）中运行的Java应用程序。
应用程序有时会在localhost上调用REST端点。
有时我会在日志中看到这样的故障：
14:55:45 ... SEVERE: url[http://localhost/detail.api?id=200030599] timing=12.010 ...
这表示我的CustomrestTemplate放弃了等待12秒的回复。
但是，在日志中查找了几行，我看到了来自服务端点的日志条目：
{
"server_ts": "2020-08-19T14:55:33.890Z","remote_ip": "127.0.0.1","local_ip": "127.0.0.1","method": "GET","url": "/detail.api","query_string": "?id=200030599","protocol": "HTTP/1.1","http_status": 200,"referer": null,"user_agent": "Apache-HttpClient/4.5.2 (Java/1.8.0_252)","time_elapsed": 5,"thread_name": "http-nio-8080-exec-20","host": "localhost",}
这是我的自定义servlet记录器，显示了 5毫秒响应。这是从外部包装的Servlet过滤器记录的。
这个问题经常发生，但是由于罕见，我无法重现。因此，我需要采取一种理性的方法...提出一系列假设和检验以反驳每个假设，直到找到正确的假设为止。
可能的原因有哪些？
到目前为止我尝试过什么
我编写了自定义记录器，因此可以捕获上面显示的时间。然后，由于超时发生在“服务器”（本地主机端点）发送的响应和客户端读取的响应之间的某个隐藏维度上，所以我基本上遇到了麻烦。
我看到Apache日志（来自elasticbeanstack）也显示了本地请求：
127.0.0.1 (-) - - [19/Aug/2020:14:55:33 +0000] "GET /detail.api?id=200030599 HTTP/1.1" 200 4982 "-" "Apache-HttpClient/4.5.2 (Java/1.8.0_252)"
解决方法
最后，我能够使用JMeter在本地测试中重现该问题。
原来“隐藏的维度”潜伏在Servlet过滤器中：
@Override
public void doFilter(ServletRequest request,ServletResponse response,FilterChain chain)
throws IOException,ServletException {
long started = System.currentTimeMillis();
chain.doFilter(request,response);
long elapsed = System.currentTimeMillis() - started;
log(request,response,elapsed);
}
log()调用包含一个同步数据库插入，该插入会减慢速度，并最终在负载下失败。我假设servlet引擎保持连接打开，直到此过滤器返回。调查正在进行中，现在就找到修复程序。