一个ab压测排查系统瓶颈的例子

时间 2019-12-04

标签一个排查系统瓶颈例子繁體版

原文原文链接

ab添加 Cookie 参数

-Cjava

ab -C cookie1_name=cookie1_value -C cookie2_name=cookie2_value ....

或者能够用 -H 参数实现mysql

ab -H "Cookie: cookie1_name=cookie1_value; cookie2_name=cookie2_value"

POST

ab -c 100 -n 1000 -p "loginData.txt" -T "application/x-www-form-urlencoded" "http://domainName/app/login"

ab测试命令

C:\Users\lenovo\Desktop\ab> ab -n 4000 -c 4000 -p "post.txt" http://192.168.238.58/app/info/getInfoDetail?Id=360270316a0960c4e05012ac24072db3 >> getInfoDetail.txt

查看服务器状态

[root@appserver ~]# top
top - 17:57:50 up 53 days,  4:05,  6 users,  load average: 1.52, 0.40, 0.14
Tasks: 138 total,   1 running, 137 sleeping,   0 stopped,   0 zombie
Cpu0  : 14.0%us,  3.7%sy,  0.0%ni, 78.7%id,  3.0%wa,  0.0%hi,  0.7%si,  0.0%st
Cpu1  : 12.6%us,  2.7%sy,  0.0%ni,  6.3%id, 77.7%wa,  0.0%hi,  0.7%si,  0.0%st
Mem:   2056880k total,  2041824k used,    15056k free,   136564k buffers
Swap:  4095992k total,      424k used,  4095568k free,   497432k cached

  PID %MEM  VIRT SWAP  RES CODE DATA  SHR nFLT nDRT S  PR  NI %CPU COMMAND
22432 24.5 1328m 836m 492m    4 1.1g  13m   65    0 S  23   0  0.0 java
22363 18.1  815m 450m 364m  22m 763m  12m   55    0 S  15   0  5.3 mysqld
13387 16.4 1522m 1.2g 329m    4 1.3g  14m  137    0 S  25   0 17.6 java
 2082  1.1 28696 6152  22m  172  20m 1732    0    0 S   6 -10  0.0 iscsiuio
 2496  0.9 30276  11m  18m   12  17m  584    0    0 S  15   0  0.0 restorecond
 2748  0.9  240m 223m  17m    4  31m 5732   76    0 S  15   0  0.0 setroubleshootd
13882  0.6 24340  12m  11m 2596 9680 1928    0    0 S  15   0  1.3 nginx
13881  0.5 22608  12m 9696 2596 7948 1936    0    0 S  15   0  0.0 nginx
 6013  0.5  131m 121m 9420    4 6324 2980    0    0 S  16   0  9.6 iotop
 2975  0.3  151m 144m 6592    4 5476 1048    0    0 S  18   0  0.0 hpssd.py
19922  0.3 95420  86m 6540  388 3912 2696    0    0 S  15   0  0.0 sshd
 2861  0.2 31840  26m 4920  248 3296 1716    0    0 S  15   0  0.0 hald
19924  0.2 58056  52m 4104   52 2588 1588    0    0 S  15   0  0.0 sftp-server
 3172  0.2 92320  86m 3860  388  812 3056    0    0 S  15   0  0.0 sshd
 3667  0.2 92320  86m 3856  388  812 3056    0    0 S  15   0  0.0 sshd
 3170  0.2 93112  87m 3852  388 1604 3052    0    0 S  16   0  0.0 sshd
 3615  0.2 92320  86m 3852  388  812 3056    0    0 S  15   0  0.0 sshd
 6019  0.2 90252  84m 3768  388  812 3000    0    0 S  15   0  0.0 sshd

# 分析：
Cpu1的 %id 空闲仅6.3%，说明Cpu1占用很高；另等待输入输出的CPU时间百分比 %wa 的值很高，说明IO等待比较严重，这可能因为磁盘大量做随机访问形成，也有可能磁盘出现瓶颈（块操做）。

 
 
[root@appserver ~]# iotop -o 
Total DISK READ: 0.00 B/s | Total DISK WRITE: 1442.33 K/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
  466 be/3 root        0.00 B/s    0.00 B/s  0.00 % 60.25 % [kjournald]
    5 rt/3 root        0.00 B/s    0.00 B/s  0.00 % 13.64 % [migration/1]
