jradius响应超长且不稳定排查
来源:互联网 发布:双系统linux安装教程 编辑:程序博客网 时间:2024/05/01 03:13
背景
公司内部需要对入网认证作一定的控制,考虑到后端系统都是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 1095405Tue 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 ms2014-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 ms2014-04-08 16:45:45,701 INFO radius - process nac handler end,consuming_time:xxxxxxx:5078 ms2014-04-08 16:50:27,084 INFO radius - process nac handler end,consuming_time:xxxxxxxxxx:5151 ms2014-04-08 16:50:26,991 INFO radius - process nac handler end,consuming_time:xxxxxxxxxxx:34617 ms2014-04-08 16:54:22,686 INFO radius - process nac handler end,consuming_time:xxxxxxxx:38230 ms2014-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.TYPValue: JRadiusSession
难道是代码问题,没有把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情况,可能能更快定位问题;
0 0
- jradius响应超长且不稳定排查
- jradius session lock引起的性能下降问题排查
- 自动化case不稳定问题排查
- 传输数据超长时,服务器未响应
- Redis 响应延迟问题排查
- http响应异常问题排查
- Redis 响应延迟问题排查
- freeradius and jradius configuration
- 不稳定
- 排查web服务器无法响应的解决办法
- nginx php-fpm响应长排查
- 解决在Ubuntu 17.10下腾达U6无线网卡不稳定且经常掉线问题!
- 用ProcessExplorer和WinDbg排查并解决“无响应”
- 一次线上页游服务器响应缓慢排查过程
- onActivityResult不响应的情况分析和排查
- 网站或接口响应时间较长应该如何排查?
- [CSS]--文字显示在图片下面,且多个图片显示在同一行,文字超长时用省略号替代
- 26+富有创意且响应式的Drupal 7主题
- QT 简单的网络通信(tcp ,udp)
- cocos2d-x 纹理深入研究 第二部分
- linux解压文件
- 在windows下编译php扩展
- Sql Server数据库事务介绍(二)---Sql语句,SqlTransaction和TransactionScope的使用方法
- jradius响应超长且不稳定排查
- 国外C#开源网站一览
- nmon下载及使用方法
- Java Map遍历方式的选择
- 十六进制字符转数字
- Mac上Svn的使用
- hdu 2813 One fihgt one(trie树+KM算法)
- 原型模式 Prototype模式
- 【ST学习小组】STM32F103的CAN 通信之从控器部分