记一次生产环境CPU飙升100%的排查经历

一、前言

是这样的,我的项目是使用传统的Spring+SpringMVC+Mybatis架构的,有PC端后台管理系统,也有微信端H5网页,也就是一个微信公众号项目;项目部署采用Windows Server2008服务器,数据库使用·Mysql5.7·,最开始运行都非常的稳定,自动上线了一款功能:“微信打卡” 之后,规定每天只能打卡一次,并且规定时间点为6:00-9:00 这个时间段才能打卡,不在这个时间段则无法打卡,我的微信公众号用户有10万多,具体每天打卡量没有去具体的统计。

二、并发场景下产生的现象

6:00-9:00 这个时间段内,大量用户集中打卡,难免产生并发,服务器CPU持续飙升为100%,远程连接Windows服务器,鼠标卡死,无法操作,感觉整个系统瘫痪了,起初是以为生成的日志文件过多,于是每个月定时去删除上一个月的日志,最后发现不是,除了在6:00-9:00 这个时间段内外的其他时间,访问微信公众号H5网页,非常的流畅和稳定,页面响应也非常的快,只有在这个时间段内大量页面卡死,等待服务器响应,于是就有了后面的三次排查经历;

三、排查经历

1. 第1次CPU飙升100%的排查经历(未定位到核心)

第一次遇到这个问题,查看日志: Data source rejected establishment of connection, message from server : "Too many connections" 大概意思是连接数太多,于是我调整了mysql默认的连接数,调整至500,之前是150

并 发量过高,请求数过多,导致mysql连接数超过了最大连接数的阀值,现在是150,我先把阀值由150加到500

在这里插入图片描述
但是这个不是核心根本问题,于是开始了第二次排查

2. 第2次CPU飙升100%的排查经历(未定位到核心)

异常日志如下图:
在这里插入图片描述
通过查询资料,网上说是连接池的问题,修改对空闲连接池回收的时间,最开始默认为每3分钟回收一次,最后修改为没30分钟回收一次

     <!-- 超时时间;单位为秒。180秒=3分钟 -->
    <property name="removeAbandonedTimeout" value="180" />

在这里插入图片描述

3. 第3次CPU飙升100%的排查经历(SQL语句优化)

这次,服务器整个功能瘫痪了,点击都无法响应,大量请求阻塞,于是又开始了第三次的排次,这次排查以先定位慢查询为思路,然后挑出哪些慢查询SQL语句存在问题,然后对SQL语句进行优化处理。

  • 执行查询计划:
show full processlist; -- 列出全部SQL执行计划

查出有大量的SQL存在慢查询等待,state一直为Sending data
在这里插入图片描述
参数说明:

字段 解释
id ID标识,要kill一个语句的时候很有用
use 当前连接用户
host 显示这个连接从哪个ip的哪个端口上发出
db 链接哪个数据库
command 连接状态,一般是休眠(sleep),查询(query),连接(connect)
time 连接持续时间,单位是秒
state 显示当前sql语句的状态
info 显示这个sql语句

其中state的状态十分关键,下表列出state主要状态和描述,这里只列举常见的几个,详细请百度:

字段 描述
Locked 被其他查询锁住了
Sending data 正在处理SELECT查询的记录,同时正在把结果发送给客户端。
Sleeping 正在等待客户端发送新请求.
  • 挑出具体的SQL语句执行执行计划EXPLAIN:
EXPLAIN SELECT
	f.nick_name AS nickName,
	f.headimgurl AS headImgUrl,
	f.open_id AS openId
FROM
  t_member m
LEFT JOIN t_follow f ON f.open_id = m.open_id WHERE m.green_card = '031011501705982345'
AND f.del_flag = '0'
AND m.del_flag = '0'

t_member 表的索引是普通索引 ,索引名字为member_openid_index, 索引的字段为open_id
t_follow 表的索引是唯一索引 , 索引名字为 唯一, 索引的字段为 open_id
从下面的执行结果图可以看出,t_follow表的唯一索引并没有使用上,而是使用的全表扫描,那么这就找到问题的核心了,一是找出为什么两个表左链接时,其中一张表的唯一索引没有使用上; 二是如何让t_follow表的所有使用上,不去全表扫描。
最后发现,光两张表连接字段加索引还不够,需要在m.green_card上也加一个索引即可,我加了普通索引

在这里插入图片描述
再次执行执行计划,就使用了索引查询:
在这里插入图片描述

  • 执行查询计划:
show full processlist; -- 列出全部SQL执行计划

数据库连接,都是空闲状态,等待客户端发送新的请求,没有产生慢查询的阻塞
在这里插入图片描述

  • 执行计划字段说明:
字段 解释
id 表示查询的类型
select_type 表示选择标识符
table 表示输出结果集的表
partitions 表示匹配的分区
type 表示表的连接类型
possible_keys 表示查询时可能使用的索引
key 表示查询时实际使用的索引
key_len 表示索引字段的长度
ref 表示列与索引的比较
rows 表示扫描出的行数(估算的行数)
filtered 表示按表条件过滤的行百分比
Extra 表示执行情况的描述和说明

四、总结

项目生产环境的数据库一定要建索引,这个非常重要,而且需要根据重要的SQL语句分析索引该不该建、建哪些字段、建什么类型的索引,这些工作不可以忽略,以后我也会注重这个环节;

五、参考

  1. Mysql left join不使用索引问题总结
  2. 查一次left join没有走索引以及原因
发布了327 篇原创文章 · 获赞 230 · 访问量 79万+
展开阅读全文

windows下javaweb运行2个多小时后导致CPU突然飙升至70%

02-23

