How to identify URIs of active (long-running) HTTP requests?

Question

Imagine a webapp which (sometimes) takes long time to respond to some HTTP (POST/GET/etc) request - how would You find such a request on server side?

So far I've used tomcat AccessLogValve to see the "completed" requests, but that doesn't let me to see the "in-progress" (stuck) ones :(

For example:

• with netstat I'm able to identify long-lived sockets which could give me a count of currently-stuck requests (not URIs though), but HTTP keep-alives invalidate this approach

• I could stackdump the app-server (kill -3 <server_pid>) multiple times and guess which threads are running long and reverse-engineer the URIs - not a smart way either

• I could inject a router/proxy in front of web-app server (substitute hostnames, clone certs) which would show me the currently-running calls - not a simple approach

• I could fall into just running tcpdump continously and parsing the traffic to keep list of currently-running URIs, but what to do with httpS then?

• the closest I found is tomcat7's StuckThreadDetectionValve which'd periodically reports long-running calls, but it outputs the stacktrace (not URI) and doesn't provide "live" data (e.g. only polls periodically, floods the logs and lets to see the state of 1-60 seconds ago, but not "now")

Maybe I'm just missing/overlooking one of vital/core/basic tomcat features? or maybe weblogic (or any other app-server) has something robust to offer for this?

I'm kind of lost without such simple and essential feature. Help? Please?

Answer 1

OK - creation of my own Valve was a proper and easy approach, sharing below. Apache did rework AccessLogValve multiple times, but all revisions follow same concept:

1. invoke(...) method just uses getNext().invoke(request,response) to invoke a chain of remaining valves and the actual handler/executor
2. log(...) method is invoked after above is complete

So we only need to:

• also invoke log(...) before the getNext().invoke(request,response)
• modify log(...) to distinguish "before" and "after" invocations

Easiest way would've been:

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

But tomcat_6.0.16 code wasn't well-extendable, so I prefixed log-messages (in a hard-coded manner) with Thread.getName() and "before"/"after" indicator. Also I preferred to use reflection to access 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;
    }
}

compiled above code with catalina.jar + servlet-api.jar and produced new catalina-my.jar, which was placed into tomcat/lib folder. After that - I've modified server.xml to have:

<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"/>

Here's the sample output:

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

This way all "in-progress" URIs can be easily retrieved at any moment:

[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

Answer 2

Unfortunately, there is not a simple way to get a list of the in-flight HTTP requests that are taking a long time. As you mention, taking several thread dumps a few seconds apart will tell you which threads are performing the HTTP operations slowly (because the thread stack will be identical in each one that is waiting for the response). But, it doesn't tell you much more than that unless you can follow the code back to a static piece of code with the URL. But, you can take the thread dumps and identify the thread IDs, then take a heap dump and find those threads in the heap dump. While not straight-forward and definitely not simple, you can get the URL that is being used, how long it has been waiting, etc.