软件性能测试（连载14）
5）案例
案例3-13：狂打日志造成的性能下降
# top
top - 09:29:06 up 3 day, 1:39, 4users, load average: 2.48, 1.12, 0.47
Tasks: 130 total, 2 running, 74 sleeping, 0 stopped, 0 zombie
%Cpu0 : 0.7 us, 6.5sy, 0.0 ni, 0.7 id, 93.8 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 8169308 total, 747684 free, 741336 used, 6680288 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 7113124 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
16520 jerry 20 0 656108 355740 5236 R 7.2 4.4 0:12.56 python3
…由于内核CPU为sy 6.5%并不是很高，而等待I/O的CPU时间为93.8%是比较高的，另外在进程信息中心可以看到Python3的进程CPU占有率为7.2%，也是比较高的，它的PID为16520。可以定位在I/O上出现了瓶颈，可能是Python3引起的。于是用iostat来分析。
# iostat -x -d 1
Device r/s w/s rkB/s wkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-szrareq-sz wareq-sz svctm %util
loop0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.000.00 0.00 0.00 0.00 0.00 0.00
sda 0.00 67.00 0.00 32768.00 0.00 0.00 0.00 0.00 0.00 9320.58 1236.57 0.00 512.00 15.50 99.18可以看到磁盘sda的I/O使用率已经高达99.18%，已经接近了I/O的饱和状态。每秒写磁盘请求数是67.00，写数据大小是32768.00（32 MB），写请求的响应时间为（9320.58 ms），也就是9s，而请求队列长度则达到了1236.57。进一步确认了性能瓶颈在I/O。接下来用pidstat来分析。
# pidstat -d 1
Linux 4.15.0-66-generic (ubuntu) 12/10/2019_x86_64_(4 CPU)
09:30:06 AM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
09:30:07 AM 0 759 11.21 0.00 0.00 0 polkitd
09:30:07 AM 0 16520 0.00 58100.00 0.00 96 python3
09:30:07 AM 1000 2044 1465.42 0.00 0.00 0 gnome-shell
…可以发现PID为16520的Python3进程正以58100.00 kB/s的速度往系统中写数据。使用strace -p <PID>查询这个进程的详情。
# strace -p 116520
strace: Process 16520 attached
...
mmap(NULL, 419430458, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x8d5a96754ab0
mmap(NULL, 419430458, PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x8d5a8583a5de
write(5, "2019-12-05 09:30:08,709 - __main"..., 419430458 ) = 419430458
munmap(0x8d5a8583a5de, 419430458) = 0
write(5, "\n", 1) = 1
munmap(0x8d5a8583b5de, 419430458) = 0
close(3) = 0
stat("/tmp/mylog.txt.3",{st_mode=S_IFREG|0644, st_size=96384178, ...}) = 0
…进程向文件描述符编号为5号的文件中，写入了400MB的数据，该5号文件为： /tmp/logtest.txt.3。
lsof -p 116520
…
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODENAME
python3 3785jerry cwd DIR 8,1 4096 554601 /home/ebusiness
…
python3 3785 jerry 5w REG 8,1 117944320 303 /tmp/mylog.txt.3这里的5W表示5号文件以写的形式打开。这样就可以分析Python文件来定位问题了。
案例3-14：数据库没有建立有效的索引造成的性能下降
# top
top - 22:06:25 up 9:22, 1 user, load average: 4.94, 2.05, 1.09
Tasks: 316 total, 1 running, 236 sleeping, 0stopped, 0 zombie
%Cpu0 : 0.7 us, 1.3 sy, 0.0 ni, 35.9 id, 74.4 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 0.3 us, 0.7 sy, 0.0 ni, 73.7 id, 20.8 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 4312648 total, 161796 free, 1820392 used, 2330460 buff/cache
KiB Swap: 969960 total, 963816 free, 6144 used. 2182356 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
7458 jerry 20 0 833852 57968 13176S 1.7 0.7 0:12.40 mysqld
3785 jerry 20 0 6171324 100048 10624 S 103.6 2.3 45:11.62 python3
1915 jerry 20 0 469516 71432 26120 S 24.1 1.7 3:30.36 Xorg
…CPU0和CPU1的等待I/O的CPU时间分别为74.4%和20.8%，是比较高的。同样用iostat分析。
iostat -d -x 1
Device r/s w/s rkB/s wkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util
sda 273.00 0.00 43963.00 0.00 0.00 0.00 0.00 0.00 7.90 0.00 1.16 119.30 0.00 3.56 97.20磁盘sda的I/O使用率高达97.20%。每秒读磁盘请求数是273.00，读数据的大小是43963.00。再利用pidstat分析。
#pidstat -w 1
22:06:26 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
22:06:26 999 27458 43963.00 0.00 0.00 0 mysqld
22:06:26 0 27617 4.00 4.00 0.00 3 python3
…可以得知数据库mysql读操作造成的性能瓶颈。需要进入数据库内部来分析具体原因。
# mysql
Type 'help;' or '\h' for help. Type '\c' to clearthe current input statement.
mysql> showfull processlist;
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| 15 | root | localhost | sec | Query | 0| init | show fullprocesslist |
| 16 | root | 127.0.0.1:42262| sec | Query | 1| Sending data | select * from website where Name= '3testing' |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
•db。表示数据库的名字。
•Command。
表示SQL类型（Query、Update、Insert、Delete）。
•Time。
表示执行时长。
•State。
表示状态。
•Info。
则包含了完整的SQL语句。
接下来切换到数据库sec中，执行explain命令，分析查询语句。
mysql> use sec
mysql> explain elect * from website where Name='3testing'；
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
| 1 | SIMPLE | website | ALL | NULL | NULL | NULL | NULL | 15000 | Using where |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
1 row in set (0.00 sec)从而发现type为ALL，即全表查询，即没有建立索引且牵扯到15000个记录，这里各项含义为。
•select_type。
表示查询类型，SIMPLE表示此查询不包括UNION查询或者子查询。
•table。
表示数据表的名字。
•type。
表示查询类型， ALL表示全表查询，索引查询为index类型。
•possible_keys。
表示可能选用的索引，这里NULL表示没有索引。
•key。
表示索引关键字。
•rows。
表示查询扫描的行数。
本文参与 腾讯云自媒体分享计划，分享自微信公众号。
原始发表：2020-02-28，如有侵权请联系 cloudcommunity@tencent.com 删除
评论
登录后参与评论
推荐阅读