From toshinobu.kobayashi ＠ jig-saw.com Thu Jan 14 19:05:23 2016 From: toshinobu.kobayashi ＠ jig-saw.com (=?UTF-8?B?5bCP5p6XIOW5tOS8uA==?=) Date: Thu, 14 Jan 2016 19:05:23 +0900 Subject: [Ultramonkey-l7-users 617] Re: =?utf-8?b?bDd2c2QodmVyIDMuMS4yKeOBjOeqgeeEtuWBnOatouOBlw==?= =?utf-8?b?44G+44GX44Gf?= In-Reply-To: <000e01d14787$165f5ac0$431e1040$@lab.ntt.co.jp> References: <567CE44C.8050205@jig-saw.com> <567D2BCA.6010309@jig-saw.com> <002001d1413e$012deda0$0389c8e0$@lab.ntt.co.jp> <5681087B.9010505@jig-saw.com> <5689CD40.9060801@jig-saw.com> <000e01d14787$165f5ac0$431e1040$@lab.ntt.co.jp> Message-ID: <569772E3.2070306@jig-saw.com> 竹田様 コミュニティの皆様 お世話になっております。 ジグソーの小林と申します。 ＞竹田様 ログの解析等色々とお手数お掛けして申し訳ございません。 私の方でもテストを行っておりまして 気になる点が2点ほどございます。 ?CPU負荷が時々上がる件について -------------------------------- 今回l7vsdが落ちた環境とは違うのですが 同じULML7-3.1.2で負荷試験を行っておりましたところ 負荷をかけ終わって少し時間が経つとCPUの負荷が 上がることが何回かありました。 処理が空いた時にスレッド内で何か後処理的なもの があるのでしょうか。 ?スレッド数とcpu負荷について -------------------------------- 上の件ですが今回負荷試験に使用している ものはcpu * 1、MEM 3GBとスペックはそれほどではないので スレッドプール数も全バーチャルサービスで 800ほどになっています。(スタックサイズは3MBほどに落としています) 只、l7vsdが落ちた機材のようにロードアベレージがたまに 10?20/min なるような形跡はありません。 スレッドプール数とcpu負荷について因果関係はあるのでしょうか。 大変お手数ではございますが、ご教授いただけますと幸いです。 On 2016/01/05 16:02, 竹田健二 wrote: > 小林様 > > 竹田です。 > > 設定ファイルおよびメッセージをお送りいただきありがとうございました。 > >> apacheのアクセスログはセキュリテイ上の理由からご提供できないのですが >> 具体的にこういう情報が必要ということであれば検討させていただきますので >> ご 教授ください。 > 　承知しました。 > 　可能であれば、「--forwarded-for」が設定された仮想サービスに対して > 　事象発生時に送信されたリクエストがわかるような情報（特にHTTPヘッダの中身）を > 　ご提供いただけますと幸いです。 > > それと、こちらも可能であればでよろしいですが > コアファイルをお送りいただけますでしょうか。 > ＃サイズが大きいとの事ですので分割して > ＃私宛に個別にお送りいただければと思います。 > > >> 以前にこちらのMLかチケットで >> スレッド間同士のファイル共有の部分で >> ロックの競合が起きて負荷が高くなることがあると >> 伺った気がします。 >> こちら可能性は考えられますでしょうか。 >> 記憶違いで的外れなことでしたら申し訳ございません。 > 　恐らくですが、今回の件はfind_http_header関数の処理上の問題で、 > 　ロックの競合とは関係はないと思います。 > 　 > > > 以上、よろしくお願いいたします。 > > >> -----Original Message----- >> From: 小林 年伸 [mailto:toshinobu.kobayashi ＠ jig-saw.com] >> Sent: Monday, January 04, 2016 10:39 AM >> To: takeda.kenji ＠ lab.ntt.co.jp; ultramonkey-l7-users ＠ lists.osdn.me >> Subject: Re: [Ultramonkey-l7-users 611] Re: l7vsd(ver 3.1.2)が突然停止しました >> >> 竹田様 >> コミュニティの皆様 >> >> お世話になっております。 >> ジグソーの小林と申します。 >> >> ご質問ばかりで申し訳ございません。 >> >> 以前にこちらのMLかチケットで >> スレッド間同士のファイル共有の部分で >> ロックの競合が起きて負荷が高くなることがあると >> 伺った気がします。 >> こちら可能性は考えられますでしょうか。 >> 記憶違いで的外れなことでしたら申し訳ございません。 >> >> >> お手数ですがご教授いただけますと幸いです。 >> >> >> >> On 2015/12/28 19:01, 小林 年伸 wrote: >>> 竹田様 >>> >>> お世話になっております。 >>> ジグソーの小林と申します。 >>> >>> ご確認と対応方法のご教授ありがとうございます。 >>> --forwarded-for は設定しています。 >>> >>> 設定ファイルは添付させていただきます。 >>> ホスト名、SSLのファイル名などは伏せてあります。 >>> >>> ログはメールに記載でもよろしいでしょうか。 >>> こちらもノード名などは伏せさせていただきました。 >>> 発生は 12/25 12:59頃になります >>> >>> ○l7vsd.log >>> ----------------------------------------------- >>> >>> ----------------------------------------------- >>> l7vsdのメインのログですが出力がありませんでした。 >>> >>> ○l7directord.log >>> ----------------------------------------------- >>> [Fri Dec 25 12:58:55 2015|4771] [INF0006] Exiting with exit status 0: >>> Reached end of `main' >>> [Fri Dec 25 12:59:05 2015|4957] [INF0006] Exiting with exit status 0: >>> Reached end of `main' >>> [Fri Dec 25 12:59:15 2015|5114] [INF0006] Exiting with exit status 0: >>> Reached end of `main' >>> [Fri Dec 25 12:59:25 2015|5277] [INF0006] Exiting with exit status 0: >>> Reached end of `main' >>> [Fri Dec 25 12:59:35 2015|5452] [INF0006] Exiting with exit status 0: >>> Reached end of `main' >>> [Fri Dec 25 12:59:45 2015|5600] [INF0006] Exiting with exit status 0: >>> Reached end of `main' >>> [Fri Dec 25 12:59:56 2015|5748] [INF0006] Exiting with exit status 0: >>> Reached end of `main' >>> [Fri Dec 25 13:00:06 2015|5955] [INF0006] Exiting with exit status 0: >>> Reached end of `main' >>> ----------------------------------------------- >>> バックエンドサーバーは特に問題なかったのでこのようになっています。 >>> >>> ○l7vsadm.log >>> ----------------------------------------------- >>> 2015/12/25 12:59:56 [ERROR] l7vsadm_common ADM43100009 connect() >>> failed: Connection refused. 〓ノード名〓 0x7fc39470b760 l7vsadm.cpp:3105 >>> 2015/12/25 13:00:56 [ERROR] l7vsadm_common ADM43100009 connect() >>> failed: Connection refused. 〓ノード名〓 0x7f22af745760 l7vsadm.cpp:3105 >>> ----------------------------------------------- >>> cronで1分に1回 l7vsadm -V を実行して情報収集してますので >>> l7vsdが停止したことでエラーがでていました、これより以前は出力がありま >>> せん。 >>> >>> ○/var/log/messages >>> ----------------------------------------------- >>> Dec 25 12:59:26 pm_logconv: [1173]: error: detect_rsc_failure(): >>> failed to parse log message. [notice: process_lrm_event: Operation >>> L7vsd_monitor_10000: not running (node=〓ノード名〓, call=24, rc=7, >>> cib-update=3078, confirmed=false)] >>> Dec 25 12:59:26 pm_logconv: [1173]: error: try_to_operate(): failed >>> to parse log message. [info: do_lrm_rsc_op: Performing key=〓Key情報〓 >>> op=L7vsd_stop_0] >>> Dec 25 12:59:26 pm_logconv: [1173]: error: operation_succeeded(): >>> failed to parse log message. [notice: process_lrm_event: Operation >>> L7vsd_stop_0: ok (node=〓ノード名〓, call=166, rc=0, cib-update=3080, >>> confirmed=true)] >>> ----------------------------------------------- >>> 当該時間帯の出力はpacemakerのもののみでした。 >>> >>> ○バックエンドのapacheエラーログ >>> ----------------------------------------------- >>> [Fri Dec 25 12:43:19 2015](32)Broken pipe: core_output_filter: writing >>> data to the network >>> [Fri Dec 25 12:54:16 2015](104)Connection reset by peer: >>> core_output_filter: writing data to the network >>> [Fri Dec 25 12:55:04 2015](104)Connection reset by peer: >>> core_output_filter: writing data to the network >>> ----------------------------------------------- >>> 12時台には上の出力しかありませんでした。何れも「info」レベルです >>> >>> >>> apacheのアクセスログはセキュリテイ上の理由からご提供できないのですが >>> 具体的にこういう情報が必要ということであれば検討させていただきますので >>> ご 教授ください。 >>> >>> >>> お手数でが何卒、よろしくお願いいたします。 >>> >>> >>> On 2015/12/28 16:04, 竹田健二 wrote: >>>> 小林様 >>>> >>>> コミュニティメンバの竹田です。 >>>> >>>> UltraMonkey-L7がダウンしたとのことで >>>> ご迷惑をおかけしております。 >>>> >>>> 以下、ご質問いただいた件についてです。 >>>> >>>>> 既出のもので上のような症状はありましたでしょうか。 >>>> 　私が知る限りではありません。 >>>> >>>>> 又、l7vsdのプロセスでDiskへの書き込みが発生する部分として >>>>> 何が考えられますでしょうか。例えば一時ファイルなど >>>>> もし分かればその部分をtmpfsとしてメモリ空間に持っていくことも >>>>> 検討しております。 >>>> 　l7vsdでディスク書込みが発生する主な箇所は >>>> 　ログ(l7directord.log以外)書込み時となります。 >>>> >>>> 　ただ、これまでにUltraMonkey-L7では性能検証等を実施した際でも >>>> 　ディスク書込み自体が問題になったということは存じておりませんので >>>> 　他の原因である可能性が高いと思います。(後述) >>>> >>>>> #5、protomod_sessionless.so の辺りで何かありましたでしょうか。 >>>> 　メールにてご報告いただいたスタックトレースをみると、 >>>> 　protomod_sessionlessから呼び出されている >>>> 　find_http_header(パケット中から特定のHTTPヘッダを取得する関数)に >>>> 　問題があるように思います。 >>>> >>>>> #9 0x00007fc5ff18cd8a in >>>>> l7vs::http_protocol_module_base::find_http_header(char const*, unsigned >>>>> long, std::basic_string, >>>>> std::allocator > const&, unsigned long&, unsigned long&) () from >>>>> /usr/lib64/l7vs/protomod_sessionless.so >>>> 　よって、まずは本関数を中心に解析を進めてまいりたいと思います。 >>>> 　つきましては、問題発生時間帯における以下の情報をいただくことは >>>> 　可能でしょうか。 >>>> >>>> ログ： >>>> 　　・/var/log/l7vsd/* >>>> 　　・/var/log/messages >>>> 　　・バックエンドサーバのアクセスログ/エラーログ等 >>>> 　設定ファイル： >>>> 　　・/etc/l7vs/* >>>> 　　・/etc/ha.d/l7directord.cf >>>> >>>> >>>> 　なお、本関数は以下のオプションが設定されている場合に >>>> 　呼び出されるため、暫定対処としてこれらのオプションを解除していただ >>>> ければ >>>> 　ひとまず問題は発生しなくなるはずですので、ご検討いただければと思い >>>> ます。 >>>> >>>> 　?「--forwarded-for(-F)」オプション >>>> 　?「--statistic(-c)」オプション >>>> 　?「-f(--flag) 」オプション >>>> >>>> 　各オプションの設定有無確認方法： >>>> 　　「l7vsadm -V 」コマンドの結果、該当VSに以下の表示があれば >>>> 　　設定有りとなります。 >>>> >>>> 　　?「--forwarded-for」の文字列がある >>>> 　　?「--statistic 1」となっている >>>> 　　?「Sorry Flag on」となっている >>>> >>>> >>>> 以上、よろしくお願いいたします。 >>>> >>>> >>>>> -----Original Message----- >>>>> From: ultramonkey-l7-users-bounces ＠ lists.osdn.me >>>>> [mailto:ultramonkey-l7-users-bounces ＠ lists.osdn.me] On Behalf Of 小 >>>>> 林 年伸 >>>>> Sent: Friday, December 25, 2015 8:43 PM >>>>> To: ultramonkey-l7-users ＠ lists.osdn.me >>>>> Subject: [Ultramonkey-l7-users 611] Re: l7vsd(ver 3.1.2)が突然停止し >>>>> ました >>>>> >>>>> コミュニティの皆様 >>>>> >>>>> お世話になっております。 >>>>> ジグソーの小林と申します。 >>>>> >>>>> 掲題の件のDumpファイルのトレース結果を記載させていただきます。 >>>>> ------------------------------------------------------------- >>>>> ...... 読み込み >>>>> >>>>> Loaded symbols for /usr/lib64/l7vs/sched_lc.so >>>>> Core was generated by `/usr/sbin/l7vsd'. >>>>> Program terminated with signal 6, Aborted. >>>>> #0 0x00007fc605a7a625 in raise () from /lib64/libc.so.6 >>>>> >>>>> (gdb) bt >>>>> #0 0x00007fc605a7a625 in raise () from /lib64/libc.so.6 >>>>> #1 0x00007fc605a7be05 in abort () from /lib64/libc.so.6 >>>>> #2 0x00007fc605ab8537 in __libc_message () from /lib64/libc.so.6 >>>>> #3 0x00007fc605abde66 in malloc_printerr () from /lib64/libc.so.6 >>>>> #4 0x00007fc605ac09b3 in _int_free () from /lib64/libc.so.6 >>>>> #5 0x00007fc5ff1a1ef6 in boost::xpressive::detail::regex_impl>>>> const*>::~regex_impl() () from /usr/lib64/l7vs/protomod_sessionless.so >>>>> #6 0x00007fc5ff1a21f2 in >>>>> boost::detail::sp_counted_impl_p>>>> >>>>> const*> >::dispose() () >>>>> from /usr/lib64/l7vs/protomod_sessionless.so >>>>> #7 0x00000000004c42d9 in >>>>> boost::detail::shared_count::~shared_count() () >>>>> #8 0x00007fc5ff1913dd in >>>>> boost::intrusive_ptr >>>>> >::~intrusive_ptr() () >>>>> from /usr/lib64/l7vs/protomod_sessionless.so >>>>> #9 0x00007fc5ff18cd8a in >>>>> l7vs::http_protocol_module_base::find_http_header(char const*, unsigned >>>>> long, std::basic_string, >>>>> std::allocator > const&, unsigned long&, unsigned long&) () from >>>>> /usr/lib64/l7vs/protomod_sessionless.so >>>>> #10 0x00007fc5ff1dacb0 in >>>>> l7vs::protocol_module_sessionless::handle_client_recv(boost::thread::id, >>>>> >>>>> boost::array const&, unsigned long) () >>>>> from /usr/lib64/l7vs/protomod_sessionless.so >>>>> #11 0x0000000000575c7b in >>>>> l7vs::tcp_session::up_thread_client_receive(l7vs::tcp_session::TCP_PROCESS_TYPE_TAG) >>>>> >>>>> () >>>>> #12 0x0000000000571941 in l7vs::tcp_session::up_thread_run() () >>>>> #13 0x000000000052303e in >>>>> l7vs::session_thread_control::upstream_run() () >>>>> #14 0x00007fc607792d47 in thread_proxy () from >>>>> /usr/lib64/libboost_thread-mt.so.5 >>>>> #15 0x00007fc6058329d1 in start_thread () from /lib64/libpthread.so.0 >>>>> #16 0x00007fc605b308fd in iopl () from /lib64/libc.so.6 >>>>> #17 0x0000000000000000 in ?? () >>>>> ------------------------------------------------------------- >>>>> #5、protomod_sessionless.so の辺りで何かありましたでしょうか。 >>>>> >>>>> l7vsdのログには出力が無かったのでこちらを記載させていただきました。 >>>>> >>>>> 大変お手数ですが、何分かりましたらご教授いただけますでしょうか。 >>>>> >>>>> >>>>> >>>>> On 2015/12/25 15:38, 小林 年伸 wrote: >>>>>> コミュニ ティの皆様 >>>>>> >>>>>> お世話になっております。 >>>>>> ジグソーの小林と申します。 >>>>>> >>>>>> 掲題の件についてご質問させていただいてよろしいでしょうか。 >>>>>> >>>>>> ■事象 >>>>>> ロードアベレージが突然 200/1分 近くになりl7vsdのプロセスがダウン >>>>>> 発生時のCPU使用率は2?3%ほどだったが >>>>>> Diskの書き込み待ちが発生していたよう >>>>>> これまでも突然ロードアベレージが高くなる(30/1分程度)時間があり >>>>>> その時もやはりDiskの書き込み待ちが発生していた。 >>>>>> クラスタ構成となっていて、待機・停止している側では >>>>>> 書き込み待ちは発生していないのでl7vsdが原因と考えております。 >>>>>> >>>>>> 既出のもので上のような症状はありましたでしょうか。 >>>>>> >>>>>> 又、l7vsdのプロセスでDiskへの書き込みが発生する部分として >>>>>> 何が考えられますでしょうか。例えば一時ファイルなど >>>>>> もし分かればその部分をtmpfsとしてメモリ空間に持っていくことも >>>>>> 検討しております。 >>>>>> >>>>>> 停止時にcore_dumpも出力するようにしていたのですが >>>>>> 如何せんサイズが重いので必要でしたら特定の部分のみを >>>>>> 取り出して添付するように致します。 >>>>>> >>>>>> お手数ではございますが、何卒ご確認よろしくお願いいたします。 >>>>>> >>>>>> ■以下は設定構成となります。 >>>>>> ・UML7ver. ultramonkeyl7-3.1.2-1 >>>>>> ・OS CentOS6.6 (Xen仮想マシン) >>>>>> ・CPU 8 >>>>>> ・MEM 16GB >>>>>> ・構成 >>>>>> HTTPをUltraMonkeyでバックエンド3台にlcで振り分け >>>>>> backendはapache2.2 >>>>>> >>>>>> ・l7vsd設定 >>>>>> --------------------------------------------- >>>>>> [logger] >>>>>> l7vsd_log_filename = "/var/log/l7vs/l7vsd.log" >>>>>> l7vsd_rotation = "size" >>>>>> l7vsd_max_backup_index = "10" >>>>>> l7vsd_max_filesize = "2048M" >>>>>> l7vsd_accesslog_rotate_type = "size" >>>>>> l7vsd_accesslog_rotate_max_backup_index = "10" >>>>>> l7vsd_accesslog_rotate_max_filesize = "2048M" >>>>>> l7vsd_network = "warn" >>>>>> l7vsd_network_qos = "warn" >>>>>> l7vsd_network_bandwidth = "warn" >>>>>> l7vsd_network_num_connection = "warn" >>>>>> l7vsd_network_access = "warn" >>>>>> l7vsd_mainthread = "warn" >>>>>> l7vsd_virtualservice = "warn" >>>>>> l7vsd_virtualservice_thread = "warn" >>>>>> l7vsd_session = "warn" >>>>>> l7vsd_session_thread = "warn" >>>>>> l7vsd_realserver = "warn" >>>>>> l7vsd_sorryserver = "warn" >>>>>> l7vsd_module = "warn" >>>>>> l7vsd_replication = "warn" >>>>>> l7vsd_replication_sendthread = "warn" >>>>>> l7vsd_parameter = "warn" >>>>>> l7vsd_logger = "warn" >>>>>> l7vsd_command = "warn" >>>>>> l7vsd_start_stop = "warn" >>>>>> l7vsd_system = "warn" >>>>>> l7vsd_system_memory = "warn" >>>>>> l7vsd_system_endpoint = "warn" >>>>>> l7vsd_system_signal = "warn" >>>>>> l7vsd_system_environment = "warn" >>>>>> l7vsd_snmpagent = "warn" >>>>>> l7vsd_protocol = "warn" >>>>>> l7vsd_schedule = "warn" >>>>>> l7vsadm_log_filename = "/var/log/l7vs/l7vsadm.log" >>>>>> l7vsadm_rotation = "size" >>>>>> l7vsadm_max_filesize = "2048M" >>>>>> l7vsadm_max_backup_index = "10" >>>>>> l7vsadm_parse = "warn" >>>>>> l7vsadm_operate = "warn" >>>>>> l7vsadm_config_result = "warn" >>>>>> l7vsadm_common = "warn" >>>>>> l7vsadm_logger = "warn" >>>>>> l7vsadm_parameter = "warn" >>>>>> l7vsadm_module = "warn" >>>>>> l7vsadm_protocol = "warn" >>>>>> l7vsadm_schedule = "warn" >>>>>> [l7vsadm] >>>>>> cmd_interval = 1 >>>>>> cmd_count = 10 >>>>>> con_interval = 1 >>>>>> con_count = 1 >>>>>> [l7vsd] >>>>>> maxfileno = 65535 >>>>>> [virtualservice] >>>>>> session_thread_pool_size = 32 >>>>>> throughput_calc_interval = 500 >>>>>> [session] >>>>>> server_connect_timeout = 61 >>>>>> --------------------------------------------- >>>>>> >>>>>> ・l7directord設定 >>>>>> --------------------------------------------- >>>>>> virtual = 10.83.13.46:80 >>>>>> real = 〓バックエンド01〓:80 masq 10 >>>>>> real = 〓バックエンド02〓:80 masq 10 >>>>>> real = 〓バックエンド03〓:80 masq 10 >>>>>> module = sessionless --forwarded-for >>>>>> scheduler = lc >>>>>> qosup = 125M >>>>>> qosdown = 125M >>>>>> checktype = connect >>>>>> service = http >>>>>> quiescent = no >>>>>> checkcount = 2 >>>>>> session_thread_pool_size = 1800 >>>>>> maxconn = 0 >>>>>> --------------------------------------------- >>>>>> スレッドのプール数を稼ぐためにスタックトレースのサイズを >>>>>> l7vsdのプロセスのみデフォルトの10MBから3MBに変更しています。 >>>>>> >>>>>> >>>>>> >>>>> -- >>>>> -------------------------------------------- >>>>> ジグソー株式会社 >>>>> 小林　年伸 >>>>> E-mail：toshinobu.kobayashi ＠ jig-saw.com >>>>> Tel：011-737-0240 Fax：011-737-0241 >>>>> 〒060-0808 >>>>> 北海道札幌市北区北8条西3丁目32番 >>>>> >>>>> _______________________________________________ >>>>> Ultramonkey-l7-users mailing list >>>>> Ultramonkey-l7-users ＠ lists.osdn.me >>>>> http://lists.osdn.me/mailman/listinfo/ultramonkey-l7-users >>> >> >> -- >> -------------------------------------------- >> ジグソー株式会社 >> 小林　年伸 >> E-mail：toshinobu.kobayashi ＠ jig-saw.com >> Tel：011-737-0240 Fax：011-737-0241 >> 〒060-0808 >> 北海道札幌市北区北8条西3丁目32番 -- -------------------------------------------- ジグソー株式会社 小林　年伸 E-mail：toshinobu.kobayashi ＠ jig-saw.com Tel：011-737-0240 Fax：011-737-0241 〒060-0808 北海道札幌市北区北8条西3丁目32番