ICTSC Tech Blog

ICTSC2024 二次予選 問題解説: [MNG] MongoDBってなんですか？

ICTSC2024 問題解説

問題文

I社の新人のあなたは、昼過ぎにあるアプリケーションのアラートを受け取った。
どうやら、あるデータベースでエラーが散発しているようだ。
先輩に聞いてみたが、どうやら先輩もアプリケーションやデータベースの構成に詳しくなく、調査するように頼まれた。アプリケーションもはるか昔に書かれたもので、詳しくない人が書いたらしいが……

どうやらMongoDBというデータベースが使われているとのことだが、とりあえず調査してみよう。

前提条件

  • 特にありません
  • どうやらI社の人はこのデータベースについてあまり詳しくないようであり、諸々の設定に意図があるのかどうかはわかりません

初期状態

  • ホストにログインすると、ホームディレクトリに ictsc-2024-problem-mng というバイナリが存在します
  • これを(どれか1台のVMで)実行しながら、別のコンソール等でVMへ接続し、以下に示すような操作を行うと確率的にエラーが生じることが確認できます
    • 場合によっては連続で成功することもありますが、しばらく(10回〜20回ほど)続けていると問題が再現するはずです
    • もし再現しない場合には質問として運営へ問い合わせてください
$ ./ictsc-2024-problem-mng
(特に何も表示されない)

$ mongosh "mongodb://mng-01,mng-02,mng-03/ictsc?socketTimeoutMS=200"
rs0 [primary] ictsc> db.data.updateOne({i: 3, j: 30}, {"$set": {t: +(new Date)}})
MongoNetworkTimeoutError: connection 9 to 192.168.255.81:27017 timed out

なお、 socketTimeoutMS=200 はこのクエリを実行するのに通常掛かるであろうレイテンシの数倍としています。

終了状態

初期状態で提示したエラーがなぜ生じているのかを調査・考察し、その原因と解決策について、1000字以下(コマンドのアウトプット等は除く)で説明してください。

(1000字という字数は、過剰な時間を掛ける必要はないという程度の意味合いです。例えば400字だから一概に減点するというようなことではありません)

解説

本問題はMongoDBにおけるトラブルを題材にしましたが、MongoDBという固有のデータベースエンジンへ詳しいことを問うものではなく、典型的なデータベースのパフォーマンス問題におけるトラブルシューティング能力、またドキュメント等の調査を通した説明力を問いました。

問題環境

今回出題した問題環境は、次のようなものでした。

  • 3台のVMが稼働している
    • VMはそれぞれ1vCPU, 1GiBのリソースが割り当てられている
    • ホスト名は mng-0x (x: 1,2,3)
  • MongoDB 8.0によるレプリカセット構成が組まれている
    • rs.initiate() コマンドで構成されたものであり、特に特殊な要件などは設定されていない
  • トラブルを発生させる ictsc-2024-problem-mng (以下問題バイナリと表記)というバイナリファイルが用意されている
    • このバイナリは MongoDB に対して大量の読み書きを行っていました。具体的には以下の操作を無限ループしていました。
      • コレクションを生成→100,000件のレコードを挿入→5万件のレコードを削除→100,000件のレコードを挿入→5万件のレコードを削除→コレクションを削除
      • このバイナリでは、 MongoDBへの接続時にwriteConcernの値として w=3 を指定していた
    • ソースコード: https://gist.github.com/kyontan/0f5d1a54b51d0864ecf62fb1952e9bb5

トラブルは、上記の問題バイナリを実行しているとき、db.data.updateOne()のような単純なクエリであっても散発的にタイムアウトが発生するというものでした。

解説

結論から言うと、今回のトラブルは以下のような要因の組み合わせにより発生していました:

問題プログラムの実装が不適切(かもしれない)

ほぼ自明ではありますが、本問題ではこれによりトラブルが発生していることからこのプログラムが適切な実装になっているかどうか、というのは指摘してほしいポイントでした。

開催中に改善しえることではないものの「実装を見直しパフォーマンスを改善する」などを提案することができたでしょう。

タイムアウト時間が短い

問題文で示した書き込みエラーの発生例を再掲します:

$ mongosh "mongodb://mng-01,mng-02,mng-03/ictsc?socketTimeoutMS=200"
rs0 [primary] ictsc> db.data.updateOne({i: 3, j: 30}, {"$set": {t: +(new Date)}})
MongoNetworkTimeoutError: connection 9 to 192.168.255.81:27017 timed out

このエラーから、db.data.updateOne()コマンドの実行がタイムアウトしたことで成功していないことが読み取れます。

