19丨Tomcat：中间件监控及常用计数器解析（上）

19丨Java & C ++：代码级监控及常用计数器解析（上）

高楼 2020-02-03

 

在性能测试分析中，有一部分人存在着一个思路上的误解，那就是一开始就一头扎进代码里，折腾代码性能。这是我非常反对的一种做法。

事实上，要想这么做，有一个前提，那就是架构中的其他组件都经过了千锤百炼，出现问题的可能性极低。

实际上，我凭着十几年的经验来看，大部分时候，代码出现严重性能瓶颈的情况还真是不多。再加上现在成熟的框架那么多，程序员们很多情况下只写业务实现。在这种情况下，代码出现性能瓶颈的可能性就更低了。

但我们今天终归要说代码级的监控及常用的计数器。如何去评估一个业务系统的代码性能呢？在我看来，分析的思路是下面这个样子的。

从上图可以看到，分析的时候有两个关键点：执行时间和执行空间。我相信很多人都清楚，我们要很快找到执行时间耗在哪一段和空间耗在哪里。

现在我们来实际操作一下，看如何判断。

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 这个方法了。但是你怎么知道整个调用逻辑中有哪些层级呢？你说我可以看源码。当然不是不可以。但要是没有源码呢？做性能分析的人经常没有源码呀。

这个时候，我们就要来看栈了。这里我打印了一个调用栈，我们来看下这个逻辑。

1. "http-nio-8080-exec-1" - Thread t@42
2. java.lang.Thread.State: RUNNABLE
3. ...............
4. at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
5. ...............
6. ...............
7. at com.sun.proxy.$Proxy87.create(Unknown Source)
8. ...............
9. at com.blog.controller.BackBlogController.save(BackBlogController.java:85)
10. ...............
11. at java.lang.Thread.run(Thread.java:745)
12. Locked ownable synchronizers:
13. - locked <4b6968c3> (a java.util.concurrent.ThreadPoolExecutor$Worker)

我把其他的都给清掉了，我们只看最简单的栈逻辑，其中 UnknownSource 的部分是因为反射实现的 insert 没有把源码反编译出来。

其实这个栈有 117 行，我怕你看晕。

从这一层一层的关系中，我们就可以知道调用逻辑了。知道调用逻辑的方法有很多，看源码也行，看编译后运行的代码也行，关键在于知道谁调了谁，这样就行了。

我这个还算是清晰的调用逻辑，要是代码调用关系再复杂一些，分分钟有想死有没有？

不过比较好的是，像 jvisualvm 这样的工具给我们提供了很多便利。这时可能有人会跳起来了，为什么不用 Arthas、BTrace 之类的工具呢？如果你喜欢的话，可以把 Athas 弄上，像下面这样。

1. [arthas@1]$ trace com.blog.controller.BackBlogController save
2. Press Q or Ctrl+C to abort.
3. Affect(class-cnt:2 , method-cnt:2) cost in 320 ms.
4. `---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
5. `---[29.048684ms] com.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$586fe45c:save()
6. `---[28.914387ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0
7. `---[27.897315ms] com.blog.controller.BackBlogController:save()
8. ...............
9. `---[24.192784ms] com.blog.service.BlogWriteService:create() #85

这也能看出来 creat 是消耗了时间的。如果你接着跟踪 create 方法。如下所示：

1. [arthas@1]$ trace com.blog.service.BlogWriteService create //这一行是arthas中跟踪class中的某个具体方法的语句。
2. Press Q or Ctrl+C to abort.
3. Affect(class-cnt:2 , method-cnt:2) cost in 199 ms. //被跟踪方法的处理次数和时长
4. `---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
5. `---[6.939189ms] com.sun.proxy.$Proxy87:create()
6. `---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
7. `---[4.144799ms] com.blog.service.BlogWriteServiceImpl:create() //写接口中create方法耗时
8. +---[2.131934ms] tk.mybatis.mapper.common.Mapper:insert() #24 //mybatis中insert方法耗时
9. ...............
10. `---[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 上去，也可以做到。何必为了可能出现的问题而长时间地消耗资源呢。

总结

大部分时间里，性能测试和分析都在和时间打交道，而在时间的拆分逻辑中，我们在前面也提到过思路，如何一步步把时间拆解到应用当中，那就是分段。

当拆解到应用当中之后，就是抓函数方法的执行时间了。这是保证我们从前到后分析逻辑的关键一环，请你注意，是关键一环，而不是最初的一环。

通过这篇文章我想告诉你，在大部分的开发语言中，都有手段直接将方法的执行时间消耗抓出来，你可能现在还不知道是什么方法，没关系，因为跟踪的手段有很多，你可以临时去学习如何操作。

我只要在你的脑子里种下这样的一种印象，那就是，有办法抓到函数方法的执行时间消耗在哪里！