之前遇到過一個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.74 containerd
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 containerd
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/ea7ed85918ac
https://www.jianshu.com/p/f9b8c139c2ed
https://www.its404.com/article/wangquan1992/105036282
https://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)