java web线上请求问题排查

最新推荐文章于 2023-08-22 18:00:17 发布

vioao

最新推荐文章于 2023-08-22 18:00:17 发布

阅读量1.6k

点赞数

分类专栏：项目经验文章标签： JAVA 高并发慢查询 TOMCAT

本文链接：https://blog.csdn.net/u010862794/article/details/79997520

版权

项目经验专栏收录该内容

16 篇文章 1 订阅

订阅专栏

问题描述

简要说明下，系统是一个微信第第三方平台，用于托管微信公众号和小程序的。
在一个普普通通的晚上，19点开始有公众号管理员向我们反馈，托管在我们平台的公众号一直提示 “该公众号提供的服务出现异常，请稍后再试“。

问题排查

验证问题

自己去对应的公众号验证，发送消息，确确实实提示”该公众号提供的服务出现异常，请稍后再试“，影响到了公众号的正常服务。并且每次都是这个返回，说明服务其实是普遍性的异常了(这点其实挺重要，不过当时没引起注意)。

查看WEB服务日志

异常日志

验证问题后，首先当然是去看看日志(后续的日志和步骤都是事后整理的，并不完全和当时生产一致)是否异常，发现此时后台日志有不少的报错(也有对应的邮件监控通知),异常如下:

错误1：

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：

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，看看有多少请求是超时的，

[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配置如下:

<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

[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抖动不太正常[问题查看请看另一篇博文—–定位CPU异常抖动—tomcat热部署的坑]，但是不太影响系统的文档运行。那么接下来就考虑是数据库方面的问题。于是立刻找了DBA做让其查看对应时段的数据库状态。

查看数据库状态

以下引自DBA的分析

从Apr 12 17:35:16,实例的cgroup cpu限制才5%

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% ，此时这个实例执行任何平时很快的操作都是很慢的………

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

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，数据库的写入量有突增。

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本身这么简单了。

# 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来看，是正常的，此时并发很低。

# 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的统计分析来看，有两方面的问题：
1. 并发徒增导致数据写入突增，CPU利用率飙升
2. 慢查询语句在cpu资源少时，查询效率更低，从而拖慢请求的响应时间，造成恶性循环

至此，问题就清晰了。立刻优化慢查询语句，释放积压请求。从而恢复服务。

总结

造成这次问题的主要原因其实是平安被授权管理了一个关注量几百万的公众号，该公众号当晚推送了一篇博文，于是，就造成了并发超过了服务器的承受能力导致服务器异常。

在这次问题的处理过程中，发现了一些不足，也吸取了些教训。
1. 缺少预警的心理，对于新接入的服务(公众号)没有去做对应的请求量估算
2. 监控缺失，数据库层面，没有配置对应的慢查询警告通知
3. 对于解决问题的思路定性不够，容易被异常打乱方向,应该明确问题的排查思路[日志检查->资源检查->数据库检查]

vioao

关注

0
点赞
踩
1

收藏

觉得还不错? 一键收藏
0
评论
java web线上请求问题排查

问题描述简要说明下，系统是一个微信第第三方平台，用于托管微信公众号和小程序的。在一个普普通通的晚上，19点开始有公众号管理员向我们反馈，托管在我们平台的公众号一直提示 “该公众号提供的服务出现异常，请稍后再试“。问题排查验证问题自己去对应的公众号验证，发送消息，确确实实提示”该公众号提供的服务出现异常，请稍后再试“，影响到了公众号的正常服务。并且每次都是这个返回，说明...
复制链接

扫一扫

专栏目录