また socketTimeoutMS という見慣れないパラメータが登場しますが、これはドキュメント( https://www.mongodb.com/ja-jp/docs/manual/reference/connection-string-options/#mongodb-urioption-urioption.socketTimeoutMS )を参照するとクエリ実行のタイムアウトを指定しているものであることが分かります。

問題文で示したように、この設定値は問題バイナリを実行するという通常でない事象が発生したことにより問題が起きていることを分かりやすく示すために与えられたものであり、この設定値の是非については問うていませんでした。

writeConcern の設定値

上述の通り、問題バイナリはMongoDBの接続時に w=3 という writeConcern を設定していました。
詳細な説明はMongoDBのドキュメントを参照して頂ければと思いますが、簡潔に説明するとこの設定値は書き込みのクエリ時に3台の書き込み完了を同期的に待ってから完了とするものです。
writeConcernのデフォルト値は w=majority であり、過半数、つまり今回の構成では2台の書き込みが完了すれば完了とみなすものでした。

w=3という設定値はデフォルトより高いデータの信頼性を要求するものであり、負荷を大きく上昇させる一因となっていました。

問題バイナリのソースコードは公開されていなかったため、この問題に気付くためには問題バイナリの実行中にどのようなクエリが実行されているかを確認する必要がありました。

MongoDBではdb.currentOp()コマンドにより実行中のクエリを確認することができます。これはMySQLのshow processlistやPostgerSQLのselect * from pg_stat_activityに相当するものです。

実際に実行すると、以下のような結果が得られたはずです:

rs0 [primary] ictsc>  db.currentOp().inprog
[
  {
    type: 'op',
    op: 'insert',
    ns: 'ictsc.data',
    command: {
      writeConcern: { w: 3 },
      ...
    },
    ...
  },
  ...
]
rs0 [primary] ictsc>

このコマンドの出力は長いのですが、注意深く確認すると他のクエリ(例えば問題文中で示されているdb.data.updateOne())の実行中に表示されるものと違い、commandオブジェクトの中にwriteConcern: { w: 3 }という項目があることが確認できます。

ここからドキュメント( https://www.mongodb.com/ja-jp/docs/v8.0/reference/write-concern/#replica-sets )を参照することで、デフォルト値と違う設定値の存在、およびこの設定値がパフォーマンスに影響を与えうることを指摘できるものでした。

一方で、上で述べたようにこの値を変更することはデータの信頼性が低下することを理解して行う必要があり、何も考えずに変更すればよいものではありません。
よって、この設定値を変更することによるトレードオフについて言及できているかどうかは採点ポイントとなっていました。

CPU,メモリのリソース不足

3台のVMがいずれも1vCPU, 1GiBのリソースしか割り当てられておらず、問題バイナリを実行することによりリソースに余裕がない状態になっていました。
リソース不足についてはtopコマンド等で調査可能でした。

これは予選中には解決できないものの、リソースの追加により改善が可能でした。

インデックスの設定不足

問題文で示したコマンドはiおよびjフィールドの値が一致するレコードの値を更新するものであり、これらのフィールドにインデックスが指定されていればパフォーマンスの改善によるトラブルの解決が期待できます。

なお本問題では上述の writeConcern の設定値に気がついてほしいという意図から、仮にインデックスを作成することで一時的に問題が解決したとしても、問題バイナリで定期的にコレクションの削除を行うことで、これが唯一の原因ではないことを暗に示していました。

(コレクションの削除時には当該コレクション上のインデックスも同時に削除されます)

採点について

想定回答

本問題は上述した複数の原因が重なったことにより発生したものであり、与えられた環境下でトラブルを完全に解決することは不可能です。

また、本問題はエラーをどのように解決してほしいのかを意図的に指示しておらず、オープンクエスチョンとしての性質が強いものでした。
よって、トラブルの原因を推測し、調査・考察し、どのような手段で解決しえるのか、なぜ解決しえるのかを順序立てて、論理的に説明する能力を問うていました。

よって、想定回答としては「問題プログラムを動かすとなぜかトラブルが発生する」というところから、問題プログラムが何をしているのかを調査し、上述のような原因を指摘したうえで、どのような変更により解決しうるのかを順を追って説明することを求めていました。

講評

全24チームの回答のうち、上述したトラブルの構成要素を指摘したチームは以下の通りです。
(採点後しばらくしてから書いているため、数は正確でない可能性があります)

  • 問題プログラムの実装が不適切(かもしれない): 0件
  • タイムアウト時間が短い: 3件程度
  • writeConcern の設定値: 5件
  • CPU,メモリのリソース不足: 2件程度
  • インデックスの設定不足: 2件程度

残念ながら、ほとんどの回答において「どのような調査によりそれが原因であると考えたのか」「なぜその方法によりトラブルが解決しえるのか」といった情報を筋道だてて説明できていませんでした。

例えば「リソース不足が原因である」という場合にも、現在割り当てられているリソースはどのようなコマンドで確認でき、その結果がこうである。ドキュメントより推奨値としてこの値が求められているために不足している、というような主張を行っている回答はほとんど見られず、単に「メモリが不足している」というような説得力に欠けた回答が見られました。

採点基準

全回答を見たうえで、以下の基準により採点を行いました。

  • 10点: ログかメトリクスを眺めた形跡を回答文において示しているもの
    • 「再起動により解決した」などの証拠を示していないものは除く
  • 75点: writeConcern に関する言及、問題の解決をしえる回答であると判断したもの
  • 100点: writeConcern (および変更におけるトレードオフ)に関して指摘した上で解決策を提示している

また、上記の基準を満たしているが回答の説明が不十分である(調査手段や原因の説明がないまま解決手法を示しているもの、事象が解決しているがその設定値によるデメリットを示していないもの)については個別に10点から25点(重複適用あり)の減点を行いました。

なお、「問題文に記載されているコマンドのタイムアウト値を伸ばすことにより問題が解決した」という趣旨の回答がいくつか見られましたが、これは問題文に記載しているコマンドによる事象が解決していないことから題意にそぐわない回答であるとみなし配点を与えていません。

また、インデックスの作成による解決を試みたチームや wtimeout の設定を行った回答についても、本来の題意とは異なりますが、問題の解決に寄与し得たものとして部分点を付与しています。

点数の分布

全38チーム中、回答は24チームからありました。

点数の分布は以下の通りです:

  • 回答なし: 14チーム
  • 0点: 3チーム
  • 10点台: 7チーム
  • 50点台: 3チーム
  • 60点台: 1チーム
  • 70点台: 5チーム
  • 90点台: 5チーム
  • 100点(満点): なし