一、问题描述
周四，Web服务通过spring session实现分布式会话的第三天，生产上该服务不能接收任何http请求了，并没有崩溃。
在事发第一时间，由于发现问题延时，并没有获取到第一时间的异常信息。由于是单机部署，整体服务不可用了，运维快速拉起另一个备用服务，恢复可用（由于一些原因服务并没有分布式）。
结合以往经验，服务不能接受请求，但是并没有崩溃，一般是接受服务的线程池空闲线程不够用了。
Dump线程栈，导出问题发生前一小时日志，分析。
问题一
首先分析的是jstack产生的线程栈，发现有一条线程 redisMessageListenerContainer-98234，编号已经到了9w多，说明新建过9w多条线程，潜意识认为这里有问题。这个线程是spring session用来监听redis 中用户会话过期用的。
另外在应用日志中发现，getSession方法获取会话时，竟然有10多秒的执行时间。
这两方面，把我的关注点放到了spring session上。
问题二
然后发现大多数tomcat线程，都在等待log4j的全局锁：
"tomcatThreadPool-481" daemon prio=10 tid=0x00002b1fb4172800 nid=0x1d25 waiting for monitor entry [0x00002b201909e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <0x00000000dacef370> (a org.apache.log4j.spi.RootLogger)
全局锁会导致性能的降低，但绝不是导致服务不接受请求的原因，因为获得日志锁打印完日志的线程，总会释放，然后线程空闲，可用来处理请求。
一次错误的尝试
认为是问题一导致的原因， redisMessageListenerContainer-98234大编号的原因，是没有指定监听reids的线程池，而使用了默认机制，默认机制没有使用线程池。
修改指定线程池后，投产。
又挂了
两天之后，周六中午，这个web服务又不能接受请求了。运维拉起了备用服务，问题服务保持现状未处理。
二、原因分析
周一，仔细想了下上周四解决问题的方案，其实并没有找到问题的真正原因。
猜测
Web服务的表现是，在浏览器输入地址，一直处于等待中，tomcat处理不了请求了，很大可能是线程池没有空闲线程了；请求处理慢，加上一定的并发量，会导致空闲线程都有任务，可能会导致新的请求无法分配到空闲线程而被拒绝。
于是带着这个猜测，查看问题出现前一小时的日志，发现大多tomcat数线程都处理得很快。个位数的tomcat线程，在getSession获取会话耗时10多秒，原因未知。
而且线程方法栈中，大多数线程处于Blocked状态，等待log4j1的全局锁。毫无疑问全局锁造成性能降低，但是单次的线程快照并不能证明线程在这个Blocked状态停留了多久，不具备参考性。
JVM heap
既然单一的从jstack的线程方法栈中分析不出原因，尝试分析jvm的内存信息。
由于周六挂掉的那台服务并没有关闭，尝试去分析它的信息，但是毕竟已经停了两天了，jvm信息可能不具备参考性了。
使用 jmap -heap pid命令，输出java 堆概况，如下：
Heap Configuration:
MinHeapFreeRatio = 40
MaxHeapFreeRatio = 70
MaxHeapSize = 536870912 (512.0MB)
NewSize = 178913280 (170.625MB)
MaxNewSize = 178913280 (170.625MB)
OldSize = 357892096 (341.3125MB)
NewRatio = 2
SurvivorRatio = 8
PermSize = 134217728 (128.0MB)
MaxPermSize = 268435456 (256.0MB)
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
New Generation (Eden + 1 Survivor Space):
capacity = 161021952 (153.5625MB)
used = 161021944 (153.56249237060547MB)
free = 8 (7.62939453125E-6MB)
99.9999950317333% used
Eden Space:
capacity = 143130624 (136.5MB)
used = 143130624 (136.5MB)
free = 0 (0.0MB)
100.0% used
From Space:
capacity = 17891328 (17.0625MB)
used = 17891320 (17.06249237060547MB)
free = 8 (7.62939453125E-6MB)
99.99995528559981% used
To Space:
capacity = 17891328 (17.0625MB)
used = 0 (0.0MB)
free = 17891328 (17.0625MB)
0.0% used
concurrent mark-sweep generation:
capacity = 357957632 (341.375MB)
used = 357957592 (341.37496185302734MB)
free = 40 (3.814697265625E-5MB)
99.99998882549318% used
Perm Generation:
capacity = 134217728 (128.0MB)
used = 53057360 (50.59944152832031MB)
free = 81160368 (77.40055847167969MB)
39.530813694000244% used
天呐，两天过去了，java heap的新生代还是处于爆满状态，得不到回收。此时的线程栈信息中，tomcat业务线程都处于runnable状态。浏览器尝试访问服务，发现还是不能访问。此时虽然线程池有空闲线程了，但是请求从外部到tomcat分配线程中间，或多或少总会需要一些内存，不可分配，所以请求还是接收不到。
OOM
既然jvm heap不够用了，那么，应用日志里应该输出OOM异常，使用关键字搜索日志，果然发现了一行OOM日志：
[2019-03-02 11:32:29 000378][springSessionRedisTaskExecutor-1][(MNG)(org.springframework.data.redis.listener.RedisMessageListenerContainer:652)(handleSubscriptionException)][ERROR][]SubscriptionTask aborted with exception:
java.lang.OutOfMemoryError: Java heap space
大对象
OOM产生之后，接下来寻找占用内存最大的对象了。
使用jdk自带的jvisualvm工具，装入dump文件：
前三名是基本类型的对象，通常情况下，java类都是有基本类型的字段的，这个工具不能很好的定位大对象。
换成JProfier工具：
可以很清楚的看到第一名是SessionRegistryImpl类，它是spring security的会话持有类，显示jvm中只有一个该实例，但是占用321M（分配给虚拟机最大内存512M）。用这个工具，甚至可以分析大对象的成分：
这时需要依靠代码了，查看这个类的代码：
public class SessionRegistryImpl implements SessionRegistry, ApplicationListener<SessionDestroyedEvent> {
//~ Instance fields ================================================================================================
protected final Log logger = LogFactory.getLog(SessionRegistryImpl.class);
/** <principal:Object,SessionIdSet> */
private final ConcurrentMap<Object,Set<String>> principals = new ConcurrentHashMap<Object,Set<String>>();
/** <sessionId:Object,SessionInformation> */
private final Map<String, SessionInformation> sessionIds = new ConcurrentHashMap<String, SessionInformation>();
...
}
如JProfier工具分析的一样。分析，sessionIds是一个map，key是sessionId，value是用户信息；principals 是当前会话中所有用户信息的集合。
使用JProfier工具，选中sessionIds，分析其成分，如下：
可以看到，全是用户信息。由于SessionRegistryImpl一直引用到这些用户数据，导致它们不会被gc，越积越多，最后OOM。
持久增长的用户信息
会话有效期间，持久引用用户数据是正常的，因为会话期间确实需要访问用户数据。正常来说，会话过期就不会再持有引用，用户数据得以gc。
spring security中 MyUserDetails是登陆用户信息的直接持有类，利用JProfier，分析该实例的数量：
数量是6.6w，大小是2646KB；说明在会话有效期1个小时内，有6w多个用户在同时登陆。但是活跃的用户数量并没有这么多，更别说1个小时内同时在线了。
因此怀疑是用户会话过期后，用户数据并没有得到gc，SessionRegistryImpl一直持有用户数据的引用。猜测终究是猜测，需要实际证据来证实。
通过命令 jmap -histo:live pid可以输出当前的大对象信息：
C:\Users\user_name>jmap -histo:live 15728
num #instances #bytes class name
----------------------------------------------
1: 1264 17022112 [B
2: 14917 1346192 [C
3: 4079 455896 java.lang.Class
4: 4243 383920 [Ljava.lang.Object;
5: 14715 353160 java.lang.String
6: 6862 219584 java.util.concurrent.ConcurrentHashMap$Node
7: 10742 171872 java.lang.Object
8: 627 75240 java.net.SocksSocketImpl
9: 1502 70192 [I
10: 2068 66176 java.util.HashMap$Node
11: 627 65208 java.net.TwoStacksPlainSocketImpl
12: 50 58368 [Ljava.util.concurrent.ConcurrentHashMap$Node;
13: 1421 56840 java.lang.ref.Finalizer
14: 614 54032 java.lang.reflect.Method
15: 1261 40352 java.net.InetAddress$InetAddressHolder
16: 927 37080 java.util.TreeMap$Entry
17: 323 32768 [Ljava.util.HashMap$Node;
18: 625 30000 java.net.SocketInputStream
19: 625 30000 java.net.SocketOutputStream
写一个shell脚本，循环定时在生产服务器上服务pid的大对象信息，显示用户对象MyUserDetails实例是在持续增长的。
三、解决方案
问题原因是会话用户数据不断增长，过期不释放。
接下来就是分析代码了。不再赘述，修改代码，使会话过期后释放SessionRegistryImpl实例引用的用户信息即可。
四、问题总结
企业级的java应用中，性能相关的问题，不可能只通过单一的手段就能定位原因的。
问题出现时，错误地单一依赖jstack输出的线程转储堆栈，得出了错误的结论；其实线程转储堆栈只是jvm线程集合的快照，单此快照，提供的信息不全面。尚需结合其他信息，多次快照，而且Full GC时，会stop the world 导致其他线程挂起。
解决性能问题的步骤应该是：
- 第一时间查看jvm 内存信息，jstack线程转储堆栈，jmap dump jvm内存，gc等信息；因为随着时间的推移，线程，jvm内存，gc信息会变化，错过了问题黄金时间，就得不到正确的信息。当然，可以通过jvm的相关参数，自动输出一些jvm相关信息；如在oom时输出dump，定期输出gc信息等。
- 获取问题出现前一段时间的日志。
- 结合日志以及jvm信息定位问题。先看日志有没有抛出明显异常，再看jvm内存，是否有大对象之类的，最后看jstack输出的信息，分析jvm，jstack务必要结合代码！！！
