如何识别活动（长时间运行）HTTP 请求的 URI？答案

【问题标题】：How to identify URIs of active (long-running) HTTP requests?如何识别活动（长时间运行）HTTP 请求的 URI？
【发布时间】：2014-02-01 21:54:16
【问题描述】：

想象一个 web 应用程序（有时）需要很长时间才能响应一些 HTTP (POST/GET/etc) 请求 - 您如何在服务器端找到这样的请求？

到目前为止，我已经使用 tomcat AccessLogValve 查看“已完成”请求，但这并没有让我看到“进行中”（卡住) :(

例如：

使用netstat，我能够识别长期存在的套接字，这可以为我提供当前卡住请求的计数（虽然不是 URI），但是 HTTP 保持活动使这种方法无效
我可以多次堆栈转储应用程序服务器 (kill -3 <server_pid>)，然后猜测哪些线程运行时间较长，并对 URI 进行逆向工程——这也不是一种聪明的方法
我可以在 Web 应用服务器前注入一个路由器/代理（替代主机名、克隆证书），它会显示当前正在运行的调用 - 这不是一个简单的方法
我可能只是不断地运行tcpdump 并解析流量以保留当前运行的 URI 列表，但那如何处理 httpS 呢？
我发现最接近的是 tomcat7 的 StuckThreadDetectionValve，它会定期报告长时间运行的调用，但它会输出堆栈跟踪（不是 URI）并且不提供“实时”数据（例如，仅定期轮询、洪水日志并让我们查看 1-60 秒前的状态，但不是“现在”）

也许我只是缺少/忽略了重要/核心/基本的 tomcat 功能之一？或者也许 weblogic（或任何其他应用程序服务器）可以为此提供强大的功能？

没有这样简单而重要的功能，我有点迷失了。帮助？请问？

【问题讨论】：

对于一些我遇到此问题的报告，我让他们在开始之前向表中插入一条记录，并在完成后对其进行更新，以跟踪它运行的时间和卡住的频率。但我提前知道哪些是问题 servlet。
@developerwjk - 是的，我正在寻找类似的东西，但在 tomcat 范围（或任何其他应用程序服务器）级别，而不是在 servlet 级别。

标签： java jakarta-ee tomcat weblogic tomcat-valve

【解决方案1】：

不幸的是，没有一种简单的方法可以获取需要很长时间的正在进行的 HTTP 请求的列表。正如您所提到的，间隔几秒钟进行几次线程转储将告诉您哪些线程正在缓慢执行 HTTP 操作（因为每个等待响应的线程堆栈都是相同的）。但是，它并不能告诉您更多信息，除非您可以按照代码返回到带有 URL 的静态代码段。但是，您可以获取线程转储并识别线程 ID，然后进行堆转储并在堆转储中找到这些线程。虽然不是直截了当，也绝对不简单，但您可以获取正在使用的 URL、等待多长时间等。

【讨论】：

试过了，但是堆转储很大，会暂时锁定服务器，而且分析器花费的时间（4 分钟以上）使其远非交互式。我找到了一种简单/直接的方法，并给出了单独的答案。

【解决方案2】：

好的 - 创建我自己的 Valve 是一种适当且简单的方法，在下面分享。 Apache 确实多次修改了 AccessLogValve，但所有修改都遵循相同的概念：

invoke(...) 方法只是使用 getNext().invoke(request,response) 来调用剩余阀门链和实际的处理程序/执行程序
log(...)方法被调用在以上完成后

所以我们只需要：

也调用log(...) 之前 getNext().invoke(request,response)
修改 log(...) 以区分“之前”和“之后”调用

最简单的方法是：

@Override
public void invoke(Request request, Response response) throws IOException, ServletException {
    log(request, response, -1); // negative time indicates "before"
    super.invoke(request, response);
}

但是 tomcat_6.0.16 代码不能很好地扩展，所以我在日志消息（以硬编码方式）前加上 Thread.getName() 和“之前”/“之后”指示符。另外我更喜欢使用反射来访问private AccessLogValve.getDate()：

package org.apache.catalina.valves;

import java.io.IOException;
import java.lang.reflect.Method;
import java.util.Date;
import javax.servlet.ServletException;
import org.apache.catalina.connector.Request;
import org.apache.catalina.connector.Response;

public class PreAccessLogValve extends AccessLogValve {
    @Override
    public void invoke(Request request, Response response) throws IOException, ServletException {
        long timeStart = System.currentTimeMillis();
        log(request, response, -timeStart); // negative time indicates "before" request
        getNext().invoke(request, response);
        log(request, response, System.currentTimeMillis() - timeStart); // actual (positive) - "after"
    }

    public void log(Request request, Response response, long time) {
        if (started && getEnabled() && null != logElements && (null == condition || null == request.getRequest().getAttribute(condition))) {
            StringBuffer result = new StringBuffer();
            try {
                Date date = (Date) methodGetDate.invoke(this); 
                for (int i = 0; i < logElements.length; i++) {
                    logElements[i].addElement(result, date, request, response, time);
                }
            } catch (Throwable t) { t.printStackTrace(); }
            log(Thread.currentThread().getName() + (time<0?" > ":" < ") + result.toString());
        }
    }

    private static final Method methodGetDate;
    static {
        Method m = null;
        try {
            m = AccessLogValve.class.getDeclaredMethod("getDate");
            m.setAccessible(true);
        } catch (Throwable t) { t.printStackTrace(); }
        methodGetDate = m;
    }
}

用catalina.jar + servlet-api.jar编译以上代码，生成新的catalina-my.jar，放入tomcat/lib 文件夹。之后 - 我修改 server.xml 有：

<Valve className="org.apache.catalina.valves.PreAccessLogValve"
    directory="/tmp" prefix="test." suffix=".txt"
    pattern="%a %t %m %U %s %b %D" resolveHosts="false" buffered="false"/>

这是示例输出：

http-8007-exec-1 > 10.61.105.105 [18/Jan/2014:05:54:14 +0000] POST /admin/0$en_US/secure/enduser/search.do 200 - -1390024454470
http-8007-exec-5 > 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/0$en_US/secure/enduser/search.do 200 - -1390024457300
http-8007-exec-5 < 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/0$en_US/secure/enduser/search.do 200 13933 44
http-8007-exec-3 > 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/html/main.js 200 - -1390024457490
http-8007-exec-3 < 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/html/main.js 200 3750 0
http-8007-exec-5 > 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/images/layout/logo.gif 200 - -1390024457497
http-8007-exec-5 < 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/images/layout/logo.gif 200 1996 0
http-8007-exec-1 < 10.61.105.105 [18/Jan/2014:05:54:24 +0000] POST /admin/0$en_US/secure/enduser/search.do 200 13308 10209

这样，所有“进行中”的 URI 都可以随时轻松检索：

[root@serv1 tomcat]# awk '{if(">"==$2){if($1 in S)print S[$1];S[$1]=$0}else delete S[$1]}END{for(i in S)print S[i]}' test
http-8007-exec-4 > 10.61.105.105 [18/Jan/2014:06:13:20 +0000] GET /admin/images/1x1blank.gif 200 - -13
http-8007-exec-2 > 10.61.105.105 [18/Jan/2014:06:13:16 +0000] POST /admin/servlet/handlersvr 200 - -13

【讨论】：