背景：

2022-08-19 17:00 收到业务报障，网站延迟很大

2022-08-23 再次收到业务报障，延迟很大

首先看了流量情况，发现故障时间点确实有流量上涨，但是高峰流量实际上也没多少，由于我们是给客服使用的系统，同时在线一共就不到两千人，部署了6台机器，我们认为流量上涨不应该导致系统响应慢，并且流量上涨也可能不是原因而是其他原因导致的现象。

查看监控发现ygc耗时非常严重，从gc日志看每次ygc都在250ms以上，因此大致确认由于ygc耗时太高导致的响应慢。

排查

确定ygc哪个阶段耗时高

我们使用的openjdk8，由于openjdk和oraclejdk ygc日志太少，看不出来每个阶段的耗时，我们换成dragonwell jdk8后，增加-XX:+PrintGCRootsTraceTime 参数上线一台观察。

dragonwell jdk是阿里维护的jdk，见“龙井”开箱评测 |Alibaba Dragonwell 新手上路指南-阿里云开发者社区

发现是older-gen scanning阶段耗时太高，刚开始一直以为older-gen scanning就是老年代扫描耗时，所以一直从跨代引用方向开始排查，从dump内存看不出跨代引用，排查一度陷入困境。

jvm使用cardtable记录哪些card存在老年代到新生代的引用，这样ygc时不需要扫描整个老年代。

后来查资料发现dragonwell jdk的older-gen scanning阶段耗时实际包括扫描跨代引用和复制对象两部分，到底是哪个部分耗时dragonwell jdk也看不出来，查资料得知dragonwell jdk的阶段耗时实现参考了G1，查看G1资料发现G1的ygc日志更加全面，有单独的对象复制的耗时，因此换G1再次上线一台。

G1的日志没有下载，已缺失，这里的图片仅仅说明G1能看到object copy阶段耗时

由于G1的日志文件没有下载，没有留截图，不过从G1日志上看，ygc耗时高主要是object copy阶段导致，因此我们需要弄清楚young区是什么对象在copy？

什么对象在copy？

如果在每次ygc后能看到young区的对象分布，我们就大概能知道是哪些对象在copy了。Dragonwell jdk 有参数能打印ygc后young区对象的直方图，因此再次换dragonwell jdk8上线一台

jinfo -flag +PrintYoungGenHistoAfterParNewGC 1 开启ygc后打印young直方图

从知直方图上看最有可疑的是HashMap$Node对象活的比较久导致，dump内存后使用MAT工具跟踪一下young区的HashMap$Node对象

// 使用OQL查询young区的HashMap$Node对象，内存地址从gc日志里能找到
select * from java.util.HashMap$Node n 
where (toHex(n.@objectAddress) >= "0x6b0800000" 
and toHex(n.@objectAddress) <= "0x770800000") 

发现排第一的是跟缓存相关的，排第二的是跟shiro相关的。

检查缓存相关的代码，发现缓存每10分钟刷新一次，每次都是新new一个map替换老的map，这里是一个可疑点，因为新map的大小在初始化时没有给值，默认16，put数据的时候如果数据量较大会一直扩容，导致发生跨代引用，但是这个缓存是10分钟更新一次，随着多次ygc后应该会进入老年代，不会一直导致ygc耗时高，我们观察的现象是每次ygc都耗时，跟缓存更新的周期对不上。

跟shiro相关的由于引用链很深，没有完全展开，也因为其他同样使用shiro的服务没有此问题，因此没有太放心上。

不过我们已经确认了是因为young区对象存活时间较长导致ygc耗时，这个大方向是没有错。

jvm监控

查看jvm监控发现，young区始终占用接近100%，old区一直增长，因此断定这些young区的对象会进入old区，我们等快要fgc（jstat -gcutil 1 5000一直盯着）的时候再去dump内存应该能找到线索。

在fyc发现前（jstat -gcutil 观察快要fyc时摘流量，dump内存），发现是SessionHandler对象关联内存最多，展开依赖图，结合jetty的源码，我们知道 _sessionCache就是Session的缓存，内部实现是一个HashMap，key是sessionId，value是session对象，这个HashMap的Node数组大小为131072，也就是说此时这台机器上有131072个Session，从依赖图上看到Session对象的attribute属性关联了一个UserBasicInfoPrincipal，UserBasicInfoPrincipal对象关联一个SimpleAuthorizationInfo，SimpleAuthorizationInfo内部有一个HashSet类型的stringPermissions存的是用户的权限，每个用户的权限有上千个。

