CVIM ノードで発生したメモリリーク問題についての解析手法を紹介します。
問題
CVIMコンピュートノードで起動していたVMが突然 shutdown したとの報告がありました。
該当のコンピュートノードの nova のログを参照すると問題発生時間帯に、"libvirtError: cannot fork child process: Cannot allocate memory"というERRORを報告していることがわかりました。
2020-XX-XX 07:43:29.772 8 ERROR nova.compute.manager [req-XXXX-XXXX-XXXX - - - - -] Error updating resources for node compute014.: libvirtError: cannot fork child process: Cannot allocate memory
このログは VM を管理する libvirt が子プロセスを fork しようとしたときにメモリを割り当てられないというエラーとなります。
おそらくメモリ不足の状態に陥っていると考えられます。
解析
まずは sar のデータからメモリの状況を確認してみます。sar によるパフォーマンス解析の詳細は以下の記事を参照して下さい。
[CVIM] パフォーマンスデータの確認
https://community.cisco.com/t5/-/-/ta-p/4277280
/var/log/sa の sar のデータから該当日時のメモリに関するデータを参照してみます。
12:00:01 AM kbswpfree kbswpused %swpused kbswpcad %swpcad
12:10:02 AM 182012 1915136 91.32 41204 2.15
12:20:01 AM 182268 1914880 91.31 42028 2.19
12:30:01 AM 189436 1907712 90.97 41888 2.20
12:40:01 AM 189436 1907712 90.97 41888 2.20
12:50:01 AM 189436 1907712 90.97 41888 2.20
01:00:01 AM 189436 1907712 90.97 41888 2.20
01:10:01 AM 189436 1907712 90.97 41916 2.20
01:20:01 AM 189436 1907712 90.97 41916 2.20
01:30:01 AM 189436 1907712 90.97 41916 2.20
01:40:01 AM 189436 1907712 90.97 41916 2.20
01:50:02 AM 189436 1907712 90.97 41968 2.20
02:00:01 AM 189436 1907712 90.97 41964 2.20
02:10:01 AM 211964 1885184 89.89 41932 2.22
02:20:01 AM 105448 1991700 94.97 52184 2.62
02:30:01 AM 105448 1991700 94.97 52184 2.62
02:40:02 AM 105448 1991700 94.97 52232 2.62
02:50:01 AM 106728 1990420 94.91 54156 2.72
03:00:01 AM 106728 1990420 94.91 54216 2.72
03:10:01 AM 4 2097144 100.00 53260 2.54
03:20:02 AM 8 2097140 100.00 53256 2.54
03:30:01 AM 8 2097140 100.00 53256 2.54
03:40:01 AM 40 2097108 100.00 53316 2.54
03:50:01 AM 44 2097104 100.00 53312 2.54
04:00:01 AM 48 2097100 100.00 53340 2.54
04:10:01 AM 48 2097100 100.00 53436 2.55
04:20:02 AM 60 2097088 100.00 53456 2.55
04:30:01 AM 84 2097064 100.00 53592 2.56
04:40:01 AM 96 2097052 100.00 53644 2.56
04:50:01 AM 104 2097044 100.00 53668 2.56
SWAP領域がほぼ100%使用されてます。メモリが逼迫している状況で間違いないはずです。
まずはプロセスのメモリ使用率を調べてみます。
プロセスのメモリ使用率を調べるには複数のツールがありますが、今回は ps aux コマンドを使います。
# ps aux|head
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1 0.0 0.0 194776 7932 ? Ss Jun15 7:43 /usr/lib/systemd/systemd --switched-root --system --deserialize 22
root 2 0.0 0.0 0 0 ? S Jun15 0:08 [kthreadd]
root 3 0.0 0.0 0 0 ? S Jun15 1:03 [ksoftirqd/0]
root 5 0.0 0.0 0 0 ? S< Jun15 0:00 [kworker/0:0H]
root 8 0.0 0.0 0 0 ? S Jun15 0:18 [migration/0]
root 9 0.0 0.0 0 0 ? S Jun15 0:00 [rcu_bh]
root 10 0.0 0.0 0 0 ? S Jun15 42:40 [rcu_sched]
root 11 0.0 0.0 0 0 ? S< Jun15 0:00 [lru-add-drain]
root 12 0.0 0.0 0 0 ? S Jun15 0:00 [migration/1]
メモリに関する項目の説明は以下となります。
%MEM プロセスが実メモリで占める占有率
RSS 実際に使用しているメモリ使用量（キロバイト単位）
VSZ 仮想メモリも含めたメモリ使用量（キロバイト単位）
今回はプロセスが使用している実メモリサイズの RSS (Resident Set Size) に注目してみます。
RSS を一番多く使っているプロセスを sort コマンドで表示します。
[root@compute014 ~]# ps aux|sort -nrk6|head -1
root 26122 3.1 58.8 234572836 232303408 ? Ssl 2019 11223:37 /usr/sbin/rsyslogd -n
rsyslogd プロセスが 232303408 KB （およそ232GB）使用しており、全体のメモリの58.8%をこの一つのプロセスのみで消費しています。
このマシンのメモリ搭載量は400GBですので、これは明らかに異常な状態です。
rsyslog は Service として設定されています。Service の状態をみてみます。
[root@compute014 ~]# systemctl status rsyslog
● rsyslog.service - System Logging Service
Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled; vendor preset: enabled)
Active: active (running) since Fri 2019-09-13 00:45:08 JST; 8 months 6 days ago
Docs: man:rsyslogd(8)
http://www.rsyslog.com/doc/
Main PID: 26122 (rsyslogd)
CGroup: /system.slice/rsyslog.service
└─26122 /usr/sbin/rsyslogd -n
May 19 17:55:14 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:16 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:18 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:19 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:22 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:23 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:25 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:27 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:28 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
May 19 17:55:30 compute014 rsyslogd[26122]: imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': Pe...2013 ]
Hint: Some lines were ellipsized, use -l to show in full.
imjournal: fopen() failed for path: '/var/lib/rsyslog/imjournal.state.tmp': というログをひたすら繰り返しているようです。
/var/log/messages から何回このログが発生しているか確認してみます。
[root@compute014 nova]# grep "fopen() failed for path:" /var/log/messages|wc -l
342365
数日の間に 34万回以上繰り返しています。
この時点で以下の典型的なメモリリークのシナリオが疑われます。
- rsyslog が/var/lib/rsyslog/imjournal.state.tmp に対して fopen() の system call の発行する
- fopen() が失敗する
- rsyslog は fopen() 発行時にメモリを確保しているが、fopen() の失敗時にはそのメモリを free していない
- rsylog が大量にこの動作を繰り返すことにより、fopen()発行時のメモリが開放されずにどんどんリークしていく
/var/log/messages にはSELinux関連のエラーも大量に出ていました。問題の /var/lib/rsyslog/imjournal.state.tmp の SELinux file context を確認してみます。
[root@compute014 log]# ls -lZ /var/lib/rsyslog/*
-rw-------. root root system_u:object_r:syslogd_var_lib_t:s0 /var/lib/rsyslog/imjournal.state
-rw-------. root root system_u:object_r:unlabeled_t:s0 /var/lib/rsyslog/imjournal.state.tmp
本来であればこのファイルは syslogd_var_lib_t の context を設定してないといけませんが、unlabeled_t という不正な context が設定されています。
このため、rsyslogd のプロセスは、このファイルにアクセスできずに fopen() が失敗していると思われます。
ファイルの作成日時をみてみると、ちょうどOSが再起動したタイミングと一致します。
unlabeled_t の context は SELinux が有効になってない状態でファイルが作成された際に設定される context となります。
システムブート時の僅かなタイミングで不正なファイルが作成されたと考えられます。
つまりこの問題は以下の2つの問題の複合問題となります。
- システムブート時に不正な SELinux file context が設定された
- rsyslogd がそのファイルに対して繰り返し fopen() でアクセスし続け、その度にメモリリークが発生し、結果としてrsyslogd が大量のメモリを保持することになった
修正
対処方法としては以下となります。
- /var/lib/rsyslog/imjournal.state.tmp を削除、もしくは以下のコマンドで正しい context を設定する
# chcon -t syslogd_var_lib_t /var/lib/rsyslog/imjournal.state.tmp
- メモリを開放するために rsyslogd プロセスを再起動する
# systemctl restart rsyslog
本事象は以下で登録されております。
rsyslogd produces errors and consumes high amount of RAM
https://access.redhat.com/solutions/3523571
