如何分析rpc日志？

一、将收集来的rpc日志解压缩

一般收集的rpc日志会得到如下zip文件

1. 将RpcLogs.zip解压缩

得到一个rpcD.V60SP1.log和一个serverRpcLogs.zip

2.再将serverRpcLogs.zip解压缩

serverRpcLogs文件夹包含如下文件

二、rpc日志分析过程

说明：rpc日志中记录的时间以毫秒为单位（1秒=1000毫秒）

 1.首先分析rpcD.V60SP1.log

第一步：找到actionTime占用时间长的那一段或几段线程

rpcD.V60SP1.log文件中一般记录了java程序中若干段线程的调用时间占用情况。每一段线程调用的时间长短记录在actionTime中（一般有几个actionTime就有几段线程），用notepad之类的工具打开rpcD.V60SP1.log。按“ctrl”+ F 搜素所有的”actionTime”关键字 点击“Find All in Current Document”

得到如下结果，一般我们只需要关注actionTime占用时间比较长的（如果actionTime比较大，证明那一段线程rpc调用确实有问题，我们只需要关注那一段或几段的线程调用）双击actionTime占用时间长的那一行即可定位到目标位置

第二步：查看时间消耗在什么地方

双击actionTime占用时间长的那一行定位到目标位置后，查看时间具体消耗在什么地方？

有如下几个时间需要关注（分别用不同的颜色进行了标注）

这里actiontime是86813毫秒即86秒（证明执行截图的这段程序一共花了86秒）

• 如果cpuTime时间占用较多，证明时间花在客户端上，这时候需要收集客户端的线程堆栈。

• 如果某一个time时间占用较多，对应那一行的net_time占用的时间也很多的话证明网络可能有问题，需要ping或wireshark之类的工具进一步诊断，如果net_time占用的时间很短的话，可能sql执行有问题，用那一行invoke_id的对应值去RpcSqlD.V60SP1.log文件去找对应,根据sql_id可以去SqlPlanD.V60SP1.log文件中查看这条sql语句的执行计划)

• 如果绿色标注的两个时间段相隔比较长的话，证明两个时间段的那个线程调用可能有问题，需要具体线程具体分析

  例如上图中的com.kingdee.eas.fi.cas.client.CasReceivingBillListUI.initUIObject()方法调用时间接近82秒（09:36:57.749-09:35:33.597 约等于82秒）。这个线程有“client”关键字证明可能是客户端的线程堆栈，需要收集客户端的线程堆栈具体分析。如果是其他线程则需要对应的研发人员进行分析。

2.分析 RpcS