我的性能分析之路启程

回顾我的职业生涯，中间件技术专家这个角色持续的时间最长，关于性能分析经历了许多，但故事要从我顿悟的那个案例开始。

某集团省公司新系统上线

该公司计划将核心业务升级到 WebService 架构。通过 WebService 将应用前后端分离。这里说的前端和后端都是运行在 WebLogic 的 Java Web 程序，只是前端负责生成 Web 页面，而后端则是负责执行业务逻辑。

可以想象，这样激进的架构不仅开发成本很高，也可能面临许多未知的风险。临近上线执行性能测试时，果然遇到了问题。新采购的小型机 CPU 已经拉满，但是几十个节点的集群才能达到几百的吞吐量。于是这个公司找到了我们提供支持，他们怀疑 WebLogic 需要调优。

可能很多年轻的朋友也不知道什么是 WebService，简单说就是一种分布式计算技术。和现在基于 JSON 的 API 很像，但报文封装用的是 SOAP，SOAP 是一种非常复杂的 XML。这个技术当年被许多大厂商推崇，但现在已经不太常见了，这里就不分析原因了，通过阅读本文你可能会对这个技术有一定的感受。

再讲讲我当时的情况。我是 Java 程序员出身，工作中接触到了 WebLogic，基本管理配置还是比较熟悉的。我也组织过大规模的性能测试，对于各类瓶颈有一定的认识。不过因为测试的对象都是成熟的系统，性能达标后就没有进一步优化，并没有在调优上做更多的工作。因此，这次支持对我来说可能也是一个挑战。

一般情况下，CPU 拉满是好现象，整个应用的瓶颈是 CPU 了，说明已经已经发挥了硬件的完全性能，可以暂时不考虑性能相关的其他因素。那么是什么占用了 CPU？当时的工具还不健全，也可能是我技能还不够完整，不过我觉得有一个思想是永远不会变的，需要更清楚地看到问题。

是应用占据了 CPU 吗？

确认这一点很容易，top、ps 命令都可以，很明显是 WebLogic 的 Java 程序占据的 CPU 最高。

哪些线程 CPU 高？

这里的操作系统是 AIX，我知道可以用 ps 命令查看线程的 CPU 占用率：

[/app/weblogic/bea/user_projects/domains/kfapp_domain]$ps -mp 172540 -o THREAD
    USER    PID   PPID      TID ST  CP PRI SC    WCHAN        F     TT BND COMMAND
weblogic 172540 119578        - A  1083  60 203        *   242001  pts/0   - /usr/java5_64/bin/java -Xms512m 
       -      -      -   377063 S    0  82  1 1190361d8   c10400      -   - -
       -      -      -   401657 S    2  83  1 f100070f10006240  8410400      -   - -
       -      -      -   405745 S    0  62  1 f100070f10006340  8410404      -   - -
       -      -      -   409615 R    8  60  1        -   400000      -   - -
       -      -      -   417831 S    1  82  1 f100070f10006640  8410400      -   - -
       -      -      -   434239 S    2  83  1 11cb85168   c10400      -   - -
       -      -      -   446625 S    0  82  1 f100070f10006d40  8410400      -   - -
       -      -      -   450639 S    0  82  1 f100070f10006e40  8410404      -   - -
       -      -      -   471155 S    0  82  1 f100070f10007340  8410404      -   - -
       -      -      -   475273 S    2  83  1 11cb85168   c10400      -   - -
       -      -      -   491667 R    7  60  1 11487ec88   c00000      -   - -
       -      -      -   508127 S    6  86  1 11cb85168   c10400      -   - -
       -      -      -   524491 S    0  66  1 f100070f10008040  8410400      -   - -
       -      -      -   528603 S   10  88  1 11cb85168   c10400      -   - -
       -      -      -   532703 S    0  82  1 1190361d8   c10400      -   - -
       -      -      -   545005 R   21  60  1 11487ec88   c00000      -   - -

