一、将收集来的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.分析 RpcSqlD.V60SP1.log

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

 RpcSqlD.V60SP1.log文件中记录了各个线程需要执行哪些sql,执行这些sql需要消耗多少时间，具体某个线程消耗的总时间记录在关键字invokeTime中 （一般有几个线程就有几个invokeTime），用notepad之类的工具打开 RpcSqlD.V60SP1.log。按“ctrl”+ F 搜素所有的”invokeTime”关键字 点击“Find All in Current Document”

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

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

• dbTime:这个线程消耗在数据库上的时间，如果时间很长，需要分析数据库awr报告

• sqlTime: 这个线程消耗在sql执行上的时间，如果时间很长，需要分析数据库awr报告

• cpuTime:  这个线程消耗在应用服务器上的时间，如果时间很长，证明应用服务器有问题，需研发进一步分改功能是否有异常。

• timespan：具体某条sql执行的时间，如果很长需分析其对应的执行计划

补充：

根据rpcD.V60SP1.log文件中的invoke_id来RpcSqlD.V60SP1.log中找到对应sql(timespan时间很长的那个sql就是执行时间长的sql，找到sql_id,根据sql_id可以去SqlPlanD.V60SP1.log文件中查看这条sql语句的执行计划)

3. 分析SqlPlanD.V60SP1.log

SqlPlanD.V60SP1.log中可以查看sql的执行计划