记一次生产问题的排查思路

最近系统出现一个很奇怪的问题，用户登录变得十分缓慢，平均登录时间在10-20s不等，并且伴随出现了堆内存告警，重启服务后问题依然存在，此问题严重影响了系统正常使用。

为了避免影响用户体验，我们首先采取的办法是对版本进行回退，将代码回退到上一发布版本，但回退后发现问题依然存在。

尝试在测试环境复现此场景，但相同的代码在测试环境却无法复现登录缓慢的情况。

通过排查日志登录接口，显示主要耗时在用户认证环节，因为涉及到对用户信息的查询，首先怀疑可能是数据库问题，通过日志分析相关sql执行时间都不超过50ms，同时其他业务功能是正常的，例如业务数据查询速度很快，因此可以排除数据库问题。

由于生产环境日志级别为error，我们只能知道主要耗时在用户认证环节，但是过程中涉及很多的方法调用，无法具体定位是哪一块代码的执行时间很长。为了解决这一问题，可以尝试在相关执行方法上都增加耗时统计的逻辑，然后调低日志级别，最后通过日志来定位具体问题，但是这样做需要增加很多无业务意义的代码，并且在抓取到日志后又得再回退版本，对于生产环境上线流程来说十分繁琐。

问题在测试环境无法复现，并且生产环境能够排查到的信息十分有限，那有没有什么办法可以不修改线上代码，就可以定位代码执行情况呢？有的，我们使用了Alibaba 开源的 Java 诊断工具Arthas，以下是官方对这个工具的介绍：Arthas 是一款线上监控诊断产品，通过全局视角实时查看应用 load、内存、gc、线程的状态信息，并能在不修改应用代码的情况下，对业务问题进行诊断，包括查看方法调用的出入参、异常，监测方法执行耗时，类加载信息等，大大提升线上问题排查效率。
官方首页 https://arthas.aliyun.com/

通过部署Arthas，使用trace打印方法内部调用路径，并输出方法路径上的每个节点上耗时，在定位到方法后，使用watch命令观测函数的出入参数，最终发现是在认证过程中筛选当前用户所属会话的操作，大概的处理逻辑是从缓存中拿到所有session并进行循环处理，这里发现循环的session集合竟然有十多万条，意味着每次用户登陆都需要进行大量的循环处理。好了，问题就出在这里。

为什么会堆积这么多的会话呢？系统的认证框架是shiro，用户登录后会话会放入shiro缓存，通过分析发现其实缓存中大部分会话已经过期，但是系统却没有销毁过期的session，于是检查SessionManager的配置，发现是有定时清理失效会话的处理sessionValidationSchedulerEnabled=true，默认使用ExecutorServiceSessionValidationScheduler调度器来进行定时清理，下面是简化后的源码。

public class ExecutorServiceSessionValidationScheduler implements SessionValidationScheduler, Runnable {

	......
    
    public void enableSessionValidation() {
        if (this.interval > 0L) {
            //创建一个定时器，定时验证所有session
            this.service = Executors.newSingleThreadScheduledExecutor(new ThreadFactory() {
                public Thread newThread(Runnable r) {
                    Thread thread = new Thread(r);
                    thread.setDaemon(true);
                    return thread;
                }
            });
            this.service.scheduleAtFixedRate(this, this.interval, this.interval, TimeUnit.MILLISECONDS);
            this.enabled = true;
        }
    }

    public void run() {
        ......
        long startTime = System.currentTimeMillis();
        //下面这个方法会定时调用
        this.sessionManager.validateSessions();
        long stopTime = System.currentTimeMillis();
        if (log.isDebugEnabled()) {
            log.debug("Session validation completed successfully in " + (stopTime - startTime) + " milliseconds.");
        }

    }
}

分析上面代码说明SessionManager的validateSessions方法会定时得到执行，而我们业务代码中对这个方法进行了复写，复写后的代码如下：

public class OnlineWebSessionManager extends DefaultWebSessionManager{
    ......
    
    /**
     * 验证session是否有效 用于删除过期session
     */
    @Override
    public void validateSessions()
    {
        //在这里出现了异常
        Principal p = UserUtils.getPrincipal();
        
        String loginName = p.getLoginName;
        ......
    	super.validateSessions();
        ......
    }
}

通过断点调试发现11行代码抛出了异常，所以后面的校验根本没有执行，难受的是控制台输出日志中没有任何异常信息，并且定时任务中断，不会再次执行，也就是说，之前的session都没有销毁成功，同时日志没有任何提示，直到这次上线才暴露出这个问题。

修改此处代码后session校验可以正常执行，大量过期session得到回收，登录业务恢复正常。虽然问题得到解决，但是很奇怪为什么定时任务在遇到异常后会中断并不会继续执行，推测官方是认为重复执行一个失败的任务没有意义，所以遇到异常后直接就失效了。百度后发现很多人也遇到同样的问题，解决方案是进行try_catch处理，将异常信息暴露出来，这样虽然任务会执行失败，但是定时任务不会失效，并且会将异常信息暴露出来。

Java中的定时任务-ScheduledExecutorService的坑-CSDN博客

为什么系统之前没有出现过这个问题呢？主要原因是最近上线了系统健康探测的组件，每搁十秒会进行一次远程调用，这就导致了大量的孤立会话，加上清理任务失效，以至于出现了大量会话堆积。

补充：查看最新版本shiro的源码发现官方已注意到这个问题了，原先的版本是1.2.3，查看最新版本源码，在ExecutorServiceSessionValidationScheduler中增加了try_catch处理，以下是1.10.1的源码。

public class ExecutorServiceSessionValidationScheduler implements SessionValidationScheduler, Runnable {
	 ......
	 public void run() {
	        ......
	        Thread.currentThread().setUncaughtExceptionHandler((t, e) -> {
	            log.error("Error while validating the session, the thread will be stopped and session validation disabled", e);
	            this.disableSessionValidation();
	        });
	        long startTime = System.currentTimeMillis();
	
	        try {
	            this.sessionManager.validateSessions();
	        } catch (RuntimeException var5) {
	            log.error("Error while validating the session", var5);
	        }
	
	        long stopTime = System.currentTimeMillis();
	        if (log.isDebugEnabled()) {
	            log.debug("Session validation completed successfully in " + (stopTime - startTime) + " milliseconds.");
	        }

    }

参考：https://github.com/apache/shiro/commit/04866620386dd20ca292328218bc852f17fa4c18