BIGLOBE鈴木(研)です。
今回は、VMwareの仮想基盤を運用していて、アラーム対応をすることがありますが、その後同じアラームがなるべく出ないように対応するといった改善活動を行った話を紹介いたします。
■事の発端は休日の運用チームからの電話から
ある日、運用チームから休日に電話連絡を受けました。vCenterのディスク使用率が90%を超えたとのことでした。特に、ディスク使用量が急激に増えている場合は、すぐに使用率100%になってしまう場合があり、とても急ぎで対応が求められるので、すぐにサーバにログインしてdfコマンドを実行してみました。
vCenterのサーバ名:~ # df -h Filesystem Size Used Avail Use% Mounted on /dev/sda3 11G 6.5G 3.7G 64% / udev 7.9G 168K 7.9G 1% /dev tmpfs 7.9G 40K 7.9G 1% /dev/shm /dev/sda1 128M 39M 83M 32% /boot /dev/mapper/core_vg-core 50G 281M 47G 1% /storage/core /dev/mapper/log_vg-log 9.9G 8.5G 950M 91% /storage/log /dev/mapper/db_vg-db 9.9G 465M 8.9G 5% /storage/db /dev/mapper/dblog_vg-dblog 5.0G 331M 4.4G 7% /storage/dblog /dev/mapper/seat_vg-seat 25G 2.7G 21G 12% /storage/seat /dev/mapper/netdump_vg-netdump 1001M 18M 932M 2% /storage/netdump /dev/mapper/autodeploy_vg-autodeploy 9.9G 151M 9.2G 2% /storage/autodeploy /dev/mapper/invsvc_vg-invsvc 9.9G 384M 9.0G 5% /storage/invsvc
確かに、/storage/log が91%になってました。何回かdfコマンドを実行してみて、/storage/logの使用量の増え方が急激ではないことを確認できたため、緊急性は下がりました。
■「何が原因か？」調べてみた
どのファイルが肥大化しているのか、duコマンドで調べてみました。
vCenterのサーバ名:~ # cd /storage/log vCenterのサーバ名:/storage/log # du -sh * 16K lost+found 4.0K remote 8.3G vmware
まずは、vmware配下で9.9GBのパーティションのうち、8.3GB使っていることが分かりました。 /storage/log/vmwareでどのディレクトリ/ファイルが肥大化しているのか、さらにduコマンドで調べてみました。
vCenterのサーバ名:/storage/log # cd vmware vCenterのサーバ名:/storage/log/vmware # vCenterのサーバ名:/storage/log/vmware # du -sm * 6 applmgmt 3346 cloudvm 149 cm 4 dnsmasq.log 1 dnsmasq.log.1.bz2 1 dnsmasq.log.2.bz2 1 dnsmasq.log.3.bz2 1 dnsmasq.log.4.bz2 1 dnsmasq.log.5.bz2 120 eam 57 iiad 40 invsvc 0 journal 1 mbcs 1 netdumper 65 perfcharts 1 rbd 44 rhttpproxy 1 rsyslogd 521 sca 10 syslog 168 vapi 1 vapi-endpoint 1 vctop 1823 vdcs 1 vmafd 514 vmafdd 1 vmdir 78 vmware-sps 1 vpostgres 1060 vpxd 13 vsan-health 13 vsm 215 vsphere-client 1 vws 223 workflow
cloudvmというディレクトリ配下が怪しいことが分かり、更に掘ってみました。
vCenterのサーバ名:/storage/log/vmware # cd cloudvm vCenterのサーバ名:/storage/log/vmware/cloudvm # du -sm * 1 cloudvm-ram-size-output 1 cloudvm-ram-size-output-20200704.bz2 1 cloudvm-ram-size-output-20200705.bz2 1 cloudvm-ram-size-output-20200706.bz2 1 cloudvm-ram-size-output-20200707.bz2 1 cloudvm-ram-size-output-20200708.bz2 1 cloudvm-ram-size-output-20200709.bz2 1 cloudvm-ram-size-output-20200710.bz2 3308 cloudvm-ram-size.log 1 install-parameter.log 0 service-config.log 37 service-control.log
cloudvm-ram-size.log が1つのファイルで3.3GBも使っていることが分かりました。
このファイルは、テキストファイルでした。
vCenterのサーバ名:/storage/log/vmware/cloudvm # file cloudvm-ram-size.log cloudvm-ram-size.log: ASCII text
このcloudvm-ram-size.logというファイルが何者かを調べてみようと思い、Google先生に聞いてみることにしました。
©2018 Google LLC
※ GoogleおよびGoogleのロゴは、Google LLC の商標です。
すると、すぐに下記KBにたどり着きました。
どうも、cloudvm-ram-size.log のログローテーションをしていない不具合に当たったようです。
■障害対応作業の実施
KBの内容に従い、下記対処を実施しました。
- /etc/logrotate.d/cloudvm_ram_size.logを下記内容で作成
/storage/log/vmware/cloudvm/cloudvm-ram-size.log{
missingok
notifempty
compress
size 20k
monthly
create 0660 root cis
}
- logrotate -f /etc/logrotate.conf
logroteteコマンドを実行した後、/etc/logrotate.d/cloudvm-ram-size.logファイルの中にcompressというキーワードがあることを思い出しました。
案の定、bzip2コマンドが動いていました。
top - 17:53:11 up 582 days, 18:14, 2 users, load average: 2.20, 2.53, 2.05
Tasks: 199 total, 2 running, 197 sleeping, 0 stopped, 0 zombie
Cpu(s): 3.7%us, 3.1%sy, 12.4%ni, 80.6%id, 0.1%wa, 0.0%hi, 0.1%si, 0.0%st
Mem: 16081M total, 15915M used, 166M free, 899M buffers
Swap: 26619M total, 1802M used, 24817M free, 9124M cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4761 root 20 0 13444 6920 460 R 98 0.0 5:33.22 bzip2
22744 root 30 10 834m 86m 12m S 10 0.5 0:10.76 vmware-vws
5704 root 20 0 24588 1044 596 S 2 0.0 3771:01 cgrulesengd
7802 vpostgre 20 0 769m 36m 35m S 2 0.2 21:31.12 postgres
8964 root 20 0 1952m 576m 56m S 2 3.6 22318:48 vpxd
10052 vdcs 20 0 1371m 338m 13m S 2 2.1 5369:51 vmware-vdcs
24490 root 20 0 17136 1352 940 R 2 0.0 0:00.01 top
1 root 20 0 10556 668 636 S 0 0.0 7:34.45 init
・・・
ここで2つの心配をしました。
CPU高負荷でvCenterの動作不具合が起きないか？
圧縮しているせいで、/storage/logの使用率が100%にならないか？
このvCenterは、休日はほとんど何も処理しない業務のVMしか載せていないし、vSphereAPIでシステム連携とかもないから大丈夫であることはわかってはいたので、とりあえずは一安心することにしました。
結果としては、20分ほどかかって処理は無事完了しました。使用率の下記のとおり57%まで下がりました。この時点で運用チームに連絡し、アラームが解消していることを確認してもらい、対応完了としました。
vCenterのサーバ名:/storage/log/vmware/cloudvm # df -h Filesystem Size Used Avail Use% Mounted on /dev/sda3 11G 6.4G 3.8G 63% / udev 7.9G 168K 7.9G 1% /dev tmpfs 7.9G 40K 7.9G 1% /dev/shm /dev/sda1 128M 39M 83M 32% /boot /dev/mapper/core_vg-core 50G 281M 47G 1% /storage/core /dev/mapper/log_vg-log 9.9G 5.3G 4.1G 57% /storage/log /dev/mapper/db_vg-db 9.9G 465M 8.9G 5% /storage/db /dev/mapper/dblog_vg-dblog 5.0G 331M 4.4G 7% /storage/dblog /dev/mapper/seat_vg-seat 25G 2.7G 21G 12% /storage/seat /dev/mapper/netdump_vg-netdump 1001M 18M 932M 2% /storage/netdump /dev/mapper/autodeploy_vg-autodeploy 9.9G 151M 9.2G 2% /storage/autodeploy /dev/mapper/invsvc_vg-invsvc 9.9G 378M 9.0G 4% /storage/invsvc
処理完了後のファイルサイズはこのようになっておりました。
vCenterのサーバ名:/storage/log/vmware/cloudvm # ls -l total 118516 -rw------- 1 root root 7336 Jul 5 23:30 cloudvm-ram-size-output-20200705.bz2 -rw------- 1 root root 7094 Jul 6 23:30 cloudvm-ram-size-output-20200706.bz2 -rw------- 1 root root 7119 Jul 7 23:30 cloudvm-ram-size-output-20200707.bz2 -rw------- 1 root root 7116 Jul 8 23:30 cloudvm-ram-size-output-20200708.bz2 -rw------- 1 root root 7093 Jul 9 23:30 cloudvm-ram-size-output-20200709.bz2 -rw------- 1 root root 6929 Jul 10 23:30 cloudvm-ram-size-output-20200710.bz2 -rw------- 1 root root 6255 Jul 11 18:03 cloudvm-ram-size-output-20200711.bz2 -rw-rw---- 1 root cis 30996 Jul 11 18:03 cloudvm-ram-size.log -rw-rw-r-- 1 root cis 82297341 Jul 11 18:03 cloudvm-ram-size.log-20200711.bz2 -rw-r--r-- 1 root root 248396 Jul 11 06:00 install-parameter.log -rw-r--r-- 1 root root 0 Feb 9 2016 service-config.log -rw------- 1 root root 38581654 Dec 18 2018 service-control.log
3GB越えのファイルが、80MB程度バイトに圧縮されました。
圧縮対象のファイルがテキストファイルであったので、圧縮率が非常に高かったため、パーティションの空き容量が少ない中で、無事処理が完了したと思います。
もし、compressを付けなかったら、私の障害対応作業で/storage/log の使用率は100%になっていただろうと思います。
■まとめ
何年か運用して、じわじわとcloudvm-ram-size.logのサイズが肥大化していき、やっと/storage/logの使用率がアラーム閾値を超えて気づくという、いわゆる不発弾の発見といえるでしょう。こういったものは、製品検証時では見つからないものです。
今回は、運用チームからのアラームコールを対応し、VMware社のKBにすぐたどり着いて対応策が決まったのはラッキーでした。他のvCenterにも後日横展開で同じ対応を実施して改善を図ることが出来ました。
ちゃんと、こういった運用での出来事を横展開で改善していくという活動は大切であることを、実際やってみて認識を新たにしました。こういう活動の積み重ねがインフラの品質を高めるもので、非常に地道ではありますがおろそかにできないことです。
あと、最近はメンバにマシンを触るのを任せっきりで、私自身はあまり触っていない中で、休日に運用チームからアラームコールをもらったので、ドキドキしながらの障害対応作業ではありました。もう少し触って慣れておかないと、いざという時には役に立たないなぁと思いました。普段ちゃんとやってくれているメンバに感謝です。
※ 本記事で記載されている会社名、製品名は、各社の登録商標または商標です。
■お知らせ
VMwareユーザ会（VMUG）に興味のある方は、
https://www.vmug.com/membership/membership-benefits
から入会していただけると幸いです。 部会でお会いできるのを楽しみにしております。
以上です。
