问题描述 简要说明下，系统是一个微信第第三方平台，用于托管微信公众号和小程序的。
在一个普普通通的晚上，19点开始有公众号管理员向我们反馈，托管在我们平台的公众号一直提示 “该公众号提供的服务出现异常，请稍后再试 “。
问题排查 验证问题 自己去对应的公众号验证，发送消息，确确实实提示”该公众号提供的服务出现异常，请稍后再试 “，影响到了公众号的正常服务。并且每次都是这个返回，说明服务其实是普遍性的异常了(这点其实挺重要，不过当时没引起注意)。
查看WEB服务日志 异常日志 验证问题后，首先当然是去看看日志(后续的日志和步骤都是事后整理的，并不完全和当时生产一致)是否异常，发现此时后台日志有不少的报错(也有对应的邮件监控通知),异常如下:
错误1：
1 2 3 4 5 6 7 8 9 10 11 12 13 ava.io.IOException: APR error: -32 at org.apache.coyote.http11.InternalAprOutputBuffer.writeToSocket(InternalAprOutputBuffer.java:291) at org.apache.coyote.http11.InternalAprOutputBuffer.writeToSocket(InternalAprOutputBuffer.java:244) at org.apache.coyote.http11.InternalAprOutputBuffer.flushBuffer(InternalAprOutputBuffer.java:213) at org.apache.coyote.http11.AbstractOutputBuffer.flush(AbstractOutputBuffer.java:305) at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:764) at org.apache.coyote.Response.action(Response.java:177) at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:349) at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:317) at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:110) at org.codehaus.jackson.impl.Utf8Generator.flush(Utf8Generator.java:1091) at org.codehaus.jackson.map.ObjectMapper.writeValue(ObjectMapper.java:1347) at org.springframework.http.converter.json.MappingJacksonHttpMessageConverter.writeInternal(MappingJacksonHttpMessageConverter.java:209)
错误2：
1 2 3 4 5 java.lang.IllegalStateException: getOutputStream() has already been called for this response org.apache.catalina.connector.Response.getWriter(Response.java:604) org.apache.catalina.connector.ResponseFacade.getWriter(ResponseFacade.java:198) org.apache.jasper.runtime.JspWriterImpl.initOut(JspWriterImpl.java:125) org.apache.jasper.runtime.JspWriterImpl.flushBuffer(JspWriterImpl.java:118)
初期就以为是微信服务端超过五秒后没有得到响应就认定为是服务器超时，主动断开连接并重发请求
access_log统计请求耗时 于是自己就去查看access_log.txt ，看看有多少请求是超时的，
1 2 3 4 5 6 [root@DEV-L002323 ~]# grep "callback" access_log.txt | awk '{print $13}' | sort -nr | head -n 5 793 793 750 750 750
如上，结果发现并没有来自微信的请求的响应是超过了五秒的。这是就犯难了。
access_log统计qps 于是，直接tail -f实时查看access_log.txt，看看有多少异常响应,结果发现来自微信的请求此时的响应都是404。看来是请求被拒绝了，查看tomcat配置如下:
1 2 3 4 5 6 7 8 9 <Server address="0.0.0.0" port="51542" shutdown="SHUTDOWN"> <!-- 此处省略部分配置... --> <Connector address="0.0.0.0" port="31542" maxThreads="150" minSpareThreads="25" enableLookups="false" redirectPort="8443" acceptCount="200" connectionTimeout="40000" disableUploadTimeout="false"/> <!-- 此处省略部分配置... --> </Service> </Server>
看其中的两个参数：
maxThreads：tomcat起动的最大线程数，即同时处理的任务个数，配置为150
acceptCount：当tomcat起动的线程数达到最大时，接受排队的请求个数，配置为200
可以知道，请求并发数超过150时，请求就会进入到等待队列中，当队列也达到上限的时候，请求就会被拒绝，直接返回异常，查看日志就是直接返回了404状态（服务器无法正常提供信息，或是服务器无法回应)。
看来是请求并发太高了的原因，于是就去统计服务器的并发：
利用awk，统计时间点相同的条数并排序，得出每秒并发量，取其前50
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 [logop@SZC-L0065219 tm_icore-wechatmgt-prdSF30704]$ grep "callback" access_log.20180412.txt | awk '{print $7}' | uniq -c | sort -nr | head -n 5 447 [12/Apr/2018:18:17:13 356 [12/Apr/2018:18:17:12 342 [12/Apr/2018:18:17:11 340 [12/Apr/2018:18:17:09 ... 省略部分 ... 176 [12/Apr/2018:18:16:46 161 [12/Apr/2018:18:16:47 160 [12/Apr/2018:18:16:51 ... 省略部分 ... 95 [12/Apr/2018:18:18:42 92 [12/Apr/2018:18:18:40 88 [12/Apr/2018:18:18:39 ... 省略部分 ... 15 [12/Apr/2018:21:58:44 15 [12/Apr/2018:21:08:10 14 [12/Apr/2018:21:35:42 ... 省略部分 ...
可以看出在高峰时期，并发量的确是超过了服务器所配置的上限，能理解当时请求出现异常的原因了。但是，从这个统计也可以看出，并发量到后面已经降下来了，按理说服务器也应该恢复正常才对，可是公众号还是照样报错。看来是服务没有恢复，此时考虑是否是服务器相关资源不够导致。
查看系统资源状态 分别查看当时的cpu和内存使用情况，如下:
可以看出，内存使用都还算正常，CPU抖动不太正常[问题查看请看另一篇博文—–定位CPU异常抖动—tomcat热部署的坑 ]，但是不太影响系统的文档运行。那么接下来就考虑是数据库方面的问题。于是立刻找了DBA做让其查看对应时段的数据库状态。
查看数据库状态
以下引自DBA的分析
从Apr 12 17:35:16,实例的cgroup cpu限制才5%
1 2 3 4 5 6 7 8 9 10 zzz ***Thu Apr 12 17:35:16 CST 2018 ==================== Cgroup Performance: proc ==================== DB_TYPE INSTANCE_NAME DATA_VOLUME VOLUME_FUSER PROC_COUNT PROC_PID_LIST ------- ------------- ----------- ------------ ---------- ------------- mysql WCMGT /paic/my3385 mysql:1 2 19491,20693 ==================== Cgroup Performance: cpu ==================== DB_TYPE INSTANCE_NAME CPU_USER CPU_SYS CPU_USED CPU_ALLO ALLO_RATE CPU_GLOB GLOB_RATE ------- ------------- -------- ------- -------- -------- --------- -------- --------- mysql WCMGT 0.1 0.0 0.2 4.0 5.0% 20 1.0%
到了Apr 12 17:35:55 实例的cpu限制就100% ，此时这个实例执行任何平时很快的操作都是很慢的………
1 2 3 4 5 6 7 8 9 10 11 zzz ***Thu Apr 12 17:35:55 CST 2018 ==================== Cgroup Performance: proc ==================== DB_TYPE INSTANCE_NAME DATA_VOLUME VOLUME_FUSER PROC_COUNT PROC_PID_LIST ------- ------------- ----------- ------------ ---------- ------------- mysql WCMGT /paic/my3385 mysql:1 2 19491,20693 ==================== Cgroup Performance: cpu ==================== DB_TYPE INSTANCE_NAME CPU_USER CPU_SYS CPU_USED CPU_ALLO ALLO_RATE CPU_GLOB GLOB_RATE ------- ------------- -------- ------- -------- -------- --------- -------- --------- mysql WCMGT 4.1 0.0 4.0 4.0 100.0% 20 20.0%
从历史vmstat命令输出看到从Apr 12 17:35:47，运行队列立马从原来的几个变成了60多了…….,CPU 空闲从原来的98断崖下降到77
1 2 3 4 5 6 7 8 9 10 11 12 zzz ***Thu Apr 12 17:35:10 CST 2018 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 1 0 0 196056336 1902464 30634752 0 0 1 15 0 0 1 1 98 0 0 2 0 0 196055616 1902464 30634768 0 0 0 1076 2772 1661 3 0 96 0 0 3 0 0 196053792 1902464 30634872 0 0 0 1660 2408 1579 2 0 97 0 0 zzz ***Thu Apr 12 17:35:47 CST 2018 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 21 0 0 196056464 1902464 30635304 0 0 1 15 0 0 1 1 98 0 0 49 0 0 196053856 1902464 30635328 0 0 0 1980 12848 6492 23 0 76 1 0 61 0 0 196051072 1902464 30635352 0 0 0 1476 13255 6366 23 0 77 0 0
从历史的iostat输出看到从Apr 12 17:35:48，数据库的写入量有突增。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 zzz ***Thu Apr 12 17:35:11 CST 2018 avg-cpu: %user %nice %system %iowait %steal %idle 3.68 0.00 1.25 0.00 0.00 95.06 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 37.00 0.00 40.00 0.00 308.00 15.40 0.00 0.03 0.00 0.03 0.03 0.10 ... zzz ***Thu Apr 12 17:35:48 CST 2018 avg-cpu: %user %nice %system %iowait %steal %idle 22.99 0.00 0.62 0.00 0.00 76.39 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 25.00 0.00 74.00 0.00 964.00 26.05 0.01 0.07 0.00 0.07 0.07 0.50 ...
可以看出服务从17：35开始，并发上来后，这个sql就慢了，但是主机上的其他实例负载都很低。由此认为是应用前端应用短时间内徒增导致后端数据库处理的挤压，后面就是一个恶性循环的结果，达到cpu的限制后，
DB端基本hang了，从监控看到dml，读的量都低了。从根本上来说需要创建index来优化，这样后端处理的效率高了，才不会积压，单单数据库查询需要0,4s 对敏感业务来说，也是挺长的一个时间了，sql本身这么简单了。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 # Time range: 2018-04-12 17:15:03 to 17:45:01 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 231599s 83us 112s 31s 66s 24s 39s # Lock time 2s 31us 585ms 283us 167us 9ms 89us # Rows sent 7.85k 0 20 1.09 1.96 1.17 0.99 # Rows examine 4.59G 0 711.51k 649.25k 683.15k 191.90k 683.15k # Query size 2.42M 51 1.50k 342.84 346.17 72.84 346.17 # Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== ================= ===== ======= ===== ========== # 1 0x551708214D03E990 231329.6276 99.9% 6765 34.1951 16.38 SELECT weixin_location # 2 0x831F70EA1FBA0F69 151.1057 0.1% 11 13.7369 65.22 SELECT weixin_menu_click_log # 3 0x3F30804C8E27D59B 60.7554 0.0% 15 4.0504 2.15 SELECT weixin_gzuserinfo # MISC 0xMISC 57.9683 0.0% 617 0.0940 0.0 <26 ITEMS> # Query 1: 3.76 QPS, 128.66x concurrency, ID 0x551708214D03E990 at byte 3458565 # This item is included in the report because it matches --limit. # Scores: V/M = 16.38 # Time range: 2018-04-12 17:15:03 to 17:45:01 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 91 6765 # Exec time 99 231330s 302ms 106s 34s 66s 24s 40s # Lock time 96 2s 31us 585ms 298us 167us 9ms 89us # Rows sent 89 7.02k 0 9 1.06 1.96 0.78 0.99 # Rows examine 99 4.59G 710.18k 711.51k 710.78k 683.15k 0 683.15k # Query size 92 2.25M 349 349 349 349 0 349 # String: # Hosts 30.16.45.43 (2257/33%), 30.16.45.29 (2256/33%)... 1 more # Users wcmgtopr # Query_time distribution # 1us # 10us # 100us # 1ms # 10ms # 100ms ######################### # 1s # # 10s+ ################################################################ # Tables # SHOW TABLE STATUS LIKE 'weixin_location'\G # SHOW CREATE TABLE `weixin_location`\G # EXPLAIN /*!50100 PARTITIONS*/ select this_.ID as ID102_0_, this_.ACCOUNTID as ACCOUNTID102_0_, this_.ADDTIME as ADDTIME102_0_, this_.LATITUDE as LATITUDE102_0_, thi s_.LONGITUDE as LONGITUDE102_0_, this_.NICKNAME as NICKNAME102_0_, this_.OPENID as OPENID102_0_, this_.PRECISIONWEIXIN as PRECISIO8_10 2_0_ from weixin_location this_ where this_.OPENID='oVJbgjmrGZJ-c99QSdbVxbsqUrDM'\G
从2018-04-12 16:45:02 to 17:15:01来看，是正常的，此时并发很低。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 # Time range: 2018-04-12 16:45:02 to 17:15:01 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 1105s 94us 1s 283ms 433ms 169ms 356ms # Lock time 369ms 29us 330us 94us 125us 25us 93us # Rows sent 3.53k 0 20 0.93 1.96 1.17 0.99 # Rows examine 1.95G 1 710.18k 524.78k 683.15k 299.80k 683.15k # Query size 1.20M 51 1.50k 323.88 346.17 107.97 346.17 # Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== =============== ===== ====== ===== ============= # 1 0x551708214D03E990 1100.6859 99.6% 2882 0.3819 0.00 SELECT weixin_location # MISC 0xMISC 3.9385 0.4% 1019 0.0039 0.0 <25 ITEMS> # Query 1: 1.60 QPS, 0.61x concurrency, ID 0x551708214D03E990 at byte 769413 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: 2018-04-12 16:45:02 to 17:15:01 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 73 2882 # Exec time 99 1101s 303ms 623ms 382ms 455ms 39ms 374ms # Lock time 69 258ms 29us 142us 89us 113us 20us 93us # Rows sent 76 2.69k 0 6 0.95 1.96 0.53 0.99 # Rows examine 99 1.95G 709.80k 710.18k 709.98k 683.15k 0 683.15k # Query size 79 982.24k 349 349 349 349 0 349 # String: # Databases wcmgt # Hosts 30.16.45.42 (971/33%), 30.16.45.29 (958/33%)... 1 more # Users wcmgtopr # Query_time distribution # 1us # 10us # 100us # 1ms # 10ms # 100ms ################################################################ # 1s # 10s+ # Tables # SHOW TABLE STATUS FROM `wcmgt` LIKE 'weixin_location'\G # SHOW CREATE TABLE `wcmgt`.`weixin_location`\G # EXPLAIN /*!50100 PARTITIONS*/ select this_.ID as ID102_0_, this_.ACCOUNTID as ACCOUNTID102_0_, this_.ADDTIME as ADDTIME102_0_, this_.LATITUDE as LATITUDE102_0_, thi s_.LONGITUDE as LONGITUDE102_0_, this_.NICKNAME as NICKNAME102_0_, this_.OPENID as OPENID102_0_, this_.PRECISIONWEIXIN as PRECISIO8_10 2_0_ from weixin_location this_ where this_.OPENID='oVJbgjh1uh7BfKuWcEZil_lxLvXI'\G
从dba的统计分析来看，有两方面的问题：
并发徒增导致数据写入突增，CPU利用率飙升
慢查询语句在cpu资源少时，查询效率更低，从而拖慢请求的响应时间，造成恶性循环
至此，问题就清晰了。立刻优化慢查询语句，释放积压请求。从而恢复服务。
总结 造成这次问题的主要原因其实是平安被授权管理了一个关注量几百万的公众号，该公众号当晚推送了一篇博文，于是，就造成了并发超过了服务器的承受能力导致服务器异常。
在这次问题的处理过程中，发现了一些不足，也吸取了些教训。
缺少预警的心理，对于新接入的服务(公众号)没有去做对应的 请求量估算
监控缺失，数据库层面，没有配置对应的慢查询警告通知
对于解决问题的思路定性不够，容易被异常打乱方向,应该明确问题的排查思路[日志检查->资源检查->数据库检查]