但是每次接口请求我们都是自己的PermissionRealm直接通过RPC拿到用户的权限列表，并没有放到Session里，查看shiro源码后发现shiro会把这个Principle存到Session里，到这里就明白了为什么HashMap$Node对象那么多了，第一Session对象本身就太多，第二每次接口都会生成一个Principle，principle里有权限列表字段，principle本身又被Session引用，Jetty的Session默认30分钟过期，那么在30分钟内这些对象都不会成为垃圾，随着请求越来越来，创建的Principle也会越来越多一直得不到释放。

session对象个数

从图上看到关联的内存都在Session对象下，我们统计一下Session对象的个数，发现有4w多个，但是我们系统同时在线用户一共就不到2000，理论上应该一个用户一个Session对象，这里明显是Session出问题了。

UserBasicInfoPrincipal里有ssoId

Session对象为什么会多出那么多？猜测是同一个用户有多个Session对象，根据上图的内存引用关系，我们知道UserBasicInfoPrincipal会有ssoId字段的，使用OQL统计下ssoId

将ssoId的结果导出成txt，使用 awk，sort，uniq一套组合拳统计下ssoId的重复次数，发现确实是同一个用户有多个Session对象。

那么我们就要问为什么同一个用户会创建多个Session对象？有2个排查方向：

一、前端传的sessionId有问题

二、前端传的sessionId没有问题，但是服务端仍然new了新的Session对象

我们观察网页的请求后发现，sessionId传的没有问题，但是几乎每个请求的response里都会set-cookie：sessionId=xxxx，也就是说每次请求服务端都让重新设置sessionId了。

那么前端传过去的sessionId是对的，服务端为什么仍然要new新的Session？为什么test，pre环境没有问题，突然想到prod是多台机器，test，pre是一台机器，到这里基本上找到原因了，因为prod环境多台机器，请求A打到服务器机器A，生成sessionA，请求B带上sessionA到机器B，因为机器B不认识这个sessionA所以重新生成了一个sessionB，也就是说Session是单机的，各机器之间互相不认识。

修复

修复的方向有以下几个：

1. 使用分布式Session（主要是引入spring-session，其他项目都是这么干的）
2. 禁用session（我们基本上都是restfull接口压根用不到session）

为了不引用更多的依赖，我们选择方案2，禁用session的办法是在shiro配置的地方加一个 NoSessionCreationFilter，部署到test环境后发现网站主页面打不开了，看异常日志后发现，主页面是一个jsp页面，jsp在编译时默认就会创建Session，上面又配置了NoSessionCreationFilter导致抛异常。最后我们的处理方式是：

1. jsp增加 <%@ page session="false" %> 指令关闭session创建
2. 取消NoSessionCreationFilter（因为修改的是一个公共jar，不能保证其他人没有使用Session）
3. 在配置DefaultWebSecurityManager的地方，增加一个配置不要使用SessionStorage（修改的是公共jar，这个配置是默认开启的保持原逻辑，我们项目关闭这个配置）

@Bean
public FilterRegistrationBean shiroFilter(
  Realm permissionRealm) throws Exception {
  
  DefaultWebSecurityManager securityManager = 
    new DefaultWebSecurityManager(permissionRealm);
  
  if (authConfig.isDisableSessionCreate()) {//新加的配置
    DefaultSessionStorageEvaluator storageEvaluator =
      new DefaultSessionStorageEvaluator();
    storageEvaluator.setSessionStorageEnabled(false);// 关闭session存储
    
    ((DefaultSubjectDAO) securityManager.getSubjectDAO())
      .setSessionStorageEvaluator(storageEvaluator);
  }
  
  //.......
}

验证

修复后

修复前

yfc avg 298ms -> 50ms

实际上ygc 50ms还是比较高，根据经验4C8G的机器ygc在20ms以内才算正常，耗时仍然较高的原因是项目里使用了大量的内存缓存，有些map大小达到50w之多，并且这个map频繁修改，会导致跨代引用，由于这个大缓存在公司统一的公共组件里，我们处理不了，目前只能先观察。（一共就2千人用，还有继续优化的必要么）