22385 be/4 mysql       0.00 B/s    0.00 B/s  0.00 % 12.67 % mysqld --basedir=/usr/local/mysql --datadir=/~emall.pid --socket=/tmp/mysql.sock --port=3306
23850 be/4 mysql       0.00 B/s  155.93 K/s  0.00 %  6.17 % mysqld --basedir=/usr/local/mysql --datadir=/~emall.pid --socket=/tmp/mysql.sock --port=3306
13450 be/4 mysql       0.00 B/s   77.96 K/s  0.00 %  6.02 % mysqld --basedir=/usr/local/mysql --datadir=/~emall.pid --socket=/tmp/mysql.sock --port=3306
13349 be/4 root        0.00 B/s    0.00 B/s  0.00 %  2.92 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
22382 be/4 mysql       0.00 B/s    0.00 B/s  0.00 %  2.92 % mysqld --basedir=/usr/local/mysql --datadir=/~emall.pid --socket=/tmp/mysql.sock --port=3306
 5913 be/4 root        0.00 B/s    0.00 B/s  0.97 %  1.95 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5851 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5887 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5901 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5911 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5915 be/4 root        0.00 B/s    0.00 B/s  1.95 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5908 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5943 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5866 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5930 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
 5998 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
13335 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.97 % java -Djava.util.logging.config.file=/usr/loc~mp org.apache.catalina.startup.Bootstrap start
12125 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [pdflush]
22386 be/4 mysql       0.00 B/s    0.00 B/s  0.00 %  0.00 % mysqld --basedir=/usr/local/mysql --datadir=/~emall.pid --socket=/tmp/mysql.sock --port=3306
 1230 be/4 mysql       0.00 B/s    0.00 B/s  0.00 %  0.00 % mysqld --basedir=/usr/local/mysql --datadir=/~emall.pid --socket=/tmp/mysql.sock --port=3306
20213 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % nginx: master process nginx
 1081 be/3 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [kedac]

# 分析：
根据io排序能够看出，kjournald占用很高，应该是ext3在狂写数据

[root@appserver src]# vmstat 2
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  2    424  17236 136560 495228    0    0     1     6    0    2  0  0 100  0  0
 0  1    424  16988 136560 495344    0    0     0  1168 1826 13231 13  4 33 49  0
 0  1    424  16244 136560 495456    0    0     0  1260 1304 11291 14  4 32 50  0
 8  1    424  13236 136560 495560    0    0     0  1190 1830 10366 21  5 38 36  0
 0  2    424  17420 136560 495980    0    0     0  1310 1655 12075 21  8 36 35  0
 1  2    424  17420 136560 496120    0    0     0  1318 1462 11666 13  4 43 40  0
 0  2    424  17172 136560 496232    0    0     0  1204 1767 12308 13  4 43 40  0
 0  1    424  16924 136564 496332    0    0     0  1250 1319 12386 14  4 43 40  0
 0  1    424  16676 136564 496440    0    0     0  1188 1834 12372 13  4 43 40  0
 0  1    424  16428 136564 496568    0    0     0  1188 1619 12459 12  4 34 50  0
 0  1    424  16180 136564 496712    0    0     0  1312 1541 11072 12  4 33 50  0
 0  1    424  16056 136564 496820    0    0     0  1180 1843 12342 14  4 41 40  0
 5  2    424  15808 136564 496924    0    0     0  1188 1327 11523 11  4 44 40  0
 0  1    424  15552 136564 497036    0    0     0  1196 1873 11847 14  4 41 41  0
 0  1    424  15304 136564 497164    0    0     0  1150 1298 12873 15  4 43 39  0
 0  1    424  15180 136564 497308    0    0     0  1246 1893 12078 13  4 43 40  0
 1  1    424  15180 136564 497432    0    0     0  1182 1754 11549 12  4 39 45  0
 0  1    424  14932 136568 497516    0    0     0  1242 1465 11814 12  3 44 41  0
 0  1    424  14932 136572 497644    0    0     0  1218 1870 13324 15  4 39 42  0
 2  1    424  14684 136576 497748    0    0     0  1238 1316 11377 12  4 44 41  0
 0  1    424  12592 136576 498052    0    0     0  1290 2695 13277 15  5 42 39  0

