jmeter5_命令行方式测试和日志分析

1、背景

真正压力测试时，应该使用命令行模式，减少客户端对测试的影响。
jmeter启动日志里也有提示：

Don't use GUI mode for load testing !, only for Test creation and Test debugging
.
For load testing, use CLI Mode (was NON GUI):
   jmeter -n -t [jmx file] -l [results file] -e -o [Path to web report folder]
& increase Java Heap to meet your test requirements:
   Modify current env variable HEAP="-Xms1g -Xmx1g -XX:MaxMetaspaceSize=256m" in
 the jmeter batch file
Check : https://jmeter.apache.org/usermanual/best-practices.html

图形界面可用来调试脚本，真正测试还得用命令行模式。

2、举例

命令行用法：

jmeter -n -t [jmx file] -l [results file]

-n:非图形模式；
-t:测试脚本；
-l:测试结果明细;

D:\...bin>jmeter -n -t E:\testFisProd.jmx -l 102
Creating summariser <summary>
Created the tree successfully using E:\02--项目\20200303--开源研究\03--原型验证2\压力测试\testFisProd.jmx
Starting standalone test @ Tue Oct 27 14:54:30 CST 2020 (1603781670799)
Waiting for possible Shutdown/StopTestNow/HeapDump/ThreadDump message on port 4445
summary +      1 in 00:00:00 =   13.2/s Avg:    28 Min:    28 Max:    28 Err:     0 (0.00%) Active: 1 Started: 1 Finished: 0
summary + 151238 in 00:00:29 = 5253.1/s Avg:     8 Min:     0 Max:   866 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 151239 in 00:00:29 = 5239.3/s Avg:     8 Min:     0 Max:   866 Err:     0 (0.00%)
summary + 117126 in 00:00:30 = 3904.3/s Avg:    12 Min:     0 Max:   622 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 268365 in 00:00:59 = 4559.0/s Avg:    10 Min:     0 Max:   866 Err:     0 (0.00%)
summary + 101580 in 00:00:30 = 3386.1/s Avg:    14 Min:     0 Max:   423 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 369945 in 00:01:29 = 4163.0/s Avg:    11 Min:     0 Max:   866 Err:     0 (0.00%)
summary +  86745 in 00:00:30 = 2891.5/s Avg:    17 Min:     0 Max:   597 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 456690 in 00:01:59 = 3842.1/s Avg:    12 Min:     0 Max:   866 Err:     0 (0.00%)
summary +  77896 in 00:00:30 = 2596.4/s Avg:    19 Min:     0 Max:   579 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 534586 in 00:02:29 = 3591.1/s Avg:    13 Min:     0 Max:   866 Err:     0 (0.00%)
summary +  72364 in 00:00:30 = 2412.1/s Avg:    20 Min:     0 Max:   663 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 606950 in 00:02:59 = 3393.3/s Avg:    14 Min:     0 Max:   866 Err:     0 (0.00%)
summary +  66633 in 00:00:30 = 2221.2/s Avg:    22 Min:     0 Max:   688 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 673583 in 00:03:29 = 3225.0/s Avg:    15 Min:     0 Max:   866 Err:     0 (0.00%)
summary +  63270 in 00:00:30 = 2109.0/s Avg:    23 Min:     0 Max:   729 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 736853 in 00:03:59 = 3084.8/s Avg:    15 Min:     0 Max:   866 Err:     0 (0.00%)
summary +  61683 in 00:00:30 = 2056.1/s Avg:    24 Min:     0 Max:   908 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 798536 in 00:04:29 = 2970.0/s Avg:    16 Min:     0 Max:   908 Err:     0 (0.00%)
summary +  57966 in 00:00:30 = 1932.2/s Avg:    25 Min:     0 Max:   819 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 856502 in 00:04:59 = 2865.9/s Avg:    17 Min:     0 Max:   908 Err:     0 (0.00%)
summary +  54283 in 00:00:30 = 1809.4/s Avg:    27 Min:     0 Max:   809 Err:     0 (0.00%) Active: 50 Started: 50 Finished: 0
summary = 910785 in 00:05:29 = 2769.5/s Avg:    17 Min:     0 Max:   908 Err:     0 (0.00%)
summary +  37245 in 00:00:30 = 1241.3/s Avg:    28 Min:     0 Max:   773 Err:     0 (0.00%) Active: 10 Started: 50 Finished: 40
summary = 948030 in 00:05:59 = 2641.7/s Avg:    18 Min:     0 Max:   908 Err:     0 (0.00%)
summary +   1970 in 00:00:14 =  145.5/s Avg:    33 Min:     0 Max:   714 Err:     0 (0.00%) Active: 0 Started: 50 Finished: 50
summary = 950000 in 00:06:12 = 2550.9/s Avg:    18 Min:     0 Max:   908 Err:     0 (0.00%)
Tidying up ...    @ Tue Oct 27 15:00:43 CST 2020 (1603782043548)
... end of run

