记一次 Java 应用性能问题定位

问题

系统大部分时间响应速度正常(平均响应时长在 50 - 500 ms),但近期隔一段时间,前端请求频发卡顿、请求超时的问题,但是一会就又好了;虽然能用,但这对于程序员来说是不能忍的,必须揪出的问题,搞定它;

当前服务现状

服务是一个基于 Java 生态圈开发的工作流调度系统,主要由两个部分组成(耦合在一起了)

  • 内嵌的 Jetty server + spring web 服务: restfull api 的方式提供工作流管理服务,系统的权限认证外接的 Iam sdk;
  • 基于 quartz 的 DAG 工作流调度模块:提供 DAG 任务调度流转服务;

由两台 server 以双主的方式提供服务,server 使用的组件包括

  • mysql 使用阿里的 Druid 连接池
  • redis 集群
  • rockemq
  • zookeeper

定位过程

定位点

  • JVM GC 问题
  • mysql 数据库瓶颈,大表,复杂查询
  • 线程阻塞、死锁
  • 服务器资源 cpu 内存 io 瓶颈
  1. 查看 gc 日志,基本正常,除了一天服务器使用 Java 7 young gc 频繁了一些,后期需要优化;先排除 gc 的问题;
  2. 联系 mysql dba,其反馈数据库监控显示无明显有规律的慢查询;此外,自己也手写脚本循环请求数据库访问,无任何异常,排除数据库的问题;
  3. 看下线程栈是否正常,Jstack 是 java 性能问题定位神器,之前 hiveserver 定时挂的问题(todo)也是通过 jstack 定位到的,通过几次 jstack 发现线程基本正常,没有发现过多的线程,以及阻塞的线程;
  4. top 监控显示,服务器的内存,cpu 都是够够的,排除;

全部排除了

定位问题 - 接口测试

首先通过一个简单的接口来测试定位问题: https://xxx/project/selectAllProjectList,此接口查询一张总行数为 8 的表,select * 操作;正常的响应时间在 50 ms 左右

编写脚本循环请求此接口接口,当响应时间超过 1s,打印响应时长;通过监控发现,服务器 10.167.6.29 上 在 15:30-15:31 发现响应速度骤降(100 倍),最长到 20 秒,整个卡顿时间持续1分钟,如下图:

image.png

通过日志量来判断请求是不是增多,grep count 这个时间段日志行数:

image.png

观察时间段是16:00,搜索统计,日志量环比猛增 50倍

image.png

进一步定位 pending ack 消息(消费)消费超过每秒 100+

通过mq admin 监控页面:

runningTopic 的消息量(发出的任务数)在16:00 处于波峰:

6.29 server 正常消费 日志量正常

image.png
image.png
image.png

16:00监控数据


image.png

16:30 监控数据


image.png

初步得出结论,但没定位到问题

1.server 消费大量消费, 性能下降,每分钟 238 条消息
2.6.28 日志量剧增,6.29 正常,说明 quartz 在两台机器拉起任务不均衡
6.28 消费与日志量统计


image.png

6.29 消费与日志量统计


image.png

16:00 启动的任务数 215 (大部分任务都配置了整点 0 点 0分 ,0分,30分,并发高)


image.png

发现问题 1

配置的定时任务都是在整点,mq 的监控数据也很有规律,整点在波峰,这点很关键
经过验证,在整点使用系统,必卡;

image.png

发现问题 2

6.28 16:00 启动了 205 个定时工作流 而 6.29 一共只有 13 个

经定位,多次 jstack grep 同一个卡主的线程 id ,发现在 iam filter 这里卡了 8 秒之多;至此可以初步断定,瓶颈在 IAM 系统;
需要注意的是:在定位问题的过程中,使用 jstack 我们更关注 waiting block 的线程,容易漏掉 running 的;

image.png

web.xml 配置了拦截器,rest请求,会先走 iam 过滤,判断用户是否登录

iam 拦截代码如下:

image.png

继续定位 IAM

既然发现是 IAM 瓶颈,在整点 jstack 日志,很快发现问题:
33个线程处于 waiting 阻塞等待中,


image.png
image.png

http://fisheuler.github.io/c3p0-debug.txt
c3p0 连接池的问题,服务器 c3p0 线程池配置都是默认值,maxSize 只有15 应该是不够的;

梳理下跟踪链:
调度系统前端请求偶发卡段
找到规律:整点卡顿
整点配置的定时任务最多
整点 jstack 发现 running 线程卡在 iam filter 拦截器
继续跟踪 iam ,整点 jstack 发现多数 mysql 线程 处于最等待状态
mysql 使用 c3p0 连接池,至此定位到是连接池问题

最终结论

  • 1.整点任务量剧增,主要是定时任务量剧增,系统 restfull 接口性能严重下降;定位出瓶颈在 IAM 服务,在任务量剧增时,响应超长,超时;
  • 2.两台 server 定时任务拉取不够均衡;具体原因待定位;

总结

  • 搭建完善的可视化监控系统:包括接口响应时长监控,cpu 内存监控,gc 监控等;
  • 熟练典型的性能定位工具:包括 jstack top free jstat 等
  • 发现规律,总结规律:最好通过监控,图形化系统卡顿的时间曲线图,这样可以第一时间发现规律,避免大海捞阵,盲找的情况。
  • 定点定位:在规律的时间点去监控系统指标,这样更有针对性,能更快的发现问题;
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 213,335评论 6 492
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,895评论 3 387
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 158,766评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,918评论 1 285
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,042评论 6 385
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,169评论 1 291
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,219评论 3 412
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,976评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,393评论 1 304
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,711评论 2 328
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,876评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,562评论 4 336
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,193评论 3 317
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,903评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,142评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,699评论 2 362
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,764评论 2 351