从 CP 字段可以看到，并没有某个或某些线程的占用的 CPU 较高，难道就是应用本身慢吗？

作为 Java 应用中间件产品专家，对于产品的了解固然重要，但另一个很重要的难点是如何证明不是中间件的问题。应用运行在中间件上，还可能要与其他外围系统交互，很多问题并不是中间件产品的问题，但是如何证明呢？

进一步分析

我知道，我还有个 Java 工程师最常用的工具：线程堆栈。因为这里用的是 AIX，其 JDK 为 IBM JDK 。通过 kill -3 [pid] 我们就可以在 WebLogic 根目录得到一个 javacore 开头的文件，也就是线程堆栈文件，线程堆栈就是 Java 进程的线程快照。

我用 kill -3 得到了几个快照，但结论并不是那么一目了然，大多数工作线程都处于类似下面的状态：

at java/util/zip/ZipFile.getEntry(Native Method) 
at java/util/zip/ZipFile.getEntry(ZipFile.java:292(Compiled Code)) 
at weblogic/utils/classloaders/ClasspathClassFinder.getZipSource(ClasspathClassFinder.java:360(Compiled Code)) 
at weblogic/utils/classloaders/ClasspathClassFinder.getSourcesInternal(ClasspathClassFinder.java:296(Compiled Code)) 
at weblogic/utils/classloaders/ClasspathClassFinder.getSource(ClasspathClassFinder.java:272(Compiled Code)) 
at weblogic/utils/classloaders/JarClassFinder.getSource(JarClassFinder.java:46(Compiled Code)) 
at weblogic/utils/classloaders/MultiClassFinder.getSource(MultiClassFinder.java:64(Compiled Code)) 
at weblogic/utils/classloaders/MultiClassFinder.getSource(MultiClassFinder.java:64(Compiled Code)) 
at weblogic/utils/classloaders/MultiClassFinder.getSource(MultiClassFinder.java:64(Compiled Code)) 
at weblogic/utils/classloaders/CodeGenClassFinder.getSource(CodeGenClassFinder.java:33(Compiled Code)) 
at weblogic/utils/classloaders/MultiClassFinder.getSource(MultiClassFinder.java:64(Compiled Code)) 
at weblogic/utils/classloaders/CodeGenClassFinder.getSource(CodeGenClassFinder.java:33(Compiled Code)) 
at weblogic/utils/classloaders/GenericClassLoader.findResource(GenericClassLoader.java:212(Compiled Code)) 
at weblogic/utils/classloaders/GenericClassLoader.getResourceInternal(GenericClassLoader.java:143(Compiled Code)) 
at weblogic/utils/classloaders/GenericClassLoader.getResource(GenericClassLoader.java:169(Compiled Code)) 
at java/lang/ClassLoader.getResourceAsStream(ClassLoader.java:482(Compiled Code)) 
at weblogic/apache/xerces/util/SecuritySupport12$4.run(SecuritySupport12.java:119(Compiled Code)) 
at java/security/AccessController.doPrivileged(AccessController.java(Compiled Code)) 
at weblogic/apache/xerces/util/SecuritySupport12.getResourceAsStream(SecuritySupport12.java(Compiled Code)) 
at weblogic/apache/xerces/util/ObjectFactory.findJarServiceProvider(ObjectFactory.java:299(Compiled Code)) 
at weblogic/apache/xerces/util/ObjectFactory.createObject(ObjectFactory.java:191(Compiled Code)) 
at weblogic/apache/xerces/util/ObjectFactory.createObject(ObjectFactory.java:121(Compiled Code)) 
at weblogic/apache/xerces/parsers/DOMParser. (DOMParser.java:157(Compiled Code)) 
at weblogic/apache/xerces/parsers/DOMParser. (DOMParser.java:140(Compiled Code)) 
at weblogic/apache/xerces/jaxp/DocumentBuilderImpl. (DocumentBuilderImpl.java:103(Compiled Code)) 
at weblogic/apache/xerces/jaxp/DocumentBuilderFactoryImpl.setAttribute(DocumentBuilderFactoryImpl.java:126(Compiled Code)) 
at weblogic/xml/jaxp/WebLogicDocumentBuilderFactory. (WebLogicDocumentBuilderFactory.java:49(Compiled Code)) 
at weblogic/xml/jaxp/RegistryDocumentBuilder.getDefaultDocumentBuilderFactory(RegistryDocumentBuilder.java:283(Compiled Code)) 
at weblogic/xml/jaxp/RegistryDocumentBuilder.getDocumentBuilder(RegistryDocumentBuilder.java:222(Compiled Code)) 
at weblogic/xml/jaxp/RegistryDocumentBuilder.parse(RegistryDocumentBuilder.java:147(Compiled Code)) 
at org/apache/axis/utils/XMLUtils.newDocument(XMLUtils.java:322(Compiled Code)) 
at org/apache/axis/utils/XMLUtils.newDocument(XMLUtils.java:335(Compiled Code)) 
at org/apache/axis/configuration/FileProvider.configureEngine(FileProvider.java:209(Compiled Code)) 
at org/apache/axis/AxisEngine.init(AxisEngine.java:187(Compiled Code)) 
at org/apache/axis/AxisEngine. (AxisEngine.java:172(Compiled Code)) 
at org/apache/axis/client/Service.getAxisClient(Service.java:143(Compiled Code)) 
at org/apache/axis/client/Service. (Service.java:152(Compiled Code)) 
at com/xxx/esb/action/webservice/ZJESBserviceServiceLocator. (ZJESBserviceServiceLocator.java:10(Compiled Code)) 
at com/yyy/integration/eai/xxxFacadeESB.getxxxESBStub(xxxFacadeESB.java:33(Compiled Code)) 
at com/yyy/integration/eai/xxxFacadeESB.doBussiness(xxxFacadeESB.java:177(Compiled Code)) 
at com/yyy/integration/eai/xxxESBServiceBean.doBussiness(xxxESBServiceBean.java:29(Compiled Code)) 
at com/yyy/integration/ejb/BusinessServiceBean.searchBusiNumLinkOrderNum(BusinessServiceBean.java:2122(Compiled Code)) 