使用springboot做了一个web小程序,只是实现了简单的查库功能。通过批处理命令 ``` @echo off echo "start-up......" set Path=%path%;C:\Program Files\Java\jdk1.8.0_191\bin set BASE_HOME=%cd% java -Xms128m -Xmx128m -jar %BASE_HOME%\querytool.jar --spring.config.location=%BASE_HOME%\config\application.yml > %BASE_HOME%\log\batchLog%date:~0,4%%date:~5,2%%date:~8,2%.log @pause ``` 启动后没做任何操作,2个小时后cpu飙升到70%左右,如下图: ![图片说明](https://img-ask.csdn.net/upload/201902/23/1550888449_454199.png) jstat -gcutil查看垃圾回收统计情况如下: ![图片说明](https://img-ask.csdn.net/upload/201902/23/1550891455_339561.png) 消耗大的线程如下(包含使用jmap -heap的信息): ``` "VM Periodic Task Thread" os_prio=2 tid=0x000000005412b000 nid=0x1504 waiting on condition "NioBlockingSelector.BlockPoller-1" #18 daemon prio=5 os_prio=0 tid=0x0000000055403000 nid=0x18f0 runnable [0x000000005dbcf000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl.resetWakeupSocket0(Native Method) at sun.nio.ch.WindowsSelectorImpl.resetWakeupSocket(Unknown Source) - locked <0x00000000f9a57f00> (a java.lang.Object) at sun.nio.ch.WindowsSelectorImpl.doSelect(Unknown Source) at sun.nio.ch.SelectorImpl.lockAndDoSelect(Unknown Source) - locked <0x00000000f98b2aa8> (a sun.nio.ch.Util$3) - locked <0x00000000f98b2a98> (a java.util.Collections$UnmodifiableSet) - locked <0x00000000f98b2948> (a sun.nio.ch.WindowsSelectorImpl) at sun.nio.ch.SelectorImpl.select(Unknown Source) at org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBlockingSelector.java:298) Locked ownable synchronizers: - None "http-nio-8081-ClientPoller-0" #29 daemon prio=5 os_prio=0 tid=0x0000000057c5b800 nid=0x894 runnable [0x000000005ea2f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(Unknown Source) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(Unknown Source) at sun.nio.ch.WindowsSelectorImpl.doSelect(Unknown Source) at sun.nio.ch.SelectorImpl.lockAndDoSelect(Unknown Source) - locked <0x00000000f9931328> (a sun.nio.ch.Util$3) - locked <0x00000000f9931318> (a java.util.Collections$UnmodifiableSet) - locked <0x00000000f9931158> (a sun.nio.ch.WindowsSelectorImpl) at sun.nio.ch.SelectorImpl.select(Unknown Source) at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:825) at java.lang.Thread.run(Unknown Source) Locked ownable synchronizers: - None "http-nio-8081-ClientPoller-1" #30 daemon prio=5 os_prio=0 tid=0x0000000057c5c800 nid=0x10a8 runnable [0x000000005ebaf000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(Unknown Source) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(Unknown Source) at sun.nio.ch.WindowsSelectorImpl.doSelect(Unknown Source) at sun.nio.ch.SelectorImpl.lockAndDoSelect(Unknown Source) - locked <0x00000000f989d8d8> (a sun.nio.ch.Util$3) - locked <0x00000000f989d8c8> (a java.util.Collections$UnmodifiableSet) - locked <0x00000000f989d6a8> (a sun.nio.ch.WindowsSelectorImpl) at sun.nio.ch.SelectorImpl.select(Unknown Source) at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:825) at java.lang.Thread.run(Unknown Source) Locked ownable synchronizers: - None // 此处是使用jamp -heap 的报错信息 Attaching to process ID 7156, please wait... Error attaching to process: sun.jvm.hotspot.runtime.VMVersionMismatchException: Supported versions are 25.191-b12. Target VM is 25.201-b09 sun.jvm.hotspot.debugger.DebuggerException: sun.jvm.hotspot.runtime.VMVersionMis matchException: Supported versions are 25.191-b12. Target VM is 25.201-b09 at sun.jvm.hotspot.HotSpotAgent.setupVM(HotSpotAgent.java:435) at sun.jvm.hotspot.HotSpotAgent.go(HotSpotAgent.java:305) at sun.jvm.hotspot.HotSpotAgent.attach(HotSpotAgent.java:140) at sun.jvm.hotspot.tools.Tool.start(Tool.java:185) at sun.jvm.hotspot.tools.Tool.execute(Tool.java:118) at sun.jvm.hotspot.tools.HeapSummary.main(HeapSummary.java:49) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl. java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces sorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at sun.tools.jmap.JMap.runTool(JMap.java:201) at sun.tools.jmap.JMap.main(JMap.java:130) Caused by: sun.jvm.hotspot.runtime.VMVersionMismatchException: Supported version s are 25.191-b12. Target VM is 25.201-b09 at sun.jvm.hotspot.runtime.VM.checkVMVersion(VM.java:227) at sun.jvm.hotspot.runtime.VM.<init>(VM.java:294) at sun.jvm.hotspot.runtime.VM.initialize(VM.java:370) at sun.jvm.hotspot.HotSpotAgent.setupVM(HotSpotAgent.java:431) ... 11 more ``` 整个程序启动后就没有使用,cup消耗大的线程也是属于tomcat的nio,实在是找不到导致CPU飙升的原因,希望各位大大能提点下。 问答

没有更多推荐了,返回首页

©️2019 CSDN 皮肤主题: 编程工作室 设计师: CSDN官方博客

分享到微信朋友圈

×

扫一扫,手机浏览