jradius响应超长且不稳定排查

背景

    公司内部需要对入网认证作一定的控制，考虑到后端系统都是java写的因此选用jradius作AAA认证系统。

基本数据

    公司内部人员规模： > 23k；

    地域分布：全国大城市都有

    设备量： 至少3倍于 人员规模

    认证频繁度：百万级别 

    分布：极不平衡，高峰期集中在30分钟-1个小时内；

整体结构

现象

1.freeradius出现请求响应时间，日志如下：

Tue Apr  8 09:20:32 2014 : Info: WARNING: Child is hung for request 1095119 in component <core> module <thread>.
Tue Apr  8 09:20:32 2014 : Info: WARNING: Child is hung for request 1095181 in component <core> module <thread>.
Tue Apr  8 09:20:33 2014 : Info: WARNING: Child is hung for request 1095181 in component <core> module <thread>.
Tue Apr  8 09:20:37 2014 : Error: WARNING: Unresponsive child for request 1095307, in component <core> module <thread>
Tue Apr  8 09:20:38 2014 : Info: WARNING: Child is hung for request 1095307 in component <core> module <thread>.
Tue Apr  8 09:20:39 2014 : Info: WARNING: Child is hung for request 1095307 in component <core> module <thread>.
Tue Apr  8 09:20:41 2014 : Error: WARNING: Unresponsive child for request 1095405, in component <core> module <thread>
Tue Apr  8 09:20:41 2014 : Error: Discarding duplicate request from client private-network-1 port 2131 - ID: 220 due to unfinished request 1095405
Tue Apr  8 09:20:42 2014 : Info: WARNING: Child is hung for request 1095405 in component <core> module <thread>.

 日志中有大量的请求处于响应慢的状态

2.该高峰期出现请求响应变成长；

2014-04-08 16:45:45,700 INFO  radius - process nac handler end,consuming_time:xxxxxxx:5083 ms
2014-04-08 16:45:45,700 INFO  radius - process nac handler end,consuming_time:<span style="font-family: Arial, Helvetica, sans-serif;">xxxxxxx</span><span style="font-family: Arial, Helvetica, sans-serif;">:5080 ms</span>
2014-04-08 16:45:45,704 INFO  radius - process nac handler end,consuming_time:xxxxxx:5080 ms
2014-04-08 16:45:45,701 INFO  radius - process nac handler end,consuming_time:xxxxxxx:5078 ms
2014-04-08 16:50:27,084 INFO  radius - process nac handler end,consuming_time:xxxxxxxxxx:5151 ms
2014-04-08 16:50:26,991 INFO  radius - process nac handler end,consuming_time:xxxxxxxxxxx:34617 ms
2014-04-08 16:54:22,686 INFO  radius - process nac handler end,consuming_time:xxxxxxxx:38230 ms
2014-04-08 16:54:22,712 INFO  radius - process nac handler end,consuming_time:xxxxxxxxxxx:5128 ms

  这个是高峰期请求响应的状况，可以看到请求响应都很长，并且出现极端不寻常的值（倒数第二、第三行）

3.系统日志中有调用后端服务链接异常，建立链接超时；

java.net.ConnectException: Connection timed out: connect
    at java.net.PlainSocketImpl.socketConnect(Native Method)
    at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)

分析过程

1.ds压力排查

理由：在认证时调用后端服务器出现链接异常，并且是在高峰期出现，而且后端服务器只有两台；

细分：ds服务器cpu，load，memory各方面系统指标都很低

2.jradius btrace追踪

发现请求确实如日志，进入时间和结束时间有阶段性，某一刻响应特长，隔断时间好了，再某一段时间有出现；

和用户数据没规律

3.jstack分析

jstack jradius线程和基本堆信息，发现里面的java进程基本被占用满（99%），但是一直没oom，怀疑是jradius进程处于oom的临界状态

4.heap分析

heapdump内存信息，mat分析结构，发现JRadiusSessionManager占用了绝大部分内存，存储数据达到了78w条；

分析JRadiusSessionManager结构，该代码采用的是ehcache保存session信息，cache的控制采用ehcache配置引入，ehcache.xml的配置信息如下：

<defaultCache     
            maxElementsInMemory="10000"
            eternal="false"
            timeToIdleSeconds="120"
            timeToLiveSeconds="120"
            
            overflowToDisk="false"
            maxElementsOnDisk="100000"
            diskPersistent="false"
            diskExpiryThreadIntervalSeconds="120"
            
            memoryStoreEvictionPolicy="LRU"
            />

session存储结构如下（其他存储结构这次没用到就不罗列了）：

Key： request.getSender()：Attr_NASIPAddress.TYPE：Attr_NASIdentifier.TYPE：Attr_UserName.TYPE：Attr_CallingStationId.TYPE：Attr_CalledStationId.TYP
Value： JRadiusSession

jradius官方给出的默认配置，限制了存储10k各数据，算法最近最少使用，计算key和alue已经最大数量存储应该不会导致内存溢出；

难道是代码问题，没有把ehcache的配置生效到代码？？？

5.分析jradius session模块

看JRadiusSessionManager代码，问题代码如下：

public void afterPropertiesSet() throws Exception
    {
        if (cacheManager == null) 
        {
            cacheManager = CacheManager.create();
        }

        if (sessionCache == null) 
        {
            sessionCache = cacheManager.getCache(cacheName);

            if (sessionCache == null)
            {
                sessionCache = new Cache(cacheName, 1000000, true, false, 0, maxInactiveInterval);
                cacheManager.addCache(sessionCache);
            }
        }

        if (logCache == null) 
        {
            logCache = cacheManager.getCache(logCacheName);

            if (logCache == null)
            {
                logCache = new Cache(logCacheName, 1000000, true, false, 0, maxInactiveInterval);
                cacheManager.addCache(logCache);
            }
        }

        sessionCache.getCacheEventNotificationService().registerListener(this);
        logCache.getCacheEventNotificationService().registerListener(this);
    }

可以看到因为ehcache.xml没有配置jradius-session session，导致实际默认配置采用的是初始化1M的数量；也就解释了为什么导致存储数量是87w左右；

7.分析gc

发现jradius在这种状态进行频繁的fullgc，由于采用的cms，在init和remark阶段会导致java进程停止响应；导致请求全部被hold；而在fullgc结束后，这批数据就进入处理流程，在排队处理一段时间后又进行fullgc，导致再次被hold，因此排队的数据又进入hold中；

一次fullgc：7s

一次响应：40s

多次fullgc使得排队的时延：7*n响应

总结

1.jradius给出错误的配置，导致使用jradius默认的ehcache.xml配置实现出错；

2.内存在处于临界点时要观察gc情况，可能能更快定位问题；