LoadRunner脚本日志定位问题案例

小编说：在实际工作中，很多使用LoadRunner 的测试人员开发Vuser 脚本时总会遇到这样或那样的问题，影响到性能测试工作的正常进展。而对于性能测试人员而言，Vuser 脚本开发技能是一项基本功，需要在工作中长期修炼才能学有所成。

本文选自《LoadRunner虚拟用户高级开发指南》一书，该书主要为了LoadRunner 使用人员精通脚本开发而创作，目的是分享作者们的经验，使大家在更短的时间内成为LoadRunner 的高手。

本案例来源于一个银行项目的性能调优阶段。

在性能调优过程中发现如下现象：LoadRunner 分析报告中的“缴费”等事务响应时间始终比目标测试模块日志统计到的时间多了200ms 左右。其中，LoadRunner 统计了从发出交易报文到返回执行结果的时间，目标系统则记录了“从收到LoadRunner 报文后进行处理=>发送给其后台模块处理=>其后台模块返回结果=>处理后将执行结果返回给LoadRunner”这一过程的时间。

对于这个问题，依次进行了如下的排查过程。

第一步：首先核实Vuser 脚本，确认脚本本身处理过程是否存在性能消耗。分析的重点主要涉及对报文进行的数据处理、返回结果的分析判断等代码是否有问题。为了分析问题将脚本最终简化成如例4-38 所示，但问题仍然存在。

第二步：分析目标测试模块的日志记录环节，确认没有问题。

第三步：通过监控网络性能，进一步确认了网络没有问题。

上面的几个常见原因依次排除后，基本可以确定这200ms 应该耗费在LoadRunner 与目标测试系统的通信交互过程中，测试团队需要做的是，深入分析时间具体耗费在哪些交互环节上。

分析这类问题，最重要的手段就是深入分析Vuser 脚本的执行日志。打开脚本的“Run-time Settings”对话框，勾选扩展Log 中的“Advanced trace”复选框，以打卡执行过程的详细追踪。注意扩展Log 中的其他选项不要勾选，否则日志输出较多的情况下阅读起来较麻烦，不容易定位问题。

脚本执行完成后，接下来开始分析执行日志来查找问题。为了便于讲解，下面分别列出了发送和接收过程的日志。发送过程日志如下：



可以看到，从15:45:29.148 开始读取buf0，15:45:29.226 完成发送，总共耗时78ms。因此可以判断多消耗的200ms 不可能耗费在发送环节上，从而可以初步断定问题很有可能出在接收报文的环节上。接收过程日志如下：


我们详细分析一下上面的接收过程日志。

•15:45:29.288: 准备从socket0 读取542 字节。

•15:45:29.319: 准备首次从socket 读取数据，超时设置为10s。

•15:45:29.538: 准备读取8192 个字节。

•15:45:29.584: 存储读取到的9 个字节。

•15:45:29.600: 未接收到指定长度数据，按照超时设置10s 继续等待。

•15:45:29.756: 准备读取8192 个字节。

•15:45:29.787: 存储读取到的651 个字节。

•15:45:29.818: 未接收到指定长度数据，按照超时设置10s 继续等待。

•15:45:29.850: 准备读取8192 个字节。

•接收完成，接收长度不匹配（期望 542 字节，实际收到 660 字节，相差118 个

•字节）。

• ……

在上面的报文接收过程中，可以看到一共进行了3 次接收数据操作：第一次接收了9个字节；第二次接收了651 个字节；第三次接收时Socket 已经关闭因此完成了接收。需要引起注意的是，前两次接收的时候相差时间为15:45:29.787－15:45:29.584=203ms。这203ms是很有可能就是LoadRunner 统计时间与应用程序日志统计结果的偏差。

两次接收时间相差了203ms，这不是正常情况下的网络延迟时间。因此，可以初步怀疑应用程序是分了两次来发送报文：第一次发送了报文头；第二次发送了报文体；之后断开了Socket 连接，所以看到了Vuser 第三次接收报文时没有收到任何内容，并完成接收报文函数的执行。

为了验证上面的假设，先修改一下接收数据过程的超时时间设置，将默认的10s 修改为0.1ms（超时设置应该小于200ms，这样可以只接收到第一次发送的报文头，从而确认每次接收报文过程中形成的接收等待时间是有规律的）。

具体操作为在事务开始前增加语句“lrs_set_recv_timeout2(0,100000);”，修改的脚本如例4-39 所示。

回放脚本， 部分执行日志如下：


在上面的日志中可以看到加入超时设置后，可以看到本次共接收了9 字节，基本可以断定应用程序返回报文分两次发送。接下来继续通过实验验证结论：增加一次接收过程来确认是因为应用程序分两次发送报文形成的时间间隔导致浪费了200ms。

修改后的脚本如例4-40 所示。

例4-40 中，第二次接收过程“lrs_receive(“socket0”, “buf2”, LrsLastArg);”语句对应执行日志如下：

在上面的日志中可以看到第二次接收函数执行时能够成功接收到数据，接收完成后Socket 关闭。这时已经可以完全确定应用程序返回交易执行结果过程如下：第一步发送报文头；第二步发送报文体；第三步关闭Socket 连接。通过与开发团队进行反复沟通与确认，证明了测试小组的结论。

在应用程序将两次发送报文合并成一次发送后，LoadRunner 统计结果与应用程序统计结果基本一致。到这一步终于完成了对应用程序底层代码的调优，使大部分交易性能均提高了200ms 以上。