Java应用服务器性能问题分析

常见问题

一、内存飙高

归根结底，都是代码中某一刻的内存数据过高引起服务器内存增加。

文件导入和导出，针对文件的读写代码不合理大数据常驻内存；或者导入/导出并发量较大。
存在大表的全表查询(或者多表级联笛卡尔积查询)，查出的结果集常驻内存；或者某表查询数据量较大且并发数过大（一次查询数据量*并发数）。
类对象实例化使用后未释放或者其它临时数据未释放。

二、CPU飙高

某些线程在做无阻塞的运算，简单的例子while(true)中不停的做运算，没有任何阻塞。写程序时，如果需要做很久的计算，可以适当将程序sleep下。
线程上下文切换、当启动了很多线程，而这些线程都处于不断的阻塞状态（锁等待、IO等待等）和执行状态的变化过程中。当锁竞争激烈时，很容易出现这种情况。（文件读写未使用NIO等）
序列化和反序列操作过于频繁或者目标数据量较大导致资源长时间占用。(xml/json)
频繁GC（内存异常飙高导致），访问量高时，有可能造成频繁的GC、甚至FGC。当调用量大时，内存分配过快，就会造成GC线程不停的执行，导致CPU飙高。
加密、解密。
正则表达式校验，大概原因是：Java 正则表达式使用的引擎实现是 NFA 自动机，这种引擎在进行字符匹配会发生回溯（backtracking）。

三、客户端请求阻塞

服务器CPU和内存资源看上去正常，通过JVM监控器发现很多Blocked请求线程；以下几个方法请勿出现在生产代码中，请求并发量大的情况下，很容导致请求线程阻塞。

System.out.println(XX)
logger.debug()
e.printStackTrace()
DefaultHttpClient.execute()未设置连接超时时间。

如何定位原因

一、CPU和内存情况分析

非容器部署时，通过top命令查看进程占用的CPU和内存资源，找出占用高的进程。

image.png
docker容器部署时，通过 “docker stats <容器id或者名称>”查看cpu和内存占用情况。

imagef7594.png
通过jvisualVM或者JConsole查看JVM的CPU、内存和线程情况，如果是CPU飙高或者线程阻塞需要dump线程信息定位问题代码。

image89810.png

image702ba.png
线程dump分析，如果开发人员能力经验不足以肉眼分析定位问题，将dump出来的内容拷贝到txt文件中，访问在线分析平台http://fastthread.io/ ，上传dump文件，点击分析按钮，等待一小会儿后即可得出分析结果。重点关注 “CPU consuming threads”类别下的线程，点击具体某个线程进一步定位问题代码。

imaged0dbd.png

imageea94c.png

image61a37.png
如果是内存问题推荐使用jmap命令dump heap信息，然后使用MAT分析工具进行分析，移步详见此文>>。

最新MAT工具下载如果是64位，直接打开会提示“Java was started but returned exit code=13”报错，解决方法重新安装64位的jdk版本。我是直接改掉对应启动的jdk路径下的javaw.exe程序，指向64位的 jdk/bin目录下的javaw.exe。
# 导出堆内存信息命令：jmap -dump:<dump-options> <pid> jmap -dump:format=b,file=heap.bin 6 # jmap -histo:live <pid> #统计对象count ，live表示在使用 # jmap -histo <pid> >mem.txt #打印比较有多少个对象占了多少内存的信息，一般重定向文件

题外话：如果是Spring Boot2.0应用并且配置了actuator，配置开启堆内存和线程的dump接口，通过浏览器访问即可获得dump文件。

二、tomcat日志分析

以上步骤还不能定位问题原因的，只能进行应用日志的分析。以下介绍一些使用linux命令的分析技巧。（当然如果已经搭建好ELK，可以通过ELK快速筛选异常时段的请求日志信息）

通过zabbix等监控工具，定位应用CPU或者内存异常时段，日志排查以异常时段前后延长一小段时间为主。
题外话：
1.win10支持linux子系统，不用特地为了使用linux命令装个虚拟机，详情搜索win10 linux子系统安装。

或者可以安装git客户端程序，利用其提供的Git Bash客户端即可享受Linux的相关命令。

### 分析tomcat的access日志，假设CPU或内存飙升时段是2019-08-29 16:00:00 ~16:40:00之间
## 截取指定时段的日志内容
# 1.日志时间格式为 -“2019-08-29 09：25：55606后面跟日志内容”
sed -n '/2019-08-29 16:00:00/,/2019-08-29 16:40:00/'p localhost_access_log.2019-08-29.txt > analyse_time.log
# 2.日志时间格式为 -“22/Feb/2019:15:57:00”
sed -n '/29\/Aug\/2019:16:00:00/,/29\/Aug\/2019:16:40:00/'p  localhost_access_log.2019-08-29.txt > analyse_time.log

## 获取指定时段QPS（升序排列,看最后几列最大qps数据即可评判是否并发数过大）
cat analyse_time.txt|awk '{Times[$4]++}END{for(a in Times) print a,Times[a]}'| sort -nk2|column -t > analyse_qps.log

## 获取指定时段按请求URL分组的QPS（带url参数）
cat analyse_time.txt|\
    awk '{gsub("\\:","_",$4);gsub("\\[","",$4);Times[$4]++;TimesURLs[$4":"$7]++}
      END{for(tturl in TimesURLs)
             {
               split(tturl,INFO,"\\:")
               printf("时间:%s 总访问量:%d 访问的URL:%s 访问量:%d\n",INFO[1],Times[INFO[1]],INFO[2],TimesURLs[tturl])
             }
         }'|sort -nk2 -nrk4|column -t > analyse_qps_url_by_params.log

## 获取指定时段按请求URL分组的QPS（不带url参数）
cat analyse_time.txt|\
    awk '{gsub("\\:","_",$4);gsub("\\[","",$4);split($7,UP,"\\?");Times[$4]++;TimesURLs[$4":"UP[1]]++}
      END{for(tturl in TimesURLs)
             {
               split(tturl,INFO,"\\:")
               printf("时间:%s 总访问量:%d 访问的URL:%s 访问量:%d\n",INFO[1],Times[INFO[1]],INFO[2],TimesURLs[tturl])
             }
         }'|sort -nk2 -nrk4|column -t > analyse_qps_url.log

## 获取指定时段按IP分组的访问次数
cat analyse_time.txt|awk '{IPS[$1]++}END{for(a in IPS) print a,IPS[a]}'| sort -nk2|column -t > analyse_ip_total.log

### 通过以上access日志大致可以定位出访问频繁的请求url以及进一步缩短定位的日志时段，根据上一步骤得到的请求url和时间分析具体的应用日志
## 截取指定时段的日志内容同上
sed -n '/2019-08-29 16:00:00/,/2019-08-29 16:40:00/'p app.info.log > analyse_info_time.log

## 假设查找到 16:40:30秒下的请求url"app/job/export"请求过于频繁，可以通过以下定位到具体应用日志
cat analyse_info_time.log|grep '2019-08-29 16:40:30'|grep 'app/job/export' >analyse_info_url.log

## 如果应用日志过多，比如有app.info.log~app.info.log.20 多个日志文件，如何快速定位要查询的内容在哪个日志文件中？
find app.info.log.*| xargs grep -ri "SIMPLEJOB-Thread-119" -l
## 查找指定内容并显示前后100行
cat app.info.log|grep -C 100 "SIMPLEJOB-Thread-119"