一、arthas
上篇文章我们讲解了使用arthas在线上环境排查定位内存占用过大、cpu使用率过高等问题,本篇文章继续使用arthas监测线上系统的运行信息,以及排查程序运行缓慢等问题。
下面是上篇文章的地址:
二、监测线上系统的运行信息
在生产环境不像本地使用idea运行,可以随时进行debug,那生产环境我们要监控程序运行到某一个方法的入参和出参时要怎么办呢?
此时我们可以通过打印日志的方式,将我们想要查看的信息都使用log输出到日志中,我们查看日志,但这种方式也存在这弊端,我们只是在出问题的时候想要查看这个写日志,平常情况下无需打印那么多日志,而且还占用了我们生产环境的磁盘空间,那么此时arthas就可以帮我们实现无需打印日志的情况下,就可以监控查看生产环境下的某个类的属性值或者摸个方法的入参出参等值。
在开始前,我们先新建一个SpringBoot项目,并写下面一个测试controller:
@RestController
public class SlowController {
public String smTest(String arg1, Integer atg2) {
return "success";
}
public String name;
public Integer age;
private static List<String> ognlList = new ArrayList<>();
@GetMapping("/addognlListData/{v}")
public String addognlListData(@PathVariable String v) {
ognlList.add(v);
return "success";
}
@GetMapping("/getOgnlList")
public List<String> getOgnlList() {
return ognlList;
}
@GetMapping("/monitorTest/{i}")
public String monitorTest(@PathVariable Integer i) {
if (i > 0) {
return "success";
} else {
throw new RuntimeException("monitorTest fail!");
}
}
}
然后启动项目。
主动查看程序的信息及内容
假如我们不熟悉程序要查询SlowController的类信息,可以使用用sc指令:
sc -d -f com.bxc.arthasdemo.controller.SlowController
可以看到已经将该类的所有信息打印出来了,包括类上的注解及类中的字段,现在我们查看SlowController的全部方法,可以使用sm指令:
sm com.bxc.arthasdemo.controller.SlowController
再查看smTest这个方法的出入参类型
sm com.bxc.arthasdemo.controller.SlowController smTest
假如我们要查看ognlList这个静态变量的内容,如果没有写查看的方法,在生产环境我们可能无法知道其中的内容,现在就可以使用arthas的ognl,使用ognl语法的方式查看:
先使用addognlListData接口添加一条数据,然后使用ognl查看ognlList的内容:
ognl '@com.bxc.arthasdemo.controller.SlowController@ognlList'
上面已经看到ognlList的内容,我们还可以查询ognlList大小:
ognl '@com.bxc.arthasdemo.controller.SlowController@ognlList.size()'
甚至我们还可以对ognlList的内容进行操作,添加一条数据:
ognl '@com.bxc.arthasdemo.controller.SlowController@ognlList.add("test")'
还可以结合grep进行内容匹配:
ognl '@com.bxc.arthasdemo.controller.SlowController@ognlList' | grep test
监视方法的执行状况
假如现在我们要统计一个方法的使用情况,是否成功,成功率多少,可以使用monitor进行监视
监视monitorTest接口,程序中我们写的当传入小于等于0的时候就会报错,现在监视下:
monitor -c 5 com.bxc.arthasdemo.controller.SlowController monitorTest
将方法的调用次数,成功次数,失败次数,以及平均响应时间和成功率,都给我们统计了,我们可以根据这写信息再具体分析程序写的逻辑,是不是可以优化。
上面通过 monitor可以帮我们统计整体的状况,但我们还需要根据输入输出参数,进行进一步的分析。
下面我们使用watch查看monitorTest接口的出入参数:
watch com.bxc.arthasdemo.controller.SlowController monitorTest '{params[0],returnObj}'
如果是对象类型,也可以使用toString:
watch com.bxc.arthasdemo.controller.SlowController monitorTest '{params.toString(),returnObj.toString()}'
如果返回是列表形式,我们也可以查看大小:
watch com.bxc.arthasdemo.controller.SlowController monitorTest '{params[0],returnObj.size}'
包括我们也可以进行一些逻辑判断,比如判断返回是否包含某个字符:
watch com.bxc.arthasdemo.controller.SlowController monitorTest '{params[0],returnObj.contains("succ")}'
上面都是查看所有的情况,一般我们可能只想查看错误的情况下的参数:
watch com.bxc.arthasdemo.controller.SlowController monitorTest '{params[0],returnObj}' -x 2 -e
测试时可以发现,如果接口正常是不会监控的,只有接口异常时,打印了参数。
同样也可以使用tt来打印方法执行情况:
tt -t com.bxc.arthasdemo.controller.SlowController monitorTest
上面是定位到某个方法的实时状况,假如还要查看方法的调用路径,进一步分析,可以使用stack指令:
stack com.bxc.arthasdemo.controller.SlowController monitorTest
三、慢程序定位
上面我们可以通过主动获取的方式监控一个方法及参数的内容,但有的时候某个接口变慢有可能是其中某个操作的问题导致的,所以第一步我们先定位这个慢的原因点:
先写一个测试的接口:
@GetMapping("/slowTest")
public String slowTest() throws InterruptedException {
return slowA();
}
public String slowA() throws InterruptedException {
TimeUnit.SECONDS.sleep(1);
return slowB();
}
public String slowB() throws InterruptedException {
TimeUnit.SECONDS.sleep(2);
return "success";
}
上面在slowTest中又调用slowA,然后又调用slowB,这样调用slowTest接口应该整体是三秒的时间,假如我们不知道原因,就可以使用arthas进行定位了。
先使用trace定位slowTest方法中的时间:
trace com.bxc.arthasdemo.controller.SlowController slowTest
可以看到slowTest整体为3023.8447ms,其中slowA()方法就占用了3023.7497ms,那问题肯定在slowA()方法中,再次定位slowA()方法的执行时间:
trace com.bxc.arthasdemo.controller.SlowController slowA
在slowA()方法中整体占了3018.3365ms,其中slowB()方法就占用了2009.4594ms,这样看slowA()方法中的逻辑占了大概一秒的时候,剩下的全部被slowB()方法占用,再次定位slowB()方法的执行时间:
trace com.bxc.arthasdemo.controller.SlowController slowB
可以看到slowB()方法没有再调用其他方法,自己内部占用了大概两秒的时间,所以现在就定位到接口慢的原因所在了。
喜欢的小伙伴可以关注我的个人微信公众号,获取更多学习资料!