こんにちは。西日本テクノロジー＆イノベーション室の金山です。

「行けたら行く」、「機会があれば是非」が口癖です。

今回は機会があったので、2年半ほど前に利用者1000人を超えるRedmineに起きた問題を解決したことと、そこから学んだことについてお話しをします。

何が起きていたか

当時、システム開発を行うにあたって課題管理やチーム間のQAを1台のRedmineに集約していました。

このRedmineは社内サービスとしてVPNにて提供しているサーバにあります。このサーバは他にもソースコード管理（SVN）や認証サーバ（LDAP）などシステム開発に必要なサービスを有しています。

登録しているユーザーは1,000人を超え、チケット数も23,000件ほどあり、情報をまとめる場所としてなくてはならない存在になっていました。

しかし、ある日Redmineにアクセスしようとしても「The website is under heavy load」というエラー画面を返し、アクセス不可となる事象が1時間ほど続きました。

アクセス不可となる事象はほぼ毎日のように発生します。

チームリーダーの会議で課題の方針を決める際にも使用していたため、課題共有ができない・課題の方針を決める会議が開けないという事態になり、仕事にならず緊急でサーバを再起動することも何度もありました。

サーバの再起動にも30分程度かかるだけでなく他のサービスも使えなくなりますが、このときは原因がわからなかったため緊急対応でさえ何を行えばよいかわからずこの方法が確実でした。

やってしまったこと

毎日のように発生する上、進捗に影響が出てしまうため、調査と対応をする流れになります。

そこで最初の調査では「Redmineが稼働しているサーバではSVNも稼働しているため、アクセス過多になったのではないか」という仮定を置いて、調査することにしました。

Apacheのアクセスログを解析して、「いつ」「なにに対して」「どれだけ」リクエストがあるかを調べることで、「アクセス不可となった時間帯はアクセスがかなり多く、平常時の三倍近いアクセスがありました」というような報告となる想像をしていました。

しかし、実際にはSVNやRedmineのアクセス量が少なくても事象は発生していましたし、アクセスがかなり多いときでも問題なく使える場合もあったという事実が判明します。

ポジティブに捉えるならば「アクセス量に関係なく発生する事象ということがわかった」と言うべきでしょうが調査方針がなくなりかなり戸惑っていました。

何がよくなかったか

初めに考えていた仮定が潰えてしまいましたが、「まったくわからないですね」で終わらせるわけもなく原因調査を継続します。

振り返ってみると最初の仮定は、「The website is under heavy load」という画面に出ているエラーメッセージしか見ずに見切り発車で調べていたということに思い至りました。

そもそもこのエラーメッセージが

  • 誰（Apache？Redmine？）が出しているのか
  • どういうときに出しているのか

ということを一切調べずに調査を開始していたのです。

そこで上記の内容を調べて、次のことがわかりました。

調査して見えてきたこと

メッセージを出しているのは、PassengerというRedmineを動かしているApacheのモジュールでした。

このPassengerが新しいリクエストを受け付けたときにアプリケーション（Redmine）のプロセスがすべて処理中の状態だとキューに溜め、キューの上限を超えると503エラーを返します。

今回発生していた事象と照らし合わせて考えると、「長い時間処理中となるようなリクエストでプロセスが埋まり、後続のリクエストが処理できずキューを埋め尽くしていた」という見切り発車ではない事実と仕様に基づいた仮定が生まれました。

そこで、新たに「長い時間処理中となるようなリクエストを見つける」という調査方針ができました。

ようやく見つかった原因

原因となるリクエストを調査するにあたってApacheのアクセスログだけでは、Redmineのプロセスがどれだけリクエストの処理にかかったのか、キューでどれだけ待っていたのかがわかりませんでした。

そこでApacheのアクセスログとRedmineのログを合わせて、リクエストの内容、リクエストの処理にかかった時間、キューで待っていた時間を一覧にするツールを作成しました。

蛇足ですがこのツールは1日分（1万件程度）のリクエストを処理するのに、20分程かかる激重ツールになってしまいました。1、2回使って終わりの予定だったので重いまま使いました。

そうして出てきた一覧からRedmineのプロセスが1時間ほど処理中になるようなリクエストをついに発見することができました。

原因はチケットの検索でした。

Redmineのソースコードを読んでわかったことですが、チケットを検索する際に検索キーワードが数字のみの場合チケットのIDを検索し、数字のみでない場合チケットの内容で検索するようです。

これは想像になりますが、チケットの件数が増えすぎたため検索にかかる時間が増えたと考えられます。

対策

原因がチケット検索による待機リクエストの圧迫とわかったので、いくつか対策が考えられます。

① チケット検索をさせない。
② 検索が早くなるようにRedmineないしDBをカスタマイズする。
③ 待機リクエストが出ないくらいにサーバを増強する。

このうち③は、検索を連打しているログがあり、どれだけリクエストを処理できるようになっても処理に1時間かかるリクエストが大量に発行されては無意味なので早々に取り下げました。

②については、この時点では調査～対応にどれだけ時間がかかるかわからないため取り下げました。1,000人ほどのユーザーが仕事にならない時間があるといういことへの影響がかなり大きく、早急の対応が必要だったためです。もちろん、原因が分かった時点でチケット検索を行わないように展開をしたものの浸透はしていないという状況もあったと思います。

そのため①の対策を取ることになりますが、単純にチケット検索ができないと不便極まりないです。チケット検索を行う人がいるからRedmineがアクセス不可になっていたわけなのです。私は初め「チケット検索はすべてエラーで返す」、ないし「検索キーワードの入力、検索ボタンを表示しない」とする対応をしようとしていました。これは大いに反省です。

最終的には、

  • チケットの内容をすべてCSVで出力したファイルをファイルサーバに置き、検索は自分のPC上で行う。
  • チケット検索については、数字（チケット番号）での検索のみ許可。（上記で見つけたチケット番号を張り付けるため。）

という対策を取りました。

CSVファイルの出力は毎朝誰も仕事をしていない時間に行い、検索の許可設定についてはApacheでリクエストの内容を確認し検索内容が数字のみの場合許可するようにしました。

まとめ

結果として、利用者1000人を超えるRedmineのアクセスが毎日1時間以上不可となる事象を撲滅することができました。2週間ほどで対応を完了しています。

この対応を行って、わかっていることを整理して何をするのか考えることがとても重要だと感じました。見切り発車だけでは、まったくわからないという状況を脱することができなかったでしょう。

本コンテンツはクリエイティブコモンズ(Creative Commons) 4.0 の「表示—継承」に準拠しています。