# 分析：
procs（进程）的b列表示等待IO的进程数量
io的bo列（每秒写入的块数）较高（超出1024k），能够看到CPU在IO等待的值也会越大
cpu的wa（IO等待时间百分比）比较高，说明IO等待比较严重


[root@appserver ~]# iostat -x 2
Linux 2.6.18-308.el5 (appserver)    01/25/2017

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          14.21    0.00    4.24   38.40    0.00   43.14

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
cciss/c0d0        0.00   139.00  0.00 170.50     0.00  2468.00    14.48     1.31    7.65   5.58  95.20
cciss/c0d0p1      0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
cciss/c0d0p2      0.00   139.00  0.00 170.50     0.00  2468.00    14.48     1.31    7.65   5.58  95.20
dm-0              0.00     0.00  0.00 309.50     0.00  2476.00     8.00     2.53    8.11   3.08  95.20
dm-1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          15.54    0.00    4.26   39.35    0.00   40.85

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
cciss/c0d0        0.00   116.50  0.00 171.00     0.00  2308.00    13.50     1.18    6.92   5.57  95.25
cciss/c0d0p1      0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
cciss/c0d0p2      0.00   116.50  0.00 171.00     0.00  2308.00    13.50     1.18    6.92   5.57  95.25
dm-0              0.00     0.00  0.00 288.50     0.00  2308.00     8.00     2.15    7.50   3.31  95.35
dm-1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          13.72    0.00    4.74   39.40    0.00   42.14

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
cciss/c0d0        0.00   119.50  0.00 178.00     0.00  2392.00    13.44     1.18    6.62   5.36  95.35
cciss/c0d0p1      0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
cciss/c0d0p2      0.00   119.50  0.00 178.00     0.00  2392.00    13.44     1.18    6.62   5.36  95.35
dm-0              0.00     0.00  0.00 296.50     0.00  2372.00     8.00     2.13    7.21   3.21  95.30
dm-1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

# 分析：
%util（一秒中I/O 操做的利用率）已经接近100%，能够看出目前这台服务器的IO已经到达瓶颈了。

登陆后取得cookie，测接口：

ab -n 1000 -c 1000 -H "Cookie:JSESSIONID=8B3E561233C3451206456CFB86DFA46E" -p "postfile" http://app.tomcatalina.com/app/mark/getMark

结果解释：

Document Path: /app/mark/getMark
#测试的页面
Document Length: 50797 bytes
#页面大小

Concurrency Level: 1000
#测试的并发数
Time taken for tests: 11.846 seconds
#整个测试持续的时间
Complete requests: 1000
#完成的请求数量
Failed requests: 0
#失败的请求数量
Write errors: 0
Total transferred: 204586997 bytes
#整个过程当中的网络传输量
HTML transferred: 203479961 bytes
#整个过程当中的HTML内容传输量
Requests per second: 337.67 [#/sec] (mean)
#最重要的指标之一，至关于LR中的每秒事务数，后面括号中的mean表示这是一个平均值
Time per request: 2961.449 [ms] (mean)
#最重要的指标之二，至关于LR中的平均事务响应时间，后面括号中的mean表示这是一个平均值
Time per request: 2.961 [ms] (mean, across all concurrent requests)
#每一个链接请求实际运行时间的平均值
Transfer rate: 16866.07 [Kbytes/sec] received
#平均每秒网络上的流量，能够帮助排除是否存在网络流量过大致使响应时间延长的问题
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 483 1773.5 11 9052
Processing: 2 556 1459.1 255 11763
Waiting: 1 515 1459.8 220 11756
Total: 139 1039 2296.6 275 11843
#网络上消耗的时间的分解，各项数据的具体算法还不是很清楚

Percentage of the requests served within a certain time (ms)
50% 275
66% 298
75% 328
80% 373
90% 3260
95% 9075
98% 9267
99% 11713
100% 11843 (longest request)
#整个场景中全部请求的响应状况。在场景中每一个请求都有一个响应时间，其中50％的用户响应时间小于275毫秒，66％的用户响应时间小于298毫秒，最大的响应时间小于11843毫秒。对于并发请求，cpu实际上并非同时处理的，而是按照每一个请求得到的时间片逐个轮转处理的，因此基本上第一个Time per request时间约等于第二个Time per request时间乘以并发请求数。