品質保証部の青田です。 （プログラマではなく）QAの面白い話が普段どのような業務に携わっているかを書くように、というオーダーがありましたので紙面を拝借します。 ＃ "面白い話"は概ね社外秘に分類されてしまうのが残念です
さて。昨年末、CyDE-Cチームの青木がcybozu.com の MQ と性能問題という記事を書きました。運用環境の負荷を軽減するための改良についてです。そこでは
運用環境に乗るのはもう少し先ですが、その時は成果をここで発表したいと思います。
と締めくくっていますが、報告が無いので勝手に後日談を書くことにします。
CyDE-Cとは?
cybozu.comのミドルウェア層です。弊社ではkintoneやGaroonといったアプリケーション層が利用する様々な機能をCyDE-Cと総称しています。インフラ担当の運用チームと密に連携しつつ、機能拡張や性能改善、細かな不具合の改修を行うことがCyDE-Cチームのメインタスクです。GUIもほぼ無く、新機能を搭載してもWebサイトやカタログで取り上げられはしませんが、非常に重要な部分です。
MQの性能問題と解決方法の提案
詳細はcybozu.com の MQ と性能問題を読んでいただけるとありがたいのですが、ざっくりとこんな内容です。
- MQに対するポーリングが行われていた
- 顧客数増加に伴い、ポーリングによって発生する負荷が許容できなくなりつつあった
- インフラチームから事態の解決を依頼され、プログラマが新方式を設計・実装した
- MySQLのTriggerとUDFを利用した
解決の目処が立ったのはめでたいのですが、本番環境に適用するためには試験を実施する必要があります。
方針・仕様の理解と試験設計
改修の大方針として以下の2点が挙げられます。
- 負荷は減らしたい
- 今まで実現していた機能は維持する必要がある
- ドメインプロテクションの維持
- MQを利用して実現していた機能の担保(利用するアプリ側に仕様変更の影響が出ないことを含む）
それに対するプログラマの回答が
- ジョブが挿入された時、自発的にキューがワーカーにジョブが挿入された事を通知する
- ワーカーは通知を受け取ったら処理スレッドを立ち上げるようにする
- 処理するジョブが無くなったら処理スレッドを終了する
です。
日中にお客様がサービスを利用されている状況では妥当なMQへのポーリングですが、利用率が落ちる時間帯（特に深夜から早朝など）にも同様の頻度で実施する必要は無い。必要になったら（≒お客様の操作に連動して）ポーリングスレッドを稼働させる方式に改良しよう、ということですね。
設計と仕様に関するレビュー、実装、開発チームによるテストを経てQAにバトンが渡されます。 単に提示された仕様を確認するだけではなく、そこに至るまでの背景を把握しておくことで、仕様の考慮漏れが無いかもチェックしておきます。この段階でプログラマを質問攻めしておくと、試験終盤にサツバツとした雰囲気に突入する可能性を減らすことが出来ます。
機能試験の内容は仕様書に記載された内容に対応して作成します。
- MQにジョブが積まれたら、ワーカーへUDPを投げて通知すること
- 通知を受けたワーカーがポーリングスレッドを起動し、ジョブの処理を開始すること
- ジョブが0個の状態が一定時間持続したら、ポーリングスレッドが終了すること
また、UDPの取りこぼし対策として実装された以下も当然試験の対象です。
- 5分に1度、MQからワーカーへTCPを投げて、ポーリングスレッドを起動すること
これらを実現するためにどのような仕組みを利用しているのか、それらはどのような手順で環境へ配置すべきなのかといった部分も押さえる必要があります。
設置試験
試験環境を構築した後、MySQLにTriggerが仕込まれていることを確認します。これが無いとUDPを投げてくれません。
mysql> use c112130_garoon;
Database changed
mysql> show triggers \G;
*************************** 1. row ***************************
Trigger: notify_to_worker
Event: INSERT
Table: _queue
Statement: BEGIN
SET @ret = notify( DATABASE() );
END
Timing: BEFORE
Created: NULL
sql_mode:
Definer: c112130@%
character_set_client: utf8mb4
collation_connection: utf8mb4_unicode_ci
Database Collation: utf8mb4_unicode_ci
1 row in set (0.32 sec)
同様にTCPでパケットを投げる役割を担う、eventの設定も確認します。 my.cnfの記述がOnになっていることを確認し、
# event scheduler event_scheduler = On
実際に登録されているeventの内容も確認します。
「5分に1度、MQからワーカーへTCPを投げて、ポーリングスレッドを起動すること」という仕様通り"interval_value: 5"で"interval_field: MINUTE"ですね。
mysql> use mysql;
mysql> select * from event \G;
*************************** 1. row ***************************
db: c112130_slash
name: scheduled_notifier
body: BEGIN
SET @ret = notify( DATABASE(), 1 );
END
definer: c112130@%
execute_at: NULL
interval_value: 5
interval_field: MINUTE
created: 2012-11-06 05:14:37
modified: 2012-11-06 05:14:37
last_executed: 2012-11-15 09:20:36
starts: 2012-11-06 05:15:36
ends: NULL
status: ENABLED
on_completion: DROP
sql_mode:
comment:
originator: 1
time_zone: +00:00
character_set_client: utf8mb4
collation_connection: utf8mb4_unicode_ci
db_collation: utf8mb4_unicode_ci
body_utf8: BEGIN
SET @ret = notify( DATABASE(), 1 );
END
*************************** 2. row ***************************
機能試験
試験環境のVMにて、tcpdumpを用いてパケットの監視を行いました。 MQが空の状態からブラウザで各アプリケーションを操作してMQにジョブを積み、UDPのパケットが流れていることを確認します。
[11/06 07:02]aota@aota5-ap-1:~$ sudo tcpdump port 8686 and udp tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes 07:03:30.450568 IP aota5-db.localdomain.33949 > aota5-ap-1.localdomain.8686: UDP, length 13 <--Slashからitoを追加した。Garoonにシンクされた。 07:07:50.749537 IP aota5-db.localdomain.53101 > aota5-ap-1.localdomain.8686: UDP, length 14 <--ガルーンでメッセージ送信。fts-indexerが積まれた。 07:09:16.711947 IP aota5-db.localdomain.42523 > aota5-ap-1.localdomain.8686: UDP, length 12 <--kintoneでレコード追加。fts-indexerが積まれた。
-Xオプションをつけて中身も確認します。 ここではブラウザからcybozu.com共通管理やkintoneを操作し、ドメイン名/アプリの組み合わせが実施した操作（操作の結果MQに積まれるジョブ）と対応していることを確認しています。
[11/07 00:43]aota@aota5-ap-1:~$ sudo tcpdump port 8686 and udp -X
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
00:44:40.471879 IP aota5-db.localdomain.44235 > aota5-ap-1.localdomain.8686: UDP, length 13 ユーザー登録
0x0000: 4500 0029 0000 4000 4011 cd3b 0a00 acc5 E..)..@.@..;....
0x0010: 0a00 acc3 accb 21ee 0015 6daf 6331 3132 ......!...m.c112
0x0020: 3133 305f 736c 6173 68 130_slash
00:45:50.998968 IP aota5-db.localdomain.42805 > aota5-ap-1.localdomain.8686: UDP, length 14 メッセージ送信
0x0000: 4500 002a 0000 4000 4011 cd3a 0a00 acc5 E..*..@.@..:....
0x0010: 0a00 acc3 a735 21ee 0016 6db0 6331 3132 .....5!...m.c112
0x0020: 3133 305f 6761 726f 6f6e 130_garoon
00:46:44.128172 IP aota5-db.localdomain.37749 > aota5-ap-1.localdomain.8686: UDP, length 13 監査ログテストメール送信
0x0000: 4500 0029 0000 4000 4011 cd3b 0a00 acc5 E..)..@.@..;....
0x0010: 0a00 acc3 9375 21ee 0015 6daf 6331 3132 .....u!...m.c112
0x0020: 3438 315f 736c 6173 68 481_slash
00:47:15.526491 IP aota5-db.localdomain.34042 > aota5-ap-1.localdomain.8686: UDP, length 12 レコード書き出し
（略
ユーザー操作の結果MQにレコードが積まれると、UDPパケットが送出されることは確認出来ました。 次は全く何も操作をしない状態で放置し、5分毎にTCPのパケットが飛ぶことを確認します。
09:44:30.676661 IP aota5-db.localdomain.58672 > aota5-ap-1.localdomain.8686: Flags [P.], seq 0:40, ack 1, win 457, options [nop,nop,TS val 1854598 ecr 1902648], length 40
0x0040: 2f63 3131 3231 3330 2f67 6172 6f6f 6e20 /c112130/garoon.
09:49:30.679025 IP aota5-db.localdomain.58682 > aota5-ap-1.localdomain.8686: Flags [P.], seq 0:40, ack 1, win 457, options [nop,nop,TS val 1884598 ecr 1932648], length 40
0x0040: 2f63 3131 3231 3330 2f67 6172 6f6f 6e20 /c112130/garoon.
09:54:30.682011 IP aota5-db.localdomain.58693 > aota5-ap-1.localdomain.8686: Flags [P.], seq 0:40, ack 1, win 457, options [nop,nop,TS val 1914598 ecr 1962649], length 40
0x0040: 2f63 3131 3231 3330 2f67 6172 6f6f 6e20 /c112130/garoon.
09:59:30.684539 IP aota5-db.localdomain.58704 > aota5-ap-1.localdomain.8686: Flags [P.], seq 0:40, ack 1, win 457, options [nop,nop,TS val 1944599 ecr 1992649], length 40
0x0040: 2f63 3131 3231 3330 2f67 6172 6f6f 6e20 /c112130/garoon.
10:04:30.686734 IP aota5-db.localdomain.58715 > aota5-ap-1.localdomain.8686: Flags [P.], seq 0:40, ack 1, win 457, options [nop,nop,TS val 1974599 ecr 2022649], length 40
0x0040: 2f63 3131 3231 3330 2f67 6172 6f6f 6e20 /c112130/garoon.
余談ですが、tcpdumpを利用するのは数年ぶりだったので、manを読み直しました。
効果測定
単位時間あたりのポーリング量を比較しました。 MySQLのクエリログをとり、MQに対するSELECT文の数を集計しています。深夜帯（例:23:00 - 07:00）を想定して8時間、傾向の確認用に1時間。いずれもGUIからの操作は実行しません。
今回はシビアな負荷検証ではないため、クエリログをMySQLに記録しておきます。このあたりは試験内容を勘案した状況判断です。 再起動せずに済むのでお手軽です。
mysql> set global general_log = 1; mysql> set global log_output = 'TABLE'; mysql> use mysql mysql> select * from general_log;
1時間分（改良前）
mysql> select user_host, count(*) from general_log where event_time between '2012-11-12 08:00:00' and '2012-11-12 09:00:00' and argument like '%FROM _queue%' group by user_host; +-----------------------------------+----------+ | user_host | count(*) | +-----------------------------------+----------+ | c113130[c113130] @ [xx.xx.xx.xx] | 8450 | | c113131[c113131] @ [xx.xx.xx.xx] | 8450 | +-----------------------------------+----------+
1時間分（改良後）
mysql> select user_host, count(*) from general_log where event_time between '2012-11-12 08:00:00' and '2012-11-12 09:00:00' and argument like '%FROM _queue%' group by user_host; +------------------------------------+----------+ | user_host | count(*) | +------------------------------------+----------+ | c112130[c112130] @ [yy.yy.yy.yy] | 375 | | c112481[c112481] @ [yy.yy.yy.yy] | 374 | +------------------------------------+----------+
8時間分（改良前）
mysql> select user_host, count(*) from general_log where event_time between '2012-11-12 15:00:00' and '2012-11-12 23:00:00' and argument like '%FROM _queue%' group by user_host; +-----------------------------------+----------+ | user_host | count(*) | +-----------------------------------+----------+ | c113130[c113130] @ [xx.xx.xx.xx] | 67645 | | c113131[c113131] @ [xx.xx.xx.xx] | 67645 | +-----------------------------------+----------+ 2 rows in set (4.60 sec)
8時間分（改良後）
mysql> select user_host, count(*) from general_log where event_time between '2012-11-12 15:00:00' and '2012-11-12 23:00:00' and argument like '%FROM _queue%' group by user_host; +------------------------------------+----------+ | user_host | count(*) | +------------------------------------+----------+ | c112130[c112130] @ [yy.yy.yy.yy] | 3000 | | c112481[c112481] @ [yy.yy.yy.yy] | 2998 | +------------------------------------+----------+ 2 rows in set (4.32 sec)
というわけで、1/20程度に削減できていました。期待したとおりです。 もっとも、実際の運用環境ではここまで綺麗に削減されるとは限りません。例えばkintoneの「リマインド通知」「グラフの定期レポート」といった、定時実行される機能が利用されることで、MQが稼働する可能性があるからです。
適用後の影響確認
新機能は期待した効果が得られそうなことは判明しました。ただ、従来よりも余分な動作をMySQLに要求するため、メモリの消費傾向に変化があるかどうかも確認しました。 ここは結構重要なポイントです。ノーチェックで本番環境に適用したらメモリが枯渇した、などという話は洒落ににならないわけです。事前に検証し、必要であれば運用チームにVMのメモリ増強を依頼するなどの打診を行います。
適用前と適用後の環境を用意し、それぞれで/proc/$MYSQL_PID/status の VmRSS を毎分チェックし、比較するやり方です。 増加傾向自体は改良前と変わらない曲線を描いていました。
こちらはドメイン数との相関について。 
運用試験とリリース
諸々の試験を経た後、サイボウズが自社で利用しているcybozu.com上の環境へ、今回の改良を適用しました。本件に限らず、お客様の環境へリリースする前には1ヶ月以上の運用試験を実施する方針なのです。今回は1月から3月の定期メンテナンスまで、約2ヶ月でした。
それ以外にもいくつかのマイルストーンがあるのですが、運用チームによる適用リハーサルなど諸々を無事にクリアして、新MQは2013/03にリリースされました。 サービスの稼働率を維持しつつ、性能問題を解決することが出来たので、非常に喜ばしいことです。リリース後数ヶ月が経過していますが、安定稼働中です。
というわけで
プログラマが開発した新MQを運用に乗せるまでのお話でした。
もしも負荷を下げることができなかったら、機器の増強で補うなどの方法を検討せざるを得なかったかもしれません。あるいは機能仕様に影響が出るような改良案だった場合に、お客様の使い勝手が変わっていた可能性もあります。前者はサービスの原価に跳ね返ってきますし、いずれにしてもあまり望ましいことではないです。ありがたいことにcybozu.comをご利用くださるお客様が着々と増えているので、今後もミドルウェアの改良には一定の工数を投資し続けることになるとなるでしょう。ミドルウェアやインフラに関しては、ご利用いただいているお客様に気づかれずに、しれっと改善してしまう方向で努力していきたいところです。
紙面の都合上割愛しましたが、重要な機構の改良なのでかなり熱心に苛めたことを申し添えておきます。