...

大量线程处于这样的状态。堆栈最后是 JDK 和 WebLogic 的方法，是否意味着 JDK 或 WebLogic 本身有性能问题？一个有经验的工程师其实会反问，如果基础的类库有问题，大概率早就有人报告了，所以还是看看自己哪里有问题。

这个思考过程其实也告诉我们，应该等某个产品的大版本成熟后再选用，这样应该可以避开那些严重的软件 Bug 。

此时此刻，如果我跟这个客户和开发商说是他们应用的问题，估计不会得到太正面的回应，毕竟证据不明显，而开发商和客户的技术水平可能更加无法理解这些现象。

那时的我的知识水平也比较有限，所以只能从现有的数据中寻找线索，于是我做了一个后来看来非常正确的动作，我将所有的线程堆栈做了一个统计，形成以下表格:

正在执行的方法	线程数量	百分比
java/util/zip/ZipFile.getEntry(Native Method)	33	16%
java/util/zip/ZipFile.getEntry(ZipFile.java:290(Compiled Code))	24	12%
com/yyy/util/UUID.(UUID.java:81(Compiled Code))	24	12%

而且这些堆栈都指向了同一个方法：

at org/apache/axis/client/Service.getAxisClient(Service.java:143(Compiled Code))

突然之间，我做开发时的一个记忆闪现了出来：对于 EJB 操作，因为 EJB Stub 的创建非常耗时，应该在客户端进行缓存。这个 Axis 的客户端，是否也有类似的问题？

解决问题

