之前遇到过一个mysql线上故障,ubunt20,机器内存使用率99%(机器只有几十兆可用内存),load值100+,几乎所有命令都是卡死状态,最终应用侧停掉所有访问后,系统性能有所缓解,升级机器配置后,暂时解决问题。
一直没有找到load值打到100多的根因,怀疑是内存引起的,尝试复现。
测试环境:2c1G机器 ubuntu20操作系统。利用redis写入数据,把内存打到99%
查看内存剩余情况,只有几十兆的可用空间,现在机器已经卡顿了。
root@ip-172-31-30-45:~# free -m
total used free shared buff/cache available
Mem: 943 855 53 0 34 8
Swap: 0 0 0
通过 top 持续观察,load值一直在往上升,同时有iowait,kswapd0 进程偶尔会把CPU打满。
top - 18:16:36 up 21 days, 7:22, 4 users, load average: 10.03, 6.14, 5.14
Tasks: 136 total, 5 running, 131 sleeping, 0 stopped, 0 zombie
%Cpu0 : 0.3 us, 86.7 sy, 0.0 ni, 0.0 id, 13.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 0.0 us, 65.4 sy, 0.0 ni, 0.0 id, 34.6 wa, 0.0 hi, 0.0 si, 0.0 st
MiB Mem : 943.8 total, 53.9 free, 855.4 used, 34.5 buff/cache
MiB Swap: 0.0 total, 0.0 free, 0.0 used. 9.4 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
91 root 20 0 0 0 0 R 64.1 0.0 65:22.01 kswapd0
122612 root 20 0 873472 15252 0 S 21.4 1.6 0:25.48 snapd
920 root 20 0 1395760 14320 0 S 10.4 1.5 19:34.52 ssm-agent-worke
448 root 20 0 1308796 7160 0 S 9.5 0.7 7:40.52 amazon-ssm-agen
122724 root 20 0 26352 12144 2232 R 1.5 1.3 0:02.41 python3
458 root 20 0 1418784 13264 0 S 1.1 1.4 12:40.74d
122737 root 20 0 758980 652596 476 R 1.1 67.5 0:01.46 redis-server
94147 root 0 -20 0 0 0 R 0.9 0.0 0:13.97 loop3
297 root 0 -20 0 0 0 D 0.6 0.0 0:32.70 loop6
13 root 20 0 0 0 0 I 0.2 0.0 0:23.22 rcu_sched
611 root 20 0 27360 14144 1388 S 0.2 1.5 1:30.46 python
122482 ubuntu 20 0 13688 2928 1468 S 0.2 0.3 0:01.74 sshd
122715 root 20 0 11024 2556 1824 R 0.2 0.3 0:01.50 top
1 root 20 0 168744 6396 2008 S 0.0 0.7 0:56.16 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.09 kthreadd
3 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_gp
4 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_par_gp
6 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/0:0H-events_highpri
9 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 mm_percpu_wq
10 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_tasks_rude_
11 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_tasks_trace
12 root 20 0 0 0 0 S 0.0 0.0 0:02.09 ksoftirqd/0
14 root rt 0 0 0 0 S 0.0 0.0 0:07.44 migration/0
15 root -51 0 0 0 0 S 0.0 0.0 0:00.00 idle_inject/0
16 root 20 0 0 0 0 S 0.0 0.0 0:00.00 cpuhp/0
17 root 20 0 0 0 0 S 0.0 0.0 0:00.10 cpuhp/1
18 root -51 0 0 0 0 S 0.0 0.0 0:00.00 idle_inject/1
19 root rt 0 0 0 0 S 0.0 0.0 0:05.67 migration/1
20 root 20 0 0 0 0 S 0.0 0.0 0:02.64 ksoftirqd/1
22 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/1:0H-events_highpri
执行iostat -xd 1 命令,查看磁盘运行情况,发现在大量读情况。
root@ip-172-31-30-45:~# iostat -xd 1
Device r/s rkB/s rrqm/s %rrqm r_await rareq-sz w/s wkB/s wrqm/s %wrqm w_await wareq-sz d/s dkB/s drqm/s %drqm d_await dareq-sz aqu-sz %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 0.00 0.00 0.00 0.00 0.00
loop1 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 0.00 0.00 0.00 0.00 0.00
loop10 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 0.00 0.00 0.00 0.00 0.00
loop2 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 0.00 0.00 0.00 0.00 0.00
loop3 51.23 2404.93 0.00 0.00 21.46 46.94 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 1.10 121.58
loop4 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 0.00 0.00 0.00 0.00 0.00
loop5 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 0.00 0.00 0.00 0.00 0.00
loop6 50.25 2270.44 0.00 0.00 22.34 45.19 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 1.12 120.79
loop7 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 0.00 0.00 0.00 0.00 0.00
loop8 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 0.00 0.00 0.00 0.00 0.00
loop9 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 0.00 0.00 0.00 0.00 0.00
nvme0n1 2808.37 167586.21 0.00 0.00 6.54 59.67 2.46 19.70 2.46 50.00 5.60 8.00 0.00 0.00 0.00 0.00 0.00 0.00 18.38 127.88
Device r/s rkB/s rrqm/s %rrqm r_await rareq-sz w/s wkB/s wrqm/s %wrqm w_await wareq-sz d/s dkB/s drqm/s %drqm d_await dareq-sz aqu-sz %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 0.00 0.00 0.00 0.00 0.00
loop1 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 0.00 0.00 0.00 0.00 0.00
loop10 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 0.00 0.00 0.00 0.00 0.00
loop2 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 0.00 0.00 0.00 0.00 0.00
loop3 31.03 1463.55 0.00 0.00 17.14 47.16 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.53 59.51
loop4 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 0.00 0.00 0.00 0.00 0.00
loop5 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 0.00 0.00 0.00 0.00 0.00
loop6 30.54 1309.36 0.00 0.00 16.73 42.87 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.51 60.30
loop7 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 0.00 0.00 0.00 0.00 0.00
loop8 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 0.00 0.00 0.00 0.00 0.00
loop9 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 0.00 0.00 0.00 0.00 0.00
nvme0n1 1546.80 83822.66 204.43 11.67 5.56 54.19 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 8.61 63.84
Device r/s rkB/s rrqm/s %rrqm r_await rareq-sz w/s wkB/s wrqm/s %wrqm w_await wareq-sz d/s dkB/s drqm/s %drqm d_await dareq-sz aqu-sz %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 0.00 0.00 0.00 0.00 0.00
loop1 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 0.00 0.00 0.00 0.00 0.00
loop10 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 0.00 0.00 0.00 0.00 0.00
loop2 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 0.00 0.00 0.00 0.00 0.00
loop3 52.00 2334.00 0.00 0.00 20.96 44.88 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 1.09 123.60
loop4 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 0.00 0.00 0.00 0.00 0.00
loop5 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 0.00 0.00 0.00 0.00 0.00
loop6 47.00 2449.00 0.00 0.00 24.34 52.11 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 1.14 125.60
loop7 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 0.00 0.00 0.00 0.00 0.00
loop8 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 0.00 0.00 0.00 0.00 0.00
loop9 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 0.00 0.00 0.00 0.00 0.00
nvme0n1 2930.00 178904.00 842.00 22.32 7.10 61.06 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 20.81 136.40
使用 iotop 命令想查看有读写的进程,等了半天才出现结果,并没有查看到读写的进程,也可能是太卡了,没有刷新出来。
换个命令,继续看。 pidstat -d 1 查看有读写的进程,发现系统的一些命令和redis都开始有磁盘读情况,这个很诡异。在系统没有负载的情况,很少有线程产生磁盘读,即使产生,也只是少量磁盘读,感觉还和内存有关系。
root@ip-172-31-30-45:/usr/local/redis-5.0.13# pidstat -d 1
Linux 5.11.0-1022-aws (ip-172-31-30-45) 03/18/22 _x86_64_ (2 CPU)
18:18:58 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
18:18:59 0 1 12866.09 0.00 0.00 103 systemd
18:18:59 0 165 12688.70 20.87 0.00 107 systemd-journal
18:18:59 0 297 6313.04 0.00 0.00 96 loop6
18:18:59 0 448 622.61 0.00 0.00 0 amazon-ssm-agen
18:18:59 0 458 27926.96 0.00 0.00 0 d
18:18:59 0 611 11808.70 0.00 0.00 103 python
18:18:59 0 920 1088.70 0.00 0.00 0 ssm-agent-worke
18:18:59 0 94147 7373.91 0.00 0.00 90 loop3
18:18:59 1000 122482 12845.22 0.00 0.00 105 sshd
18:18:59 0 122612 1913.04 0.00 0.00 27 snapd
18:18:59 0 122715 10751.30 0.00 0.00 104 top
18:18:59 0 122737 13947.83 0.00 0.00 105 redis-server
18:18:59 0 122762 13947.83 0.00 0.00 108 iotop
18:18:59 0 122763 737.39 0.00 0.00 13 pidstat
继续分析内存,sar -B 1 查看结果很不正常,网上参考了一些资料,内存一直在换出内存页。
root@ip-172-31-30-45:/usr/local/redis-5.0.13# sar -B 1
Linux 5.11.0-1022-aws (ip-172-31-30-45) 03/18/22 _x86_64_ (2 CPU)
18:20:10 pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s pgscand/s pgsteal/s %vmeff
18:20:11 129587.85 11.21 2624.30 1079.44 33643.93 1253757.01 0.00 65388.79 5.22
18:20:12 133341.05 12.63 2749.47 1143.16 34433.68 1336996.84 0.00 67088.42 5.02
18:20:13 128673.53 11.76 2417.65 1061.76 33025.49 1280571.57 0.00 64507.84 5.04
18:20:14 141319.80 11.88 2768.32 1213.86 36835.64 1448100.00 0.00 72093.07 4.98
18:20:15 137649.06 22.64 2596.23 1129.25 35185.85 1356853.77 0.00 68616.98 5.06
18:20:16 135702.08 0.00 2590.62 1131.25 35068.75 1300878.12 0.00 68475.00 5.26
18:20:17 138187.74 7.55 2639.62 1166.98 35675.47 1432819.81 0.00 69777.36 4.87
18:20:18 127922.22 12.12 2411.11 1064.65 33176.77 1290246.46 0.00 64759.60 5.02
18:20:19 135751.52 12.12 2569.70 1141.41 35144.44 1247659.60 0.00 68553.54 5.49
18:20:20 131892.23 11.65 2494.17 1077.67 34009.71 1267085.44 0.00 66330.10 5.23
18:20:21 136640.20 11.76 2585.29 1127.45 34988.24 1437513.73 0.00 68400.00 4.76
18:20:22 134836.54 92.31 2616.35 1140.38 34822.12 1475377.88 0.00 68105.77 4.62
18:20:23 122284.54 0.00 2323.71 1011.34 31298.97 1391742.27 0.00 61344.33 4.41
18:20:25 144998.10 38.10 2726.67 1200.00 37841.90 1619358.10 0.00 74034.29 4.57
18:20:25 133615.15 12.12 2518.18 1100.00 34266.67 1452670.71 0.00 67173.74 4.62
18:20:27 131804.95 7.92 2507.92 1106.93 34002.97 1384208.91 0.00 66491.09 4.80
18:20:28 133263.73 23.53 2604.90 1142.16 34750.00 1455180.39 0.00 67962.75 4.67
18:20:29 136841.58 11.88 2552.48 1132.67 34965.35 1444651.49 0.00 68576.24 4.75
18:20:30 136734.65 19.80 2629.70 1159.41 35301.98 1537196.04 0.00 69091.09 4.49
18:20:31 131172.55 0.00 2572.55 1114.71 33513.73 1539543.14 0.00 65627.45 4.26
18:20:32 133487.13 27.72 2747.52 1143.56 34372.28 1470575.25 0.00 67312.87 4.58
18:20:33 133665.05 11.65 2673.79 1146.60 34334.95 1540199.03 0.00 67248.54 4.37
18:20:34 126963.64 8.08 2451.52 1067.68 32934.34 1402451.52 0.00 64511.11 4.60
18:20:35 136550.98 23.53 2670.59 1143.14 35300.98 1473324.51 0.00 68982.35 4.68
总结:从sar -B
结果及网上参考的资料看,在内存紧张时,程序并没有把有代码加载到内存中,当需要执行的代码不在内存中时,需要生新读取磁盘加载到内存中,才会有大量的磁盘读出现,以及IO WAIT升高,LOAD值升高估计也是这个问题,许多程序都需要从磁盘中读取代码并加载到内存中。
不过都是个人怀疑,没有一个完全成立的证据。
另外 ubuntu 在内OOM机制上和centos 上差距挺大的,本想在centos7 上复现这个场景,结果centos7 上当内存剩作不多时,瞬间就把redis 进程OOM掉了,不会有卡住的情况。
在ubuntu系统上,系统宁可一直卡住,也不OOM掉内存最大的程序,但也不是不会oom,如果我在已经出现卡顿的场景下,继续往redis写数据,卡10-20分钟最终还是会触发OOM。
参考:
https://www.jianshu.com/p/ea7ed85918achttps://www.jianshu.com/p/f9b8c139c2edhttps://www.its404.com/article/wangquan1992/105036282https://www.learnsteps.com/difference-between-minor-page-faults-vs-major-page-faults/
python-redis脚本
import redis
a='a'*1000000
r=redis.Redis(host='127.0.0.1',port=6379,decode_responses=True)
for x in range(10):
r.lpush('liliil',a)