性能文章>不改一行代码定位线上性能问题>

不改一行代码定位线上性能问题原创

2年前
8254510

背景

最近时运不佳,几乎天天被线上问题骚扰。前几天刚解决了一个 HashSet 的并发问题,周六又来了一个性能问题。

大致的现象是:

我们提供出去的一个 OpenAPI 反应时快时慢,快的时候几十毫秒,慢的时候几秒钟才响应。

尝试解决

由于这种也不是业务问题,不能直接定位。所以尝试在测试环境复现,但遗憾的测试环境贼快。

没办法只能硬着头皮上了。

中途有抱着侥幸心里让运维查看了 NginxOpenAPI 的响应时间,想把锅扔给网络。结果果然打脸了; Nginx 里的日志也表明确实响应时间确实有问题。

为了清晰的了解这个问题,我简单梳理了这个调用过程。

image.png

整个的流程算是比较常见的分层架构:

  • 客户端请求到 Nginx

  • Nginx 负载了后端的 web 服务。

  • web 服务通过 RPC 调用后端的 Service 服务。

日志大法

我们首先想到的是打日志,在可能会慢的方法或接口处记录处理时间来判断哪里有问题。

但通过刚才的调用链来说,这个请求流程不短。加日志涉及的改动较多而且万一加漏了还有可能定位不到问题。

再一个是改动代码之后还会涉及到发版上线。

工具分析

所以最好的方式就是不改动一行代码把这个问题分析出来。

这时就需要一个 agent 工具了。我们选用了阿里以前开源的 Tprofile 来使用。

只需要在启动参数中加入 -javaagent:/xx/tprofiler.jar 即可监控你想要监控的方法耗时,并且可以给你输出报告,非常方便。对代码没有任何侵入性同时性能影响也较小。

工具使用

下面来简单展示下如何使用这个工具。

首先第一步自然是 clone 源码然后打包,可以克隆我修改过的源码。

因为这个项目阿里多年没有维护了,还残留一些 bug,我在它原有的基础上修复了个影响使用的 bug,同时做了一些优化。

执行以下脚本即可。

  • git clone https://github.com/crossoverJie/TProfiler
  •  
  • mvn assembly:assembly
  •  

到这里之后会在项目的 TProfiler/pkg/TProfiler/lib/tprofiler-1.0.1.jar 中生成好我们要使用的 jar 包。

接下来只需要将这个 jar 包配置到启动参数中,同时再配置一个配置文件路径即可。

这个配置文件我 copy 官方的解释。

  • #log file name
  • logFileName = tprofiler.log
  • methodFileName = tmethod.log
  • samplerFileName = tsampler.log
  •  
  • #basic configuration items
  • # 开始取样时间
  • startProfTime = 1:00:00
  •  
  • # 结束取样时间
  • endProfTime = 23:00:00
  •  
  • # 取样的时间长度
  • eachProfUseTime = 10
  •  
  • # 每次取样的时间间隔
  • eachProfIntervalTime = 1
  •  
  • samplerIntervalTime = 20
  •  
  • # 端口,主要不要冲突了
  • port = 50000
  • debugMode = false
  • needNanoTime = false
  •  
  • # 是否忽略 get set 方法
  • ignoreGetSetMethod = true
  •  
  • #file paths 日志路径
  • logFilePath = /data/work/logs/tprofile/${logFileName}
  • methodFilePath =/data/work/logs/tprofile/${methodFileName}
  • samplerFilePath =/data/work/logs/tprofile/${samplerFileName}
  •  
  • #include & excludes items
  • excludeClassLoader = org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader
  •  
  • # 需要监控的包
  • includePackageStartsWith = top.crossoverjie.cicada.example.action
  •  
  • # 不需要监控的包
  • excludePackageStartsWith = com.taobao.sketch;org.apache.velocity;com.alibaba;com.taobao.forest.domain.dataobject
  •  

最终的启动参数如下:

  • -javaagent:/TProfiler/lib/tprofiler-1.0.1.jar
  • -Dprofile.properties=/TProfiler/profile.properties
  •  

为了模拟排查接口响应慢的问题,我用 cicada 实现了一个 HTTP 接口。其中调用了两个耗时方法:

image.png

这样当我启动应用时, Tprofile 就会在我配置的目录记录它所收集的方法信息。

我访问接口 http://127.0.0.1:5688/cicada-example/demoAction?name=test&id=10 几次后它就会把每个方法的明细响应写入 tprofile.log

image.png

由左到右每列分别代表为:

线程ID、方法栈深度、方法编号、耗时(毫秒)。

tmethod.log 还是空的;

