巧用linux三剑客定位性能问题

946 阅读4分钟

背景

博主是一名练习时长三年多的Java练习生,在一家普通大数据公司搬砖头,公司大方向上是做TOB产品,并没有什么大并发大流量,所以一直很虚面试上突然被问有解决过线上问题吗

当然网上还是有一些排查Java进程内存溢出了,cpu消耗高了的例子。但是八股文终归是八股文,应付不那么较真的面试官还可以,遇到较真的一刨根问底就露馅了。真正沉淀下来运用到日常中还不太够,刚好这次遇到个用户那边出现系统整体响应慢的问题,正好抓住机会排查下。

排查服务

TOP

根据用户反馈的现象初步排查方向为某个服务占用大部分资源导致影响机器调度从而导致整体服务异常。于是第一时间让现场的实施通过top命令查看卡顿时的资源情况。

image.png

看到这个图我当时直接盖棺定论,肯定是这个Java服务导致的,机器cpu消耗了将近80%,这一个进程就耗掉了2500%,想都不用想啊,肯定是它。

Jstack

得出结论后立马让前线同事通过jstack -l pid拿到Java进程的堆栈分析,这里推荐一个不错的分析网站:fastthread.io, 线程资源情况一目了然,分析简单问题绝对够用了。

但是拿到线程日志发现一切都很正常,这个Java服务是用来同步数据的服务,创建出多个线程接入导出数据很正常,但是为啥卡呢。。内存占用的也不高,如果内存也很高的话还可以用jamp -heap pid导出堆栈日志分析下。

由于服务卡顿时间不能太长,前线同事也反馈说服务不卡顿的时候这个Java进程也是会占用很高的cpu资源。说明这个服务可能不是罪魁祸首,赶紧转换思路。

排查日志

一时定位不出是哪个代码模块导致卡顿,直接让前线同学拿出来近3天所有服务模块的日志分析。因为所有请求都会走网关服务,网关层的日志会打出整体的耗时。通过过滤大于5000hs的日志分析。

其实这个思路我是不太想走的,因为我linux的命令只能在日常开发中够用,用来统计日志有点棘手,但是leader明确给了方向要分析出接口耗时,先判断是单一服务接口卡顿还是所有接口卡顿。

没办法了,上学那会就没好好学linux命令,总有一天要补回来,仿佛当年的linux老师在我耳边轻声呵斥了一句"linux三板斧你是一斧都不会"

grep

grep命令相信大家都不陌生,搜索指定关键字,利用管道实现复杂查询,前线的日志扔过来足足有2个g左右。

grep '/api.*[ts=' 首先所有的请求都有前缀 '/api/' ,利用这一点可以排除非http请求的日志,*是从 /api开始到 [ts结束都搜索。

然后用grep -v 'ERROR'去掉请求错误的日志,这部分请求不会导致系统变慢,所以第一阶段的搜索命令为

 grep '/api.*[ts=' | grep -v 'ERROR'

awk

awk则是根据空格打印指定位置的元素,因为日志里面记录的信息太多了,分析接口耗时的话只需要几个有用的参数。请求时间、请求url、请求耗时、链路追踪的tracid。

刚才也提到了耗时附近有 [], 影响观感。。。。其实我是可以忍受的,但是我leader一定要追求极致。。。

所以可以通过sed去把对应的字符替换成空格即可,sed 's///g' 这是个固定的命令,在第一个/与第二个/见输入要替换的字符即可。由于 [ 是特殊字符需要转义,所以最终的sed命令为。

sed 's/[//g' | sed 's/]//g'

与刚才的grep命令连起来就是

 grep '/api.*[ts=' | grep -v 'ERROR' | sed 's/[//g' | sed 's/]//g'

接下来就是打印对应下标的信息了,这里有个小技巧,awk '{print$0}' 是打印一整行信息,awk '{print$(NF)}' 是打印最后一个空格下标对应的数据。也就是说如果要打印的信息靠着第一个下标近,可以从0数过去,如果靠着最后一个近可以通过 $(NF-n) 减出下标。

而且最秀的是对应下标输出的如果是数字的话还可以写条件。所以最终的命令如下

grep '/api.*[ts=' bdp-fe/mc_api.log* | sed 's/[ts=//g' | sed 's/]//g' | awk '{if($(NF-3)>5000)print$1" "$2" "$(NF-3)" "$(NF-6) " "$(NF)}' | grep -v 'ERROR'

效果也跟预想的一样,只打印出了请求时间、请求url、请求耗时、链路追踪的tracid。

image.png

分析日志

对着日志一顿分析后发现,%70接口慢是因为访问了用户中心的用户详情,但是又有一部分用户详情接口返回的很快但是整体接口慢。

这下只能让运维先把监控安装上,先排查用户详情慢的问题,由于客户那边部署的版本是个旧版本了,确实会出现如果用户所属组特别多的情况详情。这个问题本质上确实是查询用户信息耗时高,虽然有缓存,但是有一批用户同时失效会阻塞住请求导致系统抖动卡顿。

由于之前遇到过此类问题,可以通过脚本暂时规避掉,但是尴尬的事情又来了,没生效。系统还是会过一阵子就抖动卡顿,没办法了只能分析监控信息了。

监控信息

安装好Granfna监控工具,从各个图表里发现了蹊跷,发现mysql数据库所在的机器磁盘读写会持续一段时间达到100%,跟前线运维核对后发现由于部署不规范导致的mysql这台机器上还冗余了一些其他的大量io的服务,es、kafka等中间件。

结合grep命令统计近三天的活跃用户发现又100多人,对于一个TOB大数据分析产品,有100多活跃用户并发量已经不低了,遂与前线沟通下申请机器资源解决。。。

grep '[/api/' 用户中心.log.2022-11-09*| grep ' 08:| 09:| 10:| 11:| 12:' |  awk '{print$8}' | sed 's/[//g' | sed 's/]//g' | sort | uniq