性能分析之激情的过程无奈的结局

Posted 2021-12-03 高楼（Zee）

今天有个人微信上问问题。

说cpu使用率不高，为什么负载那么高？截图为证。

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

我去，确实没有中断，也没有cs。但是，但是，sysCPU这不都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("Cant execute httpRequest with subject: {}", subject, e);                    throw new RuntimeException("Cant execute httpRequest with subject:" + subject, e);                }            }        }        return httpClient.execute(httpRequest, localContext);    }

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

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

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

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

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

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

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

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