性能分析之一条SQL引起的内存溢出问题

今天在测试环境有过代码升级。升级后，在群里有人反映系统访问很慢。运维人员反映服务器cpu使用率很高。

运维重启后，没有多久，又有人反映系统访问很慢，这时运维人员说有大量的fgc产生。顿时来兴趣了，前段时间刚参加完Zee老师的培训，一直没有实践的机会，这次也是报着试试看的心态，尝试的去分析定位问题。

先top一下，发现单cpu%us一直处于100%。

在执行top时，要习惯性的点下1，这样才能看到每个CPU的使用率，如果不点，则看到的是所有CPU的平均值，像这样单CPU高的情况就会被平均掉，会遗漏掉问题。

查看gc：jstat-gcutil 7313 1000

从上图来看，jvm一直在频繁的FGC。新生代内存爆满。老年代内存爆满！怎么回事？难道是不断创建大对象，一直回收不了？

从单CPU高到查看JVM的GC，是考虑到对于串行full GC来说，会导致单CPU高的情况。

接着查看后台日志，出现大量的sql相关报错：

因为日志中有堆栈信息，和SQL相关，并且jstat中看到heap也已经满了，所以接下来就要查看heapdump。

打印相关进程的heapdump。开始借助MAT工具进行分析。

命令：jmap-dump:format=b,file=test.hprof 7313

发现ExecuteThread: '0' for queue: 'weblogic.kernel.Default(self-tuning)'占用内存1.4G，总的内存才1.7G。

根据可疑的问题点，查看一下Threadstack：

这里主要是查看和业务代码相关的行，从而找到调用点。

从上图可以看出，执行程序代码PreparedSQLQuery导致的问题。这段是sql代码，是否可以定位到具体的sql语句呢？

再看另一图：

从上图可以看到有一个thread消耗掉了1.5G的内容。展开查看其中的正在执行的sql。

从上图的左边的属性值中，可以看到当前正在执行的sql。

结合后台日志大量提示sql问题，可以确定，这条SQL是本次问题的关键所在。

既然拿到了具体的sql，那么就去相应的库中看一下！

拿着sql到相应的数据库中执行。

发现sql长时间没有响应，统计一下数据量大小，SQL查询出来的数据量是537755，表1中的数据总量是810093，表2中的数据总量是537755。

但是根据实际业务规则，这条SQL应该查询出来一条记录。这是怎么回事？

看一下2张表的结构（这里只列出SQL涉及到的列）：

表1：

表2：

再看一下2张表的索引信息：

表1：

表2：

接下来看一下原SQL的执行计划：

说明下执行计划的相关知识：

结合表结构和执行计划，第1张表进行了唯一索引扫描，第2张表则是索引快速扫描，似乎没有什么问题，但是cost和rows很高，并且主要来自于第2张表中。

分析一下原SQL,发现关联表缺少了关联条件，优化一下SQL，查询出来的记录确实是一条，执行时间在180ms左右。

再查看执行计划：

从执行计划来看，添加了关联条件后，成本值大大降低。

经跟开发沟通确认后，他们确实是在测试环境调整了这条SQL，测试环境恢复正常。了解到在生产环境对应的SQL语句是正确的。

本次算是自己第一次真正地分析定位到具体问题，具体原因，有些小兴奋。

通知本次实践，深刻体会到思路很重要，知识很重要，实践也很重要！通过不断地积累，不断地实践,才能把别人的理论转化为自己的知识体系。

在这里我衷心地感谢Zee老师的倾囊相授以及左同学的耐心指导！！！