在性能测试分析中，有一部分人存在着一个思路上的误解，那就是一开始就一头扎进代码里，折腾代码性能。这是我非常反对的一种做法。
事实上，要想这么做，有一个前提，那就是架构中的其他组件都经过了千锤百炼，出现问题的可能性极低。
实际上，我凭着十几年的经验来看，大部分时候，代码出现严重性能瓶颈的情况还真是不多。再加上现在成熟的框架那么多，程序员们很多情况下只写业务实现。在这种情况下，代码出现性能瓶颈的可能性就更低了。
但我们今天终归要说代码级的监控及常用的计数器。如何去评估一个业务系统的代码性能呢？在我看来，分析的思路是下面这个样子的。
从上图可以看到，分析的时候有两个关键点：执行时间和执行空间。我相信很多人都清楚，我们要很快找到执行时间耗在哪一段和空间耗在哪里。
现在我们来实际操作一下，看如何判断。
Java类应用查找方法执行时间
首先你得选择一个合适的监控工具。Java方法类的监控工具有很多，这里我选择JDK里自带的jvisualvm。
顺便说一下，我的Java版本号是这个：
(base) GaoLouMac:~ Zee$ java -version
java version "1.8.0_111"
Java(TM) SE Runtime Environment (build 1.8.0_111-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.111-b14, mixed mode)
打开应用服务器上的JMX之后，连上jvisualvm，你会看到这样的视图。
这里再啰嗦一下我们的目标，这时我们要找到消耗CPU的方法，所以要先点Sampler - CPU，你可以看到如下视图。
从上图可以看到方法执行的累积时间，分别为自用时间百分比、自用时间、自用时间中消耗CPU的时间、总时间、总时间中消耗CPU的时间、样本数。
从这些数据中就可以看到方法的执行效率了。
但是，这里面Method这么多，我怎么知道哪个跟我的方法执行时间有关呢？比如说上面这个应用中，最消耗CPU的是JDBC的一个方法fill。这合理吗？
先来看一下我的脚本。
从结构上你就能看出来，我做了登录，然后就做了创建的动作，接着就退出了。
这几个操作和数据库都有交互。拿create这个步骤来说，它的脚本非常直接，就是一个POST接口。
还记得前面我们怎么说查看后端的运行逻辑的吗？后端接收这个POST的代码如下：
@RequestMapping("/save")
@ResponseBody
public Object save(Blog blog, HttpSession session){
try{
Long id = blog.getId();
if(id==null){
User user = (User)session.getAttribute("user");
blog.setAuthor(user.getName());
blog.setUserId(user.getId());
blog.setCreateTime(new Date());
blog.setLastModifyTime(new Date());
blogWriteService.create(blog);
}else {
blog.setLastModifyTime(new Date());
blogWriteService.update(blog);
}
}catch (Exception e){
throw new JsonResponseException(e.getMessage());
}
return true;
}
这段代码的功能就是讲前端内容接收过来放到实体中，然后通过create方法写到数据库中。那么create是怎么实现的呢？
public void create(Blog blog) {
mapper.insert(blog);
BlogStatistics blogStatistics = new BlogStatistics(blog.getId());
blogStatisticsMapper.insert(blogStatistics);
它就是一个mapper.insert，显然这个create是我们自己实现的代码，里面其实没有什么逻辑。而ReadAheadInputStream.fill是create中的MyBatis调用的JDBC中的方法。 从压力工具到数据库的调用逻辑就是：
而我们看到的最耗时的方法是最后一个，也就是fill。实际上，我们应该关心的是save接口到底怎么样。我们来过滤下看看。
从save的结果上来看，它本身并没有耗什么时间，都是后面的调用在消耗时间。
我们再来看看cerate。
它本身也没消耗什么时间。
顺着逻辑图，我们再接着看MyBatis中的insert方法。
就这样一层层找下去，最后肯定就找到了fill这个方法了。但是你怎么知道整个调用逻辑中有哪些层级呢？你说我可以看源码。当然不是不可以。但要是没有源码呢？做性能分析的人经常没有源码呀。
这个时候，我们就要来看栈了。这里我打印了一个调用栈，我们来看下这个逻辑。
"http-nio-8080-exec-1" - Thread t@42
java.lang.Thread.State: RUNNABLE
...............
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
...............
...............
at com.sun.proxy.$Proxy87.create(Unknown Source)
...............
at com.blog.controller.BackBlogController.save(BackBlogController.java:85)
...............
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- locked <4b6968c3> (a java.util.concurrent.ThreadPoolExecutor$Worker)
我把其他的都给清掉了，我们只看最简单的栈逻辑，其中UnknownSource的部分是因为反射实现的insert没有把源码反编译出来。
其实这个栈有117行，我怕你看晕。
从这一层一层的关系中，我们就可以知道调用逻辑了。知道调用逻辑的方法有很多，看源码也行，看编译后运行的代码也行，关键在于知道谁调了谁，这样就行了。
我这个还算是清晰的调用逻辑，要是代码调用关系再复杂一些，分分钟有想死有没有？
不过比较好的是，像jvisualvm这样的工具给我们提供了很多便利。这时可能有人会跳起来了，为什么不用Arthas、BTrace之类的工具呢？如果你喜欢的话，可以把Athas弄上，像下面这样。
[arthas@1]$ trace com.blog.controller.BackBlogController save
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 320 ms.
`---ts=2020-01-06 10:38:37;thread_name=http-nio-8080-exec-2;id=2b;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4f2895f8
`---[29.048684ms] com.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$586fe45c:save()
`---[28.914387ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0
`---[27.897315ms] com.blog.controller.BackBlogController:save()
...............
`---[24.192784ms] com.blog.service.BlogWriteService:create() #85
这也能看出来creat是消耗了时间的。如果你接着跟踪create方法。如下所示：
[arthas@1]$ trace com.blog.service.BlogWriteService create //这一行是arthas中跟踪class中的某个具体方法的语句。
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 199 ms. //被跟踪方法的处理次数和时长
`---ts=2020-01-06 10:41:51;thread_name=http-nio-8080-exec-4;id=2f;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4f2895f8
`---[6.939189ms] com.sun.proxy.$Proxy87:create()
`---ts=2020-01-06 10:41:51;thread_name=http-nio-8080-exec-10;id=38;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4f2895f8
`---[4.144799ms] com.blog.service.BlogWriteServiceImpl:create() //写接口中create方法耗时
+---[2.131934ms] tk.mybatis.mapper.common.Mapper:insert() #24 //mybatis中insert方法耗时
...............
`---[1.95441ms] com.blog.mapper.BlogStatisticsMapper:insert() #26 //insert方法调用了上面的create方法耗时
要是接着往下跟踪，就可以看到反射这一块了。
[arthas@1]$ trace tk.mybatis.mapper.common.Mapper insert
Press Q or Ctrl+C to abort.
Affect(class-cnt:5 , method-cnt:5) cost in 397 ms.
`---ts=2020-01-06 10:44:01;thread_name=http-nio-8080-exec-5;id=33;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4f2895f8
`---[3.800107ms] com.sun.proxy.$Proxy80:insert()
类似的，你还可以玩JDK自带的工具jdb，它也可以直接attach到一个进程上，调试能力也是不弱的。
在我看来，这些工具、手段都是为了实现从响应时间长<->代码行的分析过程。思路是最重要的。
另外也要说一下，现在有的APM工具也可以实现这样的功能，但是呢，我并不建议一开始就上这么细致的工具，因为不管APM产品吹得有多牛逼，它都是要消耗10%左右的CPU的。并且，你觉得直接在生产上装一个APM工具的agent到业务系统中是合理的吗？如果是自己实现的metrics方法，输出性能数据尚可接受，如果是别人的这类工具，还是算了。
在大部分时候，我都不建议在生产上用APM工具。万一生产上真的有极端的情况，需要看细致的性能问题，再临时attach上去，也可以做到。何必为了可能出现的问题而长时间地消耗资源呢。
总结
大部分时间里，性能测试和分析都在和时间打交道，而在时间的拆分逻辑中，我们在前面也提到过思路，如何一步步把时间拆解到应用当中，那就是分段。
当拆解到应用当中之后，就是抓函数方法的执行时间了。这是保证我们从前到后分析逻辑的关键一环，请你注意，是关键一环，而不是最初的一环。
通过这篇文章我想告诉你，在大部分的开发语言中，都有手段直接将方法的执行时间消耗抓出来，你可能现在还不知道是什么方法，没关系，因为跟踪的手段有很多，你可以临时去学习如何操作。
我只要在你的脑子里种下这样的一种印象，那就是，有办法抓到函数方法的执行时间消耗在哪里！
思考题
最后给你留两道思考题吧。我为什么不建议在生产环境中一开始就上APM类工具来抓取方法的执行时间呢？你有什么方法可以抓取到Java语言中的方法执行时间？如果你擅长其他语言，也可以描述其他语言中的方法执行时间抓取工具。
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流一下。
精选留言
2020-02-08 21:10:16
1. 能接受10%性能损耗的，比如原来耗时1秒，上了变成1.1秒其实感觉不明显；原来高峰期CPU使用率30%，上了变成40%也还在可接受范围内；
2. APM的成功失败不影响业务的运行，就是即使APM挂了，业务也还能正常运行；
3. 在docker+k8且又有大量虚机大量服务的情况下，上APM也是一个方案，不然当出现问题时要在那么多服务里面把问题定位到，用jmx这类监控很容易措手不及和慌手慌脚。
4. 现在好些公司没有专职性能测试，好些系统没有经过性能测试就上线的，此时APM是开发和运维人员的一个救命稻草了，这种公司我相信很多。
2020-10-14 16:04:58
2020-04-03 09:19:09
2021-02-16 13:24:00
2020-02-27 09:39:14
2022-07-28 15:51:22
2021-01-12 09:36:24
2020-10-19 17:08:23
2020-04-08 09:30:53
2020-02-27 17:31:44
2023-07-17 19:59:24
这个具体是怎么操作？能说明一下吗？
2021-01-16 16:26:22
2020-03-23 14:59:35
2020-03-20 11:34:07
2020-03-18 17:28:48
2020-02-18 21:53:18