这时我们只需要执行这个命令即可把最新的方法采样信息刷到 tmethod.log 文件中。

  • java -cp /TProfiler/tprofiler.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 50000 flushmethod
  •  
  • flushmethod success
  •  

其实就是访问了 Tprofile 暴露出的一个服务,他会读取、解析 tprofile.log 同时写入 tmethod.log.

其中的端口就是配置文件中的 port。

再打开 tmethod.log

image.png

其中会记录方法的信息。

  • 第一行数字为方法的编号。可以通过这个编号去 tprofile.log(明细)中查询每次的耗时情况。

  • 行末的数字则是这个方法在源码中最后一行的行号。

其实大部分的性能分析都是统计某个方法的平均耗时。

所以还需要执行下面的命令,通过 tmethod.log tprofile.log来生成每个方法的平均耗时。

  • java -cp /TProfiler/tprofiler.jar com.taobao.profile.analysis.ProfilerLogAnalysis tprofiler.log tmethod.log topmethod.log topobject.log
  • print result success
  •  

打开 topmethod.log 就是所有方法的平均耗时。

image.png

  • 4 为请求次数。

  • 205 为平均耗时。

  • 818 则为总耗时。

和实际情况是相符的。

方法的明细耗时
这是可能还会有其他需求;比如说我想查询某个方法所有的明细耗时怎么办呢?

官方没有提供,但也是可以的,只是要麻烦一点。

比如我想查看 selectDB() 的耗时明细:

首先得知道这个方法的编号,在 tmethod.log 中可以看查到。

  • 2 top/crossoverjie/cicada/example/action/DemoAction:selectDB:84
  •  

编号为 2.

之前我们就知道 tprofile.log 记录的是明细,所以通过下面的命令即可查看。

  • grep 2 tprofiler.log
  •  

image.png

通过第三列方法编号为 2 的来查看每次执行的明细。

但这样的方式显然不够友好,需要人为来过滤干扰,步骤也多;所以我也准备加上这样一个功能。

只需要传入一个方法名称即可查询采集到的所有方法耗时明细。

总结

回到之前的问题;线上通过这个工具分析我们得到了如下结果。

  • 有些方法确实执行时快时慢,但都是和数据库相关的。由于目前数据库压力较大,准备在接下来进行冷热数据分离,以及分库分表。

  • 在第一步操作还没实施之前将部分写数据库的操作改为异步,减小响应时间。

  • 考虑接入 pinpoint 这样的 APM工具

类似于 Tprofile 的工具确实挺多的,找到适合自己的就好。

在还没有使用类似于 pinpoint 这样的分布式跟踪工具之前应该会大量依赖于这个工具,所以后续说不定也会做一些定制,比如增加一些可视化界面等,可以提高排查效率。

分类:标签:
请先登录,查看5条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

字符串字面量长度是有限制的
前言 偶然在一次单元测试中写了一个非常长的字符串字面量。 正文 在一次单元测试中,我写了一个很长的字符串字面量,大概10万个字符左右,编译时,编译器给出了异常告警 `java: constant
多次字符串相加一定要用StringBuilder而不用-吗?
今天在写一个读取Java class File并进行分析的Demo时,偶然发现了下面这个场景(基于oracle jdk 1.8.0_144): ``` package test; public c
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得
高吞吐、低延迟 Java 应用的 GC 优化实践
本篇原文作者是 LinkedIn 的 Swapnil Ghike,这篇文章讲述了 LinkedIn 的 Feed 产品的 GC 优化过程,虽然文章写作于 April 8, 2014,但其中的很多内容和
「每日五分钟,玩转 JVM」:久识你名,初居我心
聊聊 JVMJVM,一个熟悉又陌生的名词,从认识Java的第一天起,我们就会听到这个名字,在参加工作的前一两年,面试的时候还会经常被问到JDK,JRE,JVM这三者的区别。JVM可以说和我们是老朋友了
据说99.99%的人都会答错的类加载的问题
概述首先还是把问题抛给大家,这个问题也是我厂同学在做一个性能分析产品的时候碰到的一个问题。 同一个类加载器对象是否可以加载同一个类文件多次并且得到多个Class对象而都可以被java层使用吗请仔细注意
Java多线程——并发测试
编写并发程序时候,可以采取和串行程序相同的编程方式。唯一的难点在于,并发程序存在不确定性,这种不确定性会令程序出错的地方远比串行程序多,出现的方式也没有固定规则。那么如何在测试中,尽可能的暴露出这些问
Java多线程知识小抄集(一)
本文主要整理笔者遇到的Java多线程的相关知识点,适合速记,故命名为“小抄集”。本文没有特别重点,每一项针对一个多线程知识做一个概要性总结,也有一些会带一点例子,习题方便理解和记忆。 1.interr