监控慢请求堆栈

最近系统冒出不少问题，特别是偶发性的卡顿问题，不能及时找到运行堆栈。于是萌生一个想法，能不能监控一下慢请求，例如运行时间最长10秒，对于超过10秒的请求，把对应处理线程的堆栈记录到日志里边。

其实这个特性在Websphere里边是有的，如果请求处理时间非常长，就会有日志提示，只是没有堆栈罢了。

从哪里入手呢？想了想，主要是两块内容

1. 如何在一个线程里边获取另外线程的堆栈
   这个看了一下api，通过Thread的grtStackTrace方法就可以获取到了。而线程对象可以在请求过滤器里边记录下来。

2. 在执行超过一定时间后触发日志输出。
   可以考虑使用一个定时任务处理的线程池，在过滤器入口提交一个延时任务，这个任务就是获取堆栈记录日志，然后执行业务逻辑，出口的地方把这个延时任务取消就可以了。

参考实现逻辑如下:

class SlowStackTrace extends Throwable {
    public SlowStackTrace(Thread thread) {
        super("Slow Request Found");
        this.setStackTrace(thread.getStackTrace());
    }

    @Override
    public synchronized Throwable fillInStackTrace() {
        return this;
    }
}

 

打印堆栈，原本我是直接拼接字符串的，但是发现输出到日志换行符被去掉了，于是换了一个做法，采用产生一个特殊的异常来记录堆栈，这个异常默认的堆栈，转而记录特定线程的堆栈。

 

@Slf4j
class SlowRequestFilter implements Filter {
    private static final long MAX_RUN_TIME = 60L;

    private static final String WARNING_MESSAGE = "Monitor the thread running continuously for " + MAX_RUN_TIME
        + " seconds.";

    private static final ScheduledExecutorService DEFAULT_EXECUTOR;

    static {
        // 超时线程数不会过多，在特定时间内可以处理完
        ScheduledThreadPoolExecutor executor = new ScheduledThreadPoolExecutor(1);
        // 不超时的直接移除掉，避免堆积过多
        executor.setRemoveOnCancelPolicy(true);
        DEFAULT_EXECUTOR = executor;
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
        throws IOException, ServletException {
        final Thread currentThread = Thread.currentThread();
        ScheduledFuture future = DEFAULT_EXECUTOR.schedule(() -> {
            log.error(WARNING_MESSAGE, new SlowStackTrace(currentThread));
        }, MAX_RUN_TIME, TimeUnit.SECONDS);
        try {
            chain.doFilter(request, response);
        } finally {
            future.cancel(false);
        }
    }
    
    @Override
    public void destroy() {
        DEFAULT_EXECUTOR.shutdownNow();
    }
}

这里逻辑也比较简单，主要是线程池的配置，有两个设置，一个是只用了一个线程，主要是考虑业务线程数也就一两百，超时正常不会太多，所以一个足够处理。另外，就是设置取消的时候从队列移除，这是因为大多数任务都不会被执行，移除可以避免在时间限制内堆积过多的取消任务。

 

当然，这些值只是默认或者推荐的值，实际情况下，至少超时时间控制还是要做成可配置的。