JMeter自定义日志与日志分析

深藏阁楼爱情的钟 2023-10-18 21:36 84阅读 0赞

#### JMeter自定义日志与日志分析 ####

*  1 JMeter日志概览
 *  2 JMeter自定义日志
 *  3 JMeter日志分析

## 1 JMeter日志概览 ##

JMeter与Java程序一样，会记录事件日志，日志文件保存在bin目录中，名称为`jmeter.log`。当然，我们也可以在面板中直接察看日志，点击右上角黄色标志物可以打开日志面板，再次点击收起。

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_center]  
可见，通过日志可以帮助我们定位一些不容易直接察觉的问题。

另外，JMeter可以很方便地设置日志输出级别：  
![在这里插入图片描述][20200902134410665.png]

## 2 JMeter自定义日志 ##

前面所看到的都是系统日志，也就是JMeter本身所打印的日志。如果我们自己想输出一些日志，该怎么办呢？这个一般就要借助Beanshell了。

例如，一个接口响应结果如下：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_left]  
在该请求下添加Beanshell断言，运行后，日志中输出了相应内容：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_left 1]

import org.apache.log4j.Logger;
    
    // 获取接口的响应数据
    String result = prev.getResponseDataAsString();
    
    if(result.contains("error")){
        
    	Failure=true;
    	log.error("接口失败: " + result);
    }

当然，自定义日志最重要的作用还是在Linux服务器上运行脚本时，因为没有界面，排查问题更加麻烦。

> 承接前文，将JMeter脚本部署到Linux服务器上进行压力测试，存在一些不便之处：
> 
> 1.  吞吐量统计中包括了所有请求，包括一些辅助请求(beanshell请求)，导致真正的tps统计数据不准确。
> 2.  业务是否成功，以及具体失败原因难以排查。

首先，测试接口的响应内容如图所示：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_center 1]

在接口下添加2个【JSON Path Extractor】，分别用于在测试接口的响应内容里提取code、orderId。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_left 2]  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_left 3]

再在测试接口下添加【BeanShell断言】：

import org.apache.log4j.Logger;
    
    // 获取接口的响应数据
    String result = prev.getResponseDataAsString();
    // 从JSON提取器中获取code和orderId
    String code = vars.get("code");
    String orderId = vars.get("orderId");
    
    if(code.equals("0")){
        
    	log.info("place order success, orderId=" + orderId);
    }else{
        
    	Failure=true;
    	log.error("FailureMessage: " + result);
    }

将该脚本上传到Linux中，顺便写个启动脚本：start.sh

#!/bin/bash
    jmeter_log=/home/test/jmeter.log
    
    if [ -f "$jmeter_log" ]; then
     // 将原日志文件备份后删除
     cp $jmeter_log /home/test/jmeter.log_back
     rm -rf $jmeter_log
    fi
    // 启动JMeter脚本
    jmeter -n -t /home/test/test.jmx -l /home/test/result/test.jtl

运行脚本后，cat jmeter.log，效果如下：  
![在这里插入图片描述][20190713154054546.png]

## 3 JMeter日志分析 ##

针对该日志写一个日志分析脚本`logAnalysis.sh`：

#!/bin/bash
    jmeter_log=/home/test/jmeter.log
    thread_num=`grep 'Thread started' $jmeter_log|tail -n 1|awk -F"-" '{print$6}'`
    start_time=`grep 'All thread groups have been started' $jmeter_log|awk -F" " '{print $1,$2}'|awk -F"," '{print $1}'`
    end_time=`grep 'Shutdown hook ended' $jmeter_log|awk -F" " '{print $1,$2}'|awk -F"," '{print $1}'`
    
    final_success_time=`grep "place order success" $jmeter_log|tail -n 1|awk -F" " '{print$1,$2}'|awk -F"," '{print$1}'`
    success_running_time=$[ $(date -d "$final_success_time" +%s) - $(date -d "$start_time" +%s) ]
    running_time=$[ $(date -d "$end_time" +%s) - $(date -d "$start_time" +%s) ]
    cancle_times=`grep "cancle orders success" $jmeter_log|wc -l`   //撤单次数
    
    success_times=`grep success $jmeter_log|wc -l`   // 成功次数
    failure_times=`grep FailureMessage $jmeter_log|wc -l`
    request_times=$[ $success_times+$failure_times ]
    error_rate=`echo "scale=2; $failure_times/$request_times*100" | bc`
    qps=$[ $request_times/$running_time ]
    throughput=$[ $success_times/$success_running_time ]
    
    echo -e '线程数:'$thread_num
    echo -e '请求次数:' $request_times
    echo -e '成功次数:' $success_times
    echo -e '失败次数:' $failure_times
    echo -e '撤单次数:'$cancle_times
    echo -e '错误率:' $error_rate'%'
    echo -e '开始时间:'$start_time
    echo -e '结束时间:'$end_time
    echo -e '最后成功请求时间:'$final_success_time
    echo -e '请求时间:' $running_time 
    echo -e '成功运行时间:'$success_running_time
    echo -e '吞吐量:'$throughput'/s'
    echo -e 'QPS:'$qps'/s'

当JMeter脚本运行一段时间后，执行logAnalysis.sh，效果如下：

线程数:180
    请求次数: 131691
    成功次数: 131493
    失败次数: 198
    撤单次数:141
    错误率: 0%
    开始时间:2018-11-28 15:34:54
    结束时间:2018-11-28 15:37:17
    最后成功请求时间:2018-11-28 15:37:17
    请求时间: 143
    成功运行时间:143
    吞吐量:919/s
    QPS:920/s

可以看到，输出信息全面清晰。这样，我们就可以在linux下运行JMeter压测脚本时，实时获取压测详情了。

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_center]: https://img-blog.csdnimg.cn/20200902134215382.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ=,size_16,color_FFFFFF,t_70#pic_center
[20200902134410665.png]: https://img-blog.csdnimg.cn/20200902134410665.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_left]: https://img-blog.csdnimg.cn/20200902141151877.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ=,size_16,color_FFFFFF,t_70#pic_left
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_left 1]: https://img-blog.csdnimg.cn/20200902141134990.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ=,size_16,color_FFFFFF,t_70#pic_left
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_center 1]: https://img-blog.csdnimg.cn/20200902141616195.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ=,size_16,color_FFFFFF,t_70#pic_center
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_left 2]: https://img-blog.csdnimg.cn/20200902142256264.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ=,size_16,color_FFFFFF,t_70#pic_left
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ_size_16_color_FFFFFF_t_70_pic_left 3]: https://img-blog.csdnimg.cn/20200902142239698.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L211X3dpbmQ=,size_16,color_FFFFFF,t_70#pic_left
[20190713154054546.png]: https://img-blog.csdnimg.cn/20190713154054546.png