summary + :是增量的值；
summary = :是当前的累计值；
summary数量:是sampler执行的总数，不含configura组件；
in 00:06:12 = 2550.9/s:总执行时长，平均执行速度=950000/06:12。
Err ：失败的次数
Active: 0 Started: 50 Finished: 50：线程组活动、启动、完成情况。

3、日志分析

3.1日志结构

日志包含：时间戳、持续时长、组件名称、响应代码、线程名称、数据类型、是否成功、失败消息。

timeStamp,elapsed,label,responseCode,responseMessage,threadName,dataType,success,failureMessage,bytes,sentBytes,grpThreads,allThreads,URL,Latency,IdleTime,Connect
1603953984948,23,BeanShell Sampler,200,OK,Thread Group 1-1,text,true,,0,0,1,1,null,0,0,0
1603953984982,13,BeanShell Sampler,200,OK,Thread Group 1-2,text,true,,0,0,2,2,null,0,0,0
1603953985040,7,BeanShell Sampler,200,OK,Thread Group 1-3,text,true,,0,0,3,3,null,0,0,0
1603953985107,15,BeanShell Sampler,200,OK,Thread Group 1-5,text,true,,0,0,5,5,null,0,0,0

可导入到数据库做详细分析。

timestamp1	number	y		
elapsed	number	y		
label2	varchar2(100)	y		
responsecode	varchar2(100)	y		
responsemessage	varchar2(100)	y		
threadname	varchar2(100)	y		
datatype2	varchar2(100)	y		
success	varchar2(100)	y		
failuremessage	varchar2(100)	y		
bytes2	number	y		
sentbytes	number	y		
grpthreads	number	y		
allthreads	number	y		
url2	varchar2(100)	y		
latency	number	y		
idletime	number	y		
connect2	number	y		
remark	varchar2(100)	y		

sqlldr导入参数文件

LOAD DATA
INFILE '102_300hread_500loop_barcodeChange.log'
append
into table jmeter_logtab
FIELDS TERMINATED BY ','  
TRAILING NULLCOLS  
(
timestamp1, 
elapsed, 
label2, 
responsecode, 
responsemessage, 
threadname, 
datatype2, 
success, 
failuremessage, 
bytes2, 
sentbytes, 
grpthreads, 
allthreads, 
url2, 
latency, 
idletime, 
connect2, 
remark constant "102_300hread_500loop_barcodeChange"
)

3.2 日志分析的sql

----主表插入：平均数
select count(*), avg(t.elapsed), min(t.elapsed), max(t.elapsed) --75000
  from jmeter_logtab t
 where t.remark = 'mysql_150thread_500loop_barcodeChange_addConns'
   and t.label2 = 'JDBC01_insert_mian';

----主表插入：响应时长趋势图
select round((t.timestamp1 -
             (select min(t1.timestamp1)
                 from jmeter_logtab t1
                where t1.remark = 'mysql_150thread_500loop_barcodeChange_addConns'
                  and t1.label2 = 'JDBC01_insert_mian')) / 1000 / 60,
             2) timestamp,
       t.elapsed
  from jmeter_logtab t
 where t.remark = 'mysql_150thread_500loop_barcodeChange_addConns'
   and t.label2 = 'JDBC01_insert_mian'
   and mod(t.timestamp1, 100) = 0
 order by t.timestamp1;


----主表插入：响应时长 分布
select elapsed,
       cnt,
       round(cnt / 75000 * 100, 2) pct,
       sum(cnt) over(order by a.elapsed) cal,
       round((sum(cnt) over(order by a.elapsed)) / 75000 * 100, 2) cal_pct
  from (select round(t.elapsed / 2) elapsed, count(*) cnt
          from jmeter_logtab t
         where t.remark = 'mysql_150thread_500loop_barcodeChange_addConns'
           and t.label2 = 'JDBC01_insert_mian'
         group by round(t.elapsed / 2)) a;