与应用开发人员一起找到了这段代码对应的应用代码，发现果然是每一次请求都会新建一个 Axis 客户端。于是修改代码，将 Axis 客户端存放到了 ThreadLocal 上，又重新进行了测试。效果相当的惊人，吞吐量轻松提高了 10 倍以上。

什么是 Profiling 工具？

这次问题处理，帮客户解决了大问题，对我个人也有着重大的意义，从此我对这个行业有了比较充分的信心。

不久之后我进了 IBM，主要是做 WebLogic 和 WebSphere Application Server （WAS）的支持。WAS 有着更加健全的诊断体系，例如 WAS 的 MustGather 网站详细说明了不同的故障应该收集的信息，以及处理方法。这让我有机会更系统地学习软件的问题诊断。

因为当时 AIX 的市场占有率很高，所以接触到的工具也是 AIX 的。通过学习和实践，我发现了 tprof 这个工具，例如通过执行命令 tprof -kesj -x sleep 60，我们可以得到以下报告：

...
Shared Object                                                             %  
=============                                                          ======
/usr/java6_64/jre/lib/ppc64/default/libj9prt24.so                       38.23
/usr/java6_64/jre/lib/ppc64/default/libjclscar_24.so                    26.27

...
 Total % For All Processes (/usr/java6_64/jre/lib/ppc64/default/libj9prt24.so) = 38.23

Subroutine                                            %   Source              
==========                                         ====== ======              
rt_time_TEXT                                        27.92 rt_time.s           
.j9time_current_time_millis                         10.32 aix/j9time.c        

Profile: /usr/java6_64/jre/lib/ppc64/default/libjclscar_24.so

  Total % For All Processes (/usr/java6_64/jre/lib/ppc64/default/libjclscar_24.so) = 26.27

Subroutine                                            %   Source              
==========                                         ====== ======              
.JIT_java_lang_System_currentTimeMillis             20.38 jlsys.s             
._ptrgl                                              5.89 ptrgl_64.s 
...

这个报告是 60 秒的时间里 CPU 被程序占用的一个统计报告。可以看到 38.23 的 CPU 时间在执行动态链接库 libj9prt24.so 的程序，具体来说 27.92% 是在执行 rt_time_TEXT 这个方法。

这是取自另一个故障的数据，应用中大量的获取系统时间的操作严重的影响了系统的运行效率。

如果我早点知道 tprof ，我可能可以更好地完成本文所说的那次问题诊断，其实我已经自发的用 tprof 的思想执行了 profiling。

tprof 命令执行时，每隔一定的时钟周期，便会记录正在执行的指令，然后将所有的记录进行统计分析，形成报告。报告中出现较多的指令，通常也是占用 CPU 最多的指令，从而我们可以判断哪些方法，哪些组件可能存在性能问题。

现在大家都知道火焰图，这正是 profiling 工具收集数据的一种图形化展示方式：

其他工具

随着 Linux 的占有率越来越高，我们更多的使用 perf 命令实现 profiling。许多新兴的编程语言，也内置了更好的工具，例如 go 语言的 pprof。随着云原生的发展，还有 eBPF 的出现，又有人提出了 continuous profiling 这个概念。例如 Pyroscope ，通过这样的工具，我们可以随时随地实现 profiling 。

后记

职业生涯早期的这个关键之战对我意义重大。在那短短的一周里，我解决了两个关键问题，让项目能够顺利上线，赢得了合作伙伴的信任。更重要的是，这次支持也给了我信心，促使我完善自己的知识体系，让我能够更自信从容地应对未来的挑战。

不过，自此我也发现，这个行业有太多不专业的人。许多时候，即使你解决了问题，可能也无法得到感谢。例如这个客户的领导其实完全不懂技术，她并不能判断谁对谁错，谁的贡献更大，但是却有一股子不知道来自何处的傲慢。多年之后又遇到了这位领导，态度依旧，实在是不想跟这种人合作了。以后有机会跟大家聊聊工作生涯中遇到的奇葩事情奇葩人，顺便聊聊技术。