使用arthas进行代码优化

季鸟猴

发布于 2022-11-01 14:51:26

4660

发布于 2022-11-01 14:51:26

文章被收录于专栏：季鸟猴的分享

今天接到了客户反应的远程医疗系统的BUG，解决了BUG的同时，顺带发现这里除了bug之外方法执行很慢，觉得顺带优化一下。记录一下优化过程。

首先我们目标很明确，根据调用栈统计每个调用所用的时间，然后再去具体找到具体的慢代码所在的位置。

1、使用的工具是Arthas的trace命令。

2、启动arthas,并找到相关的java进程，输入service的类名和方法名，开启调用统计。

trace com.rest.server.service.InstitutionUserServiceImpl addDoctorUser

3、输入后，到程序中调试，让程序中该业务场景复现一次，并观察arthas的控制台。

[arthas@52935]$ trace com.rest.server.service.InstitutionUserServiceImpl addDoctorUser
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 882 ms, listenerId: 1
`---ts=2022-08-28 23:21:49;thread_name=http-nio-8081-exec-12;id=54;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4305e569
    `---[30508.997167ms] com.rest.server.service.InstitutionUserServiceImpl:addDoctorUser()
        +---[0.09% 28.840916ms ] com.rest.server.service.InstitutionUserServiceImpl:get() #176
        +---[0.04% 12.467833ms ] com.haiseer.edu.domain.core.MInstitutionUser:getInstitution() #176
        +---[87.74% 26767.496625ms ] com.rest.server.service.InstitutionUserServiceImpl:verifyUserName() #178
        +---[0.00% 0.04375ms ] com.rest.server.service.InstitutionUserServiceImpl$5:<init>() #186
        +---[0.37% 114.200791ms ] com.haiseer.edu.domain.core.MDoctorDAO:create() #186
        +---[0.00% 0.014417ms ] com.rest.server.service.InstitutionUserServiceImpl$6:<init>() #215
        +---[0.05% 15.798875ms ] com.haiseer.edu.domain.core.MInstitutionDoctorUserDAO:create() #215
        +---[0.02% 7.126875ms ] com.haiseer.edu.domain.core.MInstitutionDoctorUser:getInstitution() #238
        +---[0.07% 22.163417ms ] com.hsr.util.HSUtil:query() #239
        +---[0.00% 0.01225ms ] com.haiseer.edu.domain.core.MInstitution:getUuid() #240
        +---[0.00% 0.02275ms ] org.hibernate.Query:setParameter() #240
        +---[0.00% 0.005291ms ] org.hibernate.Query:setParameter() #241
        +---[0.08% 23.364834ms ] org.hibernate.Query:uniqueResult() #242
        +---[0.00% 0.021667ms ] com.haiseer.edu.domain.core.MInstitutionDoctorUser:setInstitutionRole() #243
        `---[0.01% 2.707083ms ] com.rest.server.service.InstitutionUserServiceImpl:saySuccess() #245

可以看到，统计结果显示一共花了30508.997167ms，将近30秒钟…实在太慢了，而且调用时间大部分都浪费在InstitutionUserServiceImpl:verifyUserName这个方法上了。

4、找到程序中对应的点具体问题具体分析去优化

在代码中找到verifyUserName这个方法的问题，再去细看后发现是n+1次查询问题，修改解决。

5、测试修改后的效果：

`---ts=2022-08-28 23:46:40;thread_name=http-nio-8081-exec-13;id=55;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4305e569
    `---[377.296708ms] com.rest.server.service.InstitutionUserServiceImpl:addDoctorUser()
        +---[0.86% 3.247375ms ] com.rest.server.service.InstitutionUserServiceImpl:get() #176
        +---[0.94% 3.532208ms ] com.haiseer.edu.domain.core.MInstitutionUser:getInstitution() #176
        +---[78.55% 296.379708ms ] com.rest.server.service.InstitutionUserServiceImpl:verifyUserName() #178
        +---[0.01% 0.032959ms ] com.rest.server.service.InstitutionUserServiceImpl$5:<init>() #186
        +---[8.19% 30.918583ms ] com.haiseer.edu.domain.core.MDoctorDAO:create() #186
        +---[0.01% 0.038666ms ] com.rest.server.service.InstitutionUserServiceImpl$6:<init>() #215
        +---[3.73% 14.081791ms ] com.haiseer.edu.domain.core.MInstitutionDoctorUserDAO:create() #215
        +---[1.38% 5.208292ms ] com.haiseer.edu.domain.core.MInstitutionDoctorUser:getInstitution() #238
        +---[0.03% 0.120333ms ] com.hsr.util.HSUtil:query() #239
        +---[0.00% 0.004583ms ] com.haiseer.edu.domain.core.MInstitution:getUuid() #240
        +---[0.01% 0.031542ms ] org.hibernate.Query:setParameter() #240
        +---[0.00% 0.005583ms ] org.hibernate.Query:setParameter() #241
        +---[5.73% 21.62025ms ] org.hibernate.Query:uniqueResult() #242
        +---[0.00% 0.017584ms ] com.haiseer.edu.domain.core.MInstitutionDoctorUser:setInstitutionRole() #243
        `---[0.17% 0.658083ms ] com.rest.server.service.InstitutionUserServiceImpl:saySuccess() #245

可以看到，时间从30508.997167ms降低到了377.296708ms。

6、总结

呼吁各位小伙伴，编码中切记不要出现n+1次查询问题，这种问题正式上线后随着数据量的增加，注定要返工的。

Q.E.D.

本文参与腾讯云自媒体同步曝光计划，分享自作者个人站点/博客。

如有侵权请联系 cloudcommunity@tencent.com 删除

编程算法

本文分享自作者个人站点/博客前往查看

如有侵权，请联系 cloudcommunity@tencent.com 删除。

本文参与腾讯云自媒体同步曝光计划，欢迎热爱写作的你一起参与！

编程算法

登录后参与评论

0 条评论

热度