Edited at

Apache設定を変えたことによりアプリが爆速になった話

More than 1 year has passed since last update.


これは何

この記事は 第2のドワンゴ Advent Calendar 2017 の16日目のやつ。

幾つかの勘違いとテスト漏れが重なり、サーバ設定が意図したものになっておらず、APIが重くなっていた現象がありました。これを直したらレスポンスが爆速になった、という話です。

タイトルは釣り気味で、正しくは「爆速APIが、インフラエンジニアがクソだったので劇重になっていた」が正しいです。恥を偲んで失敗談を共有します。


私は誰

ニコニコ静画のインフラエンジニアをやってます。


結論からいうと

ApacheのKeepAlive設定が意図せずOnになっていた。

その結果、クライアントとコネクションを張りっぱなしになり、接続数上限に到達していました。Apacheの処理待ち行列に入り、待たされが発生していた。


問題原因突き止めるまでの過程


インフラ構成

問題原因を突き止めるには、切り分けのためにインフラ構成やミドルウェア設定を知っていないといけません。インフラ構成についてざっくり書いておく。


  • ロードバランサで負荷分散

  • APIサーバは複数台構成

  • OSはCentOS6系

  • APIからつなぎに行くバックエンドサーバとして、DB(MySQL)、Cache(memcached)などがある


障害の切り分け

諸事情によりAPIへのアクセスが増えた。ピークタイムにAPIがめちゃくちゃ重くなる現象が報告されていた。しかしながら、リソース使用量をみると、そこそこ空いておりそんなに処理待ちになるとは思えなかった(例えばCPU使用率でいうと30%程度)。

問題箇所が特定できるまでは、以下のようなことを考えた。


  • 本当に沢山アクセスきてるの? => ログベースだと特に落ち込んでない。むしろピーク前からみると微増(本来はもっと増えてもいいと思うんだけどなーという感じ)

  • サーバリソースがガラ空きなのにめちゃ重いとなるとネットワークの問題? => 同一NWにいる他の役割のサーバには影響なし(WebFrontサーバは快調)。一応LBなどのエラーやリソース使用量見てみるが特になし。

  • じゃあサーバのネットワークインターフェースとかは? 故障してたりしない? => それが原因なら1台だけに出て、全台同じ現象になることはない

  • 全台に出るなら裏のDBとかが詰まった? => Connectionは増えているが、特段重いということはなさそう。ここも重くなればWebFrontにも影響出るはず

  • コードの問題? => 直前にデプロイしているわけでもないし、アプリケーションログに出力なし

  • となるとミドルウェアかサーバ設定(kernelチューニング)とかの問題? => syslog(/var/log/messages) 見てみよう => なんか見慣れないものが出ている!

kernel: possible SYN flooding on port 8443. Sending cookies.


上記ログが出るのはどんな時だ? 対応どうすればいいの?

今回の本題と関係はするものの根本原因じゃないのでざっくりとだけ書く.

ここら辺のRedhatの資料を読んだ。https://access.redhat.com/solutions/30453


  • 悪意あるアクセス(TCPハンドシェイクのSynだけめっちゃ送ってきているとか)があると出るかも

  • そうでない場合、kernelのnet.core.somaxconn設定とかnet.ipv4.tcp_max_syn_backlog設定が小さくなってしまっているかも。ApacheのBacklog設定も見た方がいいよ。

なるほど。確かにsomaxconnはこのサーバできちんと設定されてなさそうだ。

そうすると、待ち行列が溢れているのかな? 設定変えてみよう <- この時点で何も考えていない。資料を慌てて読んでその通りの対応を入れただけ。テンパっているのである。


治らず

APIが重い現象は解決せず。しかし心なしか、完全にタイムアウトするというのは減り、待てばレスポンスが帰ってくる感じになった。とりあえず待ち行列にちゃんと入ってくれたか。


そもそも待ち行列が溢れているの?

待ち行列がどれくらいになっているのか、確認する手段を知らなかったので、Apacheのserver-statusをみれば書いてあるかもと推測して見てみた。

ここで(個人的には)衝撃の出力を見た。

285 requests/sec - 16.3 kB/second - 58 B/request

600 requests currently being processed, 0 idle workers
KKWKKWKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKKKKKKKKKKKKKWKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKWKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKWKKKKKKKKKKKKKKWKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK
KKKKKKKKKKKKKKKKKKKKKKKK
Scoreboard Key:
"_" Waiting for Connection, "S" Starting up, "R" Reading Request,
"W" Sending Reply, "K" Keepalive (read), "D" DNS Lookup,
"C" Closing connection, "L" Logging, "G" Gracefully finishing,
"I" Idle cleanup of worker, "." Open slot with no current process

こんな出力初めてである。Kってなんだ?  なるほど、KeepAlive・・・ え? 切ってあるはずでは?


設定変更したら

KeepAlive Offを明示的に書いたら、API爆速になった。辛い。


なぜこのような設定が入ってしまったか

ansibleで設定していて、group_varsでOn/Offを管理(しているつもりだった)


修正前


group_vars/api/httpd_vars.yml

IS_KEEPALIVE: "false"



conf/extra/httpd-default.conf.j2

{% if IS_KEEPALIVE == "true" %}

KeepAlive On
{% endif %}

なぜこれじゃダメかというと、Apacheのデフォルト設定(明示的に書かなかった時の設定)がOnなので、Offにしたかったら明示的に書かないといけない。

参考: https://httpd.apache.org/docs/2.2/ja/mod/core.html#keepalive


修正後

{% if IS_KEEPALIVE == "true" %}

KeepAlive On
{% else %}
KeepAlive Off
{% endif %}

これで、大丈夫。

設定当時、Apacheのデフォルトの値を確認するのを怠ってしまったと思われる。なんとなくKeepAliveはデフォルトOffのイメージだったので、それでOnにするときにだけOnを書けばいいと思ったのだろう(と推測)。この分岐を入れる前はKeepAlive Offがベタ書きされていたが、分岐を入れたときに失敗した。


根本対応はどういうものがありえる?


  • ミドルウェアの設定デフォルト値を必ず確認する

  • そもそもデフォルト値を気にしないでいいように、全ての気になる設定を明示的に書いておく


    • その際に、設定の意図も一緒にコメントとして書いておくのが重要。コメントないと負債。



  • ミドルウェア設定のテストを書いてCI回しておくべき


    • ミドルウェアが居るかどうかのテストコードはあったが、細かい設定まであまり踏み込んでなかった

    • チューニングとして重要なところは多少細くてもテスト書くべき(全ての設定をやるか、と言うと不毛なので微妙)



  • アラートを設定する


    • ApacheのServer-statusを叩いてrequests currently being processedは常に取得していたが、アラートは設定されていなかった

    • zabbixのitem設定、graph設定とともに、たまに邪魔になるかもしれないがtrigger設定もセットで入れるようにする




終わりに


まとめ

思い込みでアクセス増加をトリガーにして障害を起こしてしまった話。

インフラもテスト重要。アラートも勝手に投げられるようにしておこう。


広告

ニコニコ静画ではエンジニアを募集しています。

インフラの仕事でアプリが爆速になる快感を味わえます(自虐)。

真面目な話↓

実はこのボトルネックが解消されたことにより捌けるリクエストが増えてPUSH通知時にDBのコネクション数がつまるところへボトルネックが移動しました(対応中・もしくはこの記事が公開される時には対応済み)。

このように、結構アクセスあるので常に細々問題が発生し、改善を通して成長できる環境です。全く対応できない速度でタスクが発生するわけではないので、個人の改善努力で割と良いものに変えていけます。

というわけで、一緒にインフラ構成改善や作業自動化・チューニングを進めることで爆速サービスを提供していける人を探してます。