ソーシャルアプリのボトルネック調査例(strace編)
KLab Advent Calendar 2011 「DSAS for Social を支える技術」の6日目です。
はじめに
ソーシャルゲームの開発では、仕様変更への柔軟な対応が求められることが多い上、突発的なアクセス増加にも耐えられる応答性能が要求されます。
一昔前までは、サービスの性能を担保するにはきちんとアーキテクチャを設計し、入念に動作チェックして、負荷試験して、プロファイル取って・・・みたいなことをリリース前にひらすやるのが理想だと思っていた頃もありました。
しかし、ソーシャルゲームの世界ではリリース直後からイベントやキャンペーンなどの追加開発が入ったり、ユーザの動向やコミュニティを参考にして仕様を変更することが多いので、リリース前に頑張ってチューニングしていても、その性能を担保し続ける事が難しいといった現状があります。
まあ、これはこれで刺激があって楽しい面もありますし、遊んでくれているユーザの皆様にできるだけ良いサービスを提供したいという気持ちもあるので、きちんと運用ができるように様々な工夫をしていますが、所詮プログラムは人間が書くものなので、時には思わぬ爆弾を仕込んでしまい、著しく応答性能が悪くなってしまうこともあったりします。
このような問題のほとんどは、原因さえわかってしまえば容易に解決できるケースが多いので、イカに速くボトルネックを見つけ出すかが鍵となります。
ボトルネック調査といっても、発生している事象によってアプローチの仕方は様々です。DBサーバに想定以上のI/Oが発生している場合は、slowログを見てexplainするでしょうし、接続エラーやタイムアウトが頻発している場合はネットワークの品質を疑って、スイッチのログを確認したりもするでしょう。
必要な場面で必要な情報を取り出す手段を知っていることが、ボトルネックを調査する上で必要とされるスキルなのかもしれません。
えーっと、、すっかり前置きが長くなってしまいましたが、今回はstraceを使ってアプリケーションのボトルネックを調査した例を紹介してみたいと思います。
apacheのプロセスを覗いてみる
「実稼動中のapacheをstraceなんかして本当に解析できるの?」と疑問に感じる方もいるかもしれませんが、実際にやってみると以外と簡単です。
# strace -p 8139 -tt -T -e trace=network,poll 15:21:01.490665 accept(3, {sa_family=AF_INET, sin_port=htons(xxxxx), sin_addr=inet_addr("x.x.x.x")}, [16]) = 11 <0.000011> -- snip -- 15:21:02.039149 accept(3, {sa_family=AF_INET, sin_port=htons(xxxxx), sin_addr=inet_addr("x.x.x.x")}, [16]) = 11 <0.000007> -- snip -- 15:21:02.727402 accept(3, {sa_family=AF_INET, sin_port=htons(xxxxx), sin_addr=inet_addr("x.x.x.x")}, [16]) = 11 <0.000007> -- snip -- 15:21:03.625652 accept(3, {sa_family=AF_INET, sin_port=htons(xxxxx), sin_addr=inet_addr("x.x.x.x")}, [16]) = 11 <0.000009>
apacheの子プロセスをstraceすると上記のような結果となります。accept(2) を境界にしてリクエスト毎の処理を追うことができそうです。
15:21:04.244882 accept(3, {sa_family=AF_INET, sin_port=htons(37421), sin_addr=inet_addr("x.x.x.x")}, [16]) = 11 <0.000011> 15:21:04.254675 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 20 <0.000007> 15:21:04.254702 connect(20, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("0.0.0.0")}, 28) = 0 <0.000007> 15:21:04.254749 poll([{fd=20, events=POLLOUT}], 1, 0) = 1 ([{fd=20, revents=POLLOUT}]) <0.000055> 15:21:04.254829 sendto(20, "W\"..., 43, MSG_NOSIGNAL, NULL, 0) = 43 <0.000018> 15:21:04.254873 poll([{fd=20, events=POLLIN}], 1, 5000) = 1 ([{fd=20, revents=POLLIN}]) <0.000014> 15:21:04.254918 recvfrom(20, "W\"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [16]) = 79 <0.000006> 15:21:04.254974 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 20 <0.000007> 15:21:04.255018 connect(20, {sa_family=AF_INET, sin_port=htons(11211), sin_addr=inet_addr("x.x.x.x")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000019> 15:21:04.255059 poll([{fd=20, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, -997199722) = 1 ([{fd=20, revents=POLLOUT}]) <0.000098> 15:21:04.255182 getsockopt(20, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 <0.000005> 15:21:04.255219 sendto(20, "get "..., 38, MSG_DONTWAIT, NULL, 0) = 38 <0.000014> 15:21:04.255255 poll([{fd=20, events=POLLIN|POLLERR|POLLHUP}], 1, -997199722) = 1 ([{fd=20, revents=POLLIN}]) <0.000174> 15:21:04.255456 recvfrom(20, "VALUE "..., 8192, MSG_DONTWAIT, NULL, NULL) = 3655 <0.000007> 15:21:04.367211 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 21 <0.000009> 15:21:04.367408 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 22 <0.000010> 15:21:04.367445 connect(22, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("0.0.0.0")}, 28) = 0 <0.000010> 15:21:04.367511 poll([{fd=22, events=POLLOUT}], 1, 0) = 1 ([{fd=22, revents=POLLOUT}]) <0.000007> 15:21:04.367551 sendto(22, "e("..., 43, MSG_NOSIGNAL, NULL, 0) = 43 <0.000027> 15:21:04.367614 poll([{fd=22, events=POLLIN}], 1, 5000) = 1 ([{fd=22, revents=POLLIN}]) <0.000008> 15:21:04.367663 recvfrom(22, "e("..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [16]) = 79 <0.000007> 15:21:04.367761 connect(21, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("x.x.x.x")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000025> 15:21:04.367837 poll([{fd=21, events=POLLIN|POLLPRI}], 1, 30000) = 1 ([{fd=21, revents=POLLIN}]) <0.000246> -- snip -- 15:21:04.381269 shutdown(21, 2 /* send and receive */) = 0 <0.000011> 15:21:04.382572 shutdown(11, 1 /* send */) = 0 <0.000015>
このログの黄色の部分は、11211番ポートへ接続してgetという文字列を送信してることからmemcachedへの問い合わせでしょう。また、水色の部分は3306番ポートに接続しているので、MySQLへ接続していることがわかります。
そして、memcachedから値を取得し、MySQLへ接続するまでに100ms以上の時間がかかっていることが読み取れます。したがって、この処理のボトルネックは、SQLでもネットワークでもなく、MySQLへ接続するまでのアプリケーションコードの中にあると推測できます。
straceで把握できるのはここまでですが、アプリケーションのボトルネックを発見するための有力な手がかりにはなるのではないでしょうか。
ただ、さすがに稼働中の全サーバの全プロセスをトレースするのは大変すぎるので、「問題が見つかればらっきー☆」な気持ちで、アクセスが増える時間帯だけ、一部のサーバだけでstraceをかけてみるところから始めるのがよいと思います。
まとめ
本来であれば、この手の問題は試験環境などでXDebugなどを使ってプロファイルを取るのが定石だと思いますが、試験環境で再現させる事が難しい事象も数多くあります。このようなケースでは、アプリケーションの中でデバッグプリントを仕込み、ログを大量に出力させながら調査するといった手法を取ったりすることもありますが、今回ご紹介したstraceや、ltrace、oprofile、LatencyTOPなどのツールをうまく利用することで、調査にかかる時間や手間を減らせる可能性もあります。
ただ、この手のツールはアプリケーションエンジニアには馴染みが薄く、どちらかというとサーバエンジニアやネットワークエンジニアの得意分野な気がしています。不慣れなツールを頑張って駆使しようとする意気込みも素敵ですが、どうしても困った時には、最寄りのサーバ担当者に「アプリケーションプロセスをトレースしてちょ!」と依頼してみるのも悪くはないと思っています。
まあ、要は何が言いたかったかというと、「これは僕が自分で解決しなければいけない問題さ!」と信じて一人で頑張るだけでなく、ダメもとでいいので、たまにはサーバ屋とか、ネットワーク屋とか、八百屋とか、魚屋とかにも相談してみると、もしかすると別の視点から問題解決の糸口が見つかるかもしれないよ!、、というお話でした。
最後に念のため補足
straceでapacheプロセスをトレースする際は、httpd.confに
MaxRequestsPerChild 0
を指定しないと、プロセスが勝手に終了してしまうのでご注意ください。
また、straceは昔からバグが多いことでも有名です。できるだけ新しいバージョンを使い、事前に安全な環境でテストしてから利用することをおすすめします。