search

tagomoris / fluent-plugin-secure-forward

Other
140 stars 30 forks source link

Memory leak of in_secure_forward? #10

Closed ghost closed 9 years ago

ghost commented 9 years ago

v 0.2.3 により連続稼動試験を行っています。

受信側サーバを監視しているとデータ送信量の増加に従い、メモリ&スワップの使用量が増加します。 その後 残スワップがなくなると以下のようなメッセージが OS のログに出力され、同時に td-agent の プロセスが再起動します。

Nov 1 00:45:07 dev01 kernel: Out of memory: Kill process 29624 (ruby) score 951 or sacrifice child Nov 1 00:45:07 dev01 kernel: Killed process 29624, UID 496, (ruby) total-vm:9549424kB, anon-rss:1542876kB, file-rss:124kB

このとき、/var/log/td-agent/td-agent.log には以下のようなログが出力されています。

2014-11-01 00:45:09 +0900 [info]: process finished code=9 2014-11-01 00:45:09 +0900 [error]: fluentd main process died unexpectedly. restarting. 2014-11-01 00:45:09 +0900 [info]: starting fluentd-0.10.55 2014-11-01 00:45:09 +0900 [info]: reading config file path="/etc/td-agent/td-agent.conf"

127 0 0 1_mem-day

同じ試験を "type forward" により行った場合 (11/01 16:00 ～) はスワップ使用量の変化はありません。

127 0 0 1_mem-day

これらの現象についてお気づきの点がないかご確認ください。

尚、検証時のログなどの記録も採取しておりますが、github では画像以外の形式を添付できない ようですので、必要に応じメールなどで提供させて頂きます。

tagomoris commented 9 years ago

検証時 in_secure_forward を動かしていたfluentd(td-agent)の設定ファイル全体をいただけませんか？ もちろん shared_key などは伏せていただいてで構いません。

ghost commented 9 years ago

送信側、受信側の /etc/td-agent/td-agent.conf は次のようになっています。

送信側

<source> type unix path /var/run/td-agent/td-agent.sock </source>

<source> type forward </source>

<match data._> type secure_forward shared_key _ shared-key ** self_hostname ${hostname} keepalive 10s retry_wait 60s flush_interval 60s buffer_type file buffer_path /data/td-agent/buffer/dev buffer_queue_limit 1280

<server> host \ host1-ip-address port 24285 </server> <server> host \ host2-ip-address port 24285 </server> </match>

受信側

<source> type unix path /var/run/td-agent/td-agent.sock </source>

<source> type forward </source>

<source> type secure_forward port 24285 shared_key \ shared-key ** cert_auto_generate yes self_hostname ${hostname} allow_anonymous_source yes </source>

<match data.*.f001> type file flush_interval 60s buffer_chunk_limit 32m path /data/svr/dev/dat/f001/p01/new/rec time_format %Y-%m-%d %H:%M:%S </match>

<match data.*.f002> type file flush_interval 60s buffer_chunk_limit 32m path /data/svr/dev/dat/f002/p01/new/rec time_format %Y-%m-%d %H:%M:%S </match>

ghost commented 9 years ago

解決のヒントになるかどうかはわかりませんが、念のため報告させて頂きます。

最初の書込み (11/1) 後に 11/3 に同じような試験を行いました。 添付したグラフがそれになりますが、スワップが無くなったことが確認 (11/3 12:30) でき その後、18:00 ごろに定期送信を行うことをやめました。

これにより CPU のグラフは値が低くなっていますが、メモリのグラフにある残スワップ量は 減り続けています。

[CPU] 1-127 0 0 1_cpu-day

[MEMORY] 1-127 0 0 1_mem-day

tagomoris commented 9 years ago

緑色のエリアが実メモリ容量ですか？ 普段実メモリは空きゼロで運用しているということでしょうか。

tagomoris commented 9 years ago

CPUのグラフも、数字が75〜100くらいになっているように見えますが、グラフに書かれている "Load Avelage" という説明は正しいですか？

ghost commented 9 years ago

グラフはサーバ機に設置した mrtg から採取したもので、ご質問頂いた通り 緑色のエリアが実メモリになります。

グラフにあるサーバは試験用のものであるため運用環境とは異なりますが、 実際の運用環境サーバでもメモリは減り続けていきます。

残メモリがなくなったときの影響がわからなかったので、運用サーバでは日次で fluentd を再起動することにより、残メモリ量を回復するようにしています。

CPU グラフも mrtg のものになります。

グラフにある "Load Average" も私が編集したものではなく、ツールが出力しているものに なりますが、top コマンドで出力される Load Average の数値と同等であるため、 /proc/loadavg と一致していると考えて頂いて良いと思います。

ghost commented 9 years ago

念のため、現在の top コマンドの表示状態を以下に転記させて頂きました。

top - 16:43:41 up 7 days, 20 min, 1 user, load average: 0.00, 0.02, 0.00 Tasks: 153 total, 1 running, 152 sleeping, 0 stopped, 0 zombie Cpu(s): 0.3%us, 0.7%sy, 0.0%ni, 99.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 1736176k total, 1707076k used, 29100k free, 5700k buffers Swap: 6291432k total, 1858128k used, 4433304k free, 60532k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 25780 td-agent 20 0 5872m 1.4g 2380 S 0.7 84.9 59:12.97 ruby 13241 appadmin 20 0 15024 1360 1008 R 0.3 0.1 0:00.05 top 1 root 20 0 19228 268 132 S 0.0 0.0 0:01.10 init 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd 3 root RT 0 0 0 0 S 0.0 0.0 0:00.00 migration/0 4 root 20 0 0 0 0 S 0.0 0.0 0:03.73 ksoftirqd/0 5 root RT 0 0 0 0 S 0.0 0.0 0:00.00 migration/0 6 root RT 0 0 0 0 S 0.0 0.0 0:09.73 watchdog/0

tagomoris commented 9 years ago

恐らくと思われる原因を発見したので別途issueを立てました。 #11 また送信側の keepalive を短くすれば状況は軽減されると思います。

keepalive 10s
retry_wait 60s
flush_interval 60s

flush interval 60s なのに keepalive 10s というのは無意味な設定だと思われます(1回送信される前に5回、全く使われずにexpireするSSL sessionがあることになる)。もっと長い時間に設定してはいかがでしょうか。

ghost commented 9 years ago

keepalive についてご案内を頂きありがとうございます。 設定を変更してみます。

tagomoris commented 9 years ago

commit ef55aa4d2867d94b4a7599032f730968bc143cc2 にて修正しました。 @cbh34680g master の HEAD に上げてありますが、これを試すことはできますか？