性能分析之JMeter 脚本执行失败导致的问题

背景

今天有个人微信上问问题。说 cpu 使用率不高，为什么负载那么高？

问题分析

我也没见过说负载高，cpu 使用率不高的。因为 load average 本来就是 cpu 队列，cpu 使用率不高就出现队列，也不是没可能，要是同步对象争用什么的。也应该可以看到 cs 吧。于是，我让他把 vmstat 打印出来给我看一下。

我去，确实没有中断，也没有 cs。但是，但是，sys CPU 这不都 94 左右了吗？为什么还说使用率不高？

结果他说，我看 us cpu 不高呀，本着救人救到死，送佛送上天的原则。

我还是耐心地分析了一下，从现象来看确实是个问题。

从上一个截图看应该是负载低的时候截的。不过也没关系，sys cpu 高到这种程度已经可以分析了。

既然 sys cpu 这么高，当然要看一下 cpu 热点在哪。因为从现在的数据来看，确实不知道应该在哪。

自旋锁（说明一下，自旋锁是正常的多核 CPU 并发控制机制，它占 cpu 高通常都是问题的表现，根本原因 99.99 %都在它处）

这时我才想起来，我还不知道这个操作系统上跑的是什么东西。于是问了一下。这小伙说跑的 Jmeter。

唉，你说我费这劲干吗，跑个 Jmeter 直接看 Jmeter 不就好了。上面确实看到 java 进程消耗的 cpu 高的。

这种情况，我也确实不记得见过。

同样，跟分析 java 的任意进程一样。打堆栈、转pid，找到它。

为什么这里，我要这样做，而不是问 Jmeter 执行的什么脚本、什么业务逻辑呢？

因为这种的远程分析，信息的传递经常会有缺失。对方也不一定知道要怎么回答。

在性能分析过程中，经常出现的一种情况就是“我觉得是没有问题的”、“我觉得这个角度我已经分析过了”。可怕的就是这种“我觉得”，因为判断的标准因为技术背景和经验、以及经历的不同，会出现完全不同的判断结果。所以在大部分的沟通过程中，我都倾向于自己看数据的方式，因为这样的数据只会表现真实的情况，不会给一个错误的判断，而这个判断只能由自己来做。

"省市县查询 1-46" #65 prio=5 os_prio=0 tid=0x00007f93582ab000 nid=0x4a84 runnable [0x00007f92e7dfb000]
   java.lang.Thread.State: RUNNABLE
  at java.net.PlainSocketImpl.socketConnect(Native Method)
  at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
  - locked <0x00000000de80d890> (a java.net.SocksSocketImpl)
  at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
  at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
  at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
  at java.net.Socket.connect(Socket.java:589)
  at org.apache.http.conn.socket.PlainConnectionSocketFactory.connectSocket(PlainConnectionSocketFactory.java:75)
  at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:142)
  at org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl$JMeterDefaultHttpClientConnectionOperator.connect(HTTPHC4Impl.java:331)
  at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:373)
  at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:394)
  at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:237)
  at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
  at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
  at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
  at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
  at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
  at org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl.executeRequest(HTTPHC4Impl.java:832)
  at org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl.sample(HTTPHC4Impl.java:570)
  at org.apache.jmeter.protocol.http.sampler.HTTPSamplerProxy.sample(HTTPSamplerProxy.java:67)
  at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1231)
  at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1220)
  at org.apache.jmeter.threads.JMeterThread.doSampling(JMeterThread.java:622)
  at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:546)
  at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:486)
  at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:253)
  at java.lang.Thread.run(Thread.java:745)
   Locked ownable synchronizers:
  - None

看起来这是应该去正常工作的线程吧。但是，我看了一下，这样的线程有 48 个，全在这个状态。

这就完全不合理了，一个正常工作的 Jmeter（通篇看完，才会知道这句话不够严谨），accept 多都能理解，connect 多，怎么对呢。

翻一下 Jmeter 的代码，看这一段干的啥。

private CloseableHttpResponse executeRequest(final CloseableHttpClient httpClient,
            final HttpRequestBase httpRequest, final HttpContext localContext, final URL url)
            throws IOException {
        AuthManager authManager = getAuthManager();
        if (authManager != null) {
            Subject subject = authManager.getSubjectForUrl(url);
            if (subject != null) {
                try {
                    return Subject.doAs(subject,
                            (PrivilegedExceptionAction<CloseableHttpResponse>) () ->
                                    httpClient.execute(httpRequest, localContext));
                } catch (PrivilegedActionException e) {
                    log.error("Can't execute httpRequest with subject: {}", subject, e);
                    throw new RuntimeException("Can't execute httpRequest with subject:" + subject, e);
                }
            }
        }
        return httpClient.execute(httpRequest, localContext);
    }

（唉，写这文章的时候，我回想当时可能也是闲的。真不应该看这些乱七八糟的，这就是远程分析的缺点，要是在现场，估计一眼就看出来问题在哪了。）

执行一个请求的时候，没执行成功。好明显，那就是请求有问题呗。于是我问他，日志里是不是大量的 Can't execute httpRequest with subject:？

他去一翻日志，回答说，嗯，还真是。

唉，脚本都没跑成功嘛。我费这一圈的劲。

总结

虽说这个问题是个小白的乌龙问题，而我也没有在一开始问清楚场景和一些条件，导致后面这一顿折腾，又看热点，又看自旋锁，又看堆栈，又翻代码的，根本就是不值当的过程。

其实这个分析有价值的地方是因为以上数据反应出来一个有价值的结论。

但是从分析的过程来看是比较有可参考的价值的，所以我记录下来。

总体来说，从问题的表象到原因之间，都是会有证据可循的。而在分析的过程中就是要把证据找出来。层次清晰，逻辑合理，不要绕来绕去把问题复杂化。