欢迎大家来到IT世界,在知识的湖畔探索吧!

起因

近日某客户使用了Klink-API集成平台进行企业内部应用系统进行集成，客户发现使用AXIS1.4进行请求交易耗时长，超过了200秒，客户一连几天都为这个事情联系我，为了让客户放心，我亲自带领团队进行问题分析。本次分析耗时3天，我已经有好几年没有这么带劲的分析问题了。

现象

客户方调用耗时图片

交易开始调用时间为：2022/04/22 06:06:30,030；结束时间为：2022/04/22 06:09:31,051；总计耗时大约为：180秒左右（3分钟）

我们来看看交易链路：

交易链路图

API请求方的代码是通过AXIS1.4自动生成的（注意这里不详细说明如何生成代码，某度就能够搜索到），通过生成的代码发送soap消息给Klink平台，Klink平台将请求方系统转换为https协议和json消息发送给API提供方。

1、这里不详细说明如何通过AXIS1.4自动生成请求代码，可以某度进行搜索；

2、也不详细说明如何组装soap报文；

3、AXIS1.4生成代码需要wsdl文件，AXIS1.4是一个通过wsdl文件自动生成java代码的工具；

分析过程

1、通过Klink平台的日志模块查看调用链路耗时：

交易耗时

Klink平台分为：日志模块和监控模块；

监控模块：通过漂亮的图表查看整个企业API的交易链路，包括：耗时，错误率，今日交易量，失败率等；

日志模块：通过关键字，时间段，流水号查看交易链路调用日志

那么我们使用了日志模块查询到这笔交易的情况，从日志可以看出klink平台耗时大约在1秒内（毫秒字段被隐藏起来了，可以查询毫秒的）

第一个怀疑点：网络层

客户请求通过域名进行访问，所以第一个怀疑点DNS解析耗时，通过traceroute查看DNS跳点数量。

traceroute结果

通过traceroute发现路由跳点只有1个，DNS解析怀疑排除了。继续排查网络，团队写了一个httpSender.jar工具，这个工具可以发送http请求；将这个工具部署到自己的服务和客户服务器运行看看耗时。

运行jar

耗时结果

通过运行jar发现在客户服务器耗时在5秒左右（耗时包括：DNS解析,VPN连接耗时等）;

通过以上工具分析第一个怀疑点网络层抛弃了

第二怀疑点：AXIS1.4建连耗时和发送逻辑

最后没有办法了只能查看AXIS1.4源码，查看它的网络建连耗时多少，发送逻辑是怎么样的。

1、首先得复现和客户一样的情况，通过AXIS1.4生成代码，发送交易，耗时居然在200S左右（居然复现了，这里就成功了一半了）

2、查看请求逻辑，通过查看axis1.4源码得知，axis1.4是通过socket发送http请求，socket建立连接很快。但是发现axis1.4发送的时候是http1.0，请求头里面没有使用http1.1的connection：keep-alive（keep-alive是什么这里不科普了），后续想了想，有很多交易也是通过axis1.4发送请求的，为什么它们请求这么快速呢？

3、跟踪AXIS1.4源代码发现，AXIS在从SocketInputStream里面读取字节数的时候耗时了200秒左右，定位点在XML11Configuration类848行，这个行代码就是从Socket里面读取字节码将字节码转换为xml报文

XML11Configuration部分代码

4、AXIS是通过SAX解析xml报文的，xml文档是有结束符号的，大家知道XML的结束符号为> ascii为62，通过在SocketInputStream的字节数组里面发现最后一个字节确实也为62，文档结束符没有问题，为什么需要看结束符呢？这里有一个读取字节数据的循环代码，当读取到文档结束符后才会跳出循环

XMLDocumentFragmentScannerImpl读取字节码

5、返回报文里面有中文字符（重点了）。

解决疑难杂症的最好办法就是重现问题，如果你复现了现象，那么你就能够解决问题了。

第三怀疑点：编码

1、之前在协议上面已经检查了请求编码和响应编码都是UTF-8，但是为什么还会有编码问题呢？

2、WebService底层发送逻辑还是Http协议，Http协议底层发送是socket，检查Http协议的response是否设置请求头为Content-Type：text/xml; charset=utf-8（没有问题），返回的报文是否通过UTF-8编码返回（没有问题）;

3、最后检查是否设置了response.setCharacterEncoding(“UTF-8”);（天哪这里居然没有设置编码格式）

4、问题解决后，我们通过AXIS1.4发送请求，解析非常快，如下图：

问题解决后通过axis1.4发送请求耗时为1秒

解释一下 Content-Type 和 setCharacterEncoding的区别

response.setHeader(“Content-type”, “text/html;charset=UTF-8”);

//这句话的意思，是让浏览器用utf8来解析返回的数据，重点浏览器，浏览器，浏览器

response.setCharacterEncoding(“UTF-8”);

//这句话的意思，是告诉请求方用UTF-8转码，而不是用默认的ISO-8859-1

总结

分析协议的交易耗时一般是比较困难的，它发生的原因有多种，例如：1，线程池处理大并发请求堵塞；2、DNS解析耗时、网络层建立连接耗时，可能需要抓包工具进行抓包分析等；本次分析总计耗时3天，写了一个份报告给客户，客户对此很满意。这里记录下分析过程。