私が問題解決で意識していること

末廣雅利（スエヒロマサトシ）

2004年入社のシナジーマーケティング最古参のインフラエンジニア。
コロナ禍のステイホームでピアノを習い始めたものの、なかなか上達しなくて悪戦苦闘中。

はじめに

皆さんは、障害や不具合などの問題解決は好きでしょうか？それともできれば関わり合いたくないものでしょうか？

私は大好物です。迷宮入りしそうな問題の原因を究明してズバッと解決できたら気持ちいいですね。

エラーメッセージや事象でググってそれらしいものが引っかからなければお手上げという方もいらっしゃるのではないでしょうか。そういう方の参考になるかどうか分かりませんが、私が問題解決に取り組むときに意識してやっていることをまとめてみます。

問題解決で意識していること

私が問題解決に取り組む際に意識してやっていることは次の二つです。

情報を集める
情報をもとに仮説を立てる

情報を集める

問題を理解しないことにはその原因を究明して解決することはできません。問題解決の第一歩はその問題に関する情報をできる限りたくさん集めることです。

まずは、ログや各種メトリクスを調査します。問題の事象と関係や相関のありそうなものがないか片っ端から見ていきます。対象は問題が発生しているコンポーネントだけとは限りません、例えばアプリケーションサーバで問題が発生している場合、必要とあらばDBサーバやネットワーク機器なども調査します。

事象が継続していたり再現できる場合は、tcpdump, strace, perfなどを利用して情報を収集します。Javaで動いているものであればスレッドダンプを取得します。

ソースコードも情報源になります。エラーメッセージを手がかりにソースコードの場所を特定して読んでいくと、どのような条件でそのエラーが発生するのかを知ることができます。また、ログメッセージを理解するのにも役立ちます。例えば、sshdの意味不明なこのログ出力も

sshd[26394]: debug3: channel 0: status: #0 server-session (t4 r2 i3/0 o3/0 fd -1/-1 cc -1)\r\n

対応するソースコードを見つけると、なんとなく理解できます。

snprintf(buf, sizeof buf,
    "  #%d %.300s (t%d r%d i%u/%d o%u/%d fd %d/%d cc %d)\r\n",
    c->self, c->remote_name,
    c->type, c->remote_id,
    c->istate, buffer_len(&c->input),
    c->ostate, buffer_len(&c->output),
    c->rfd, c->wfd, c->ctl_chan);

仮説を立てる

情報がある程度出揃ったら、事象を説明できる仮説を考えます。少ない仮定で多くの事実を説明できるのが良い仮説です。

この仮説を考える過程で要素技術を詳細に調べたり、公式ドキュメントやソースコードに当たったりするので、良い勉強になります。もうこれだけでも十分に楽しいですね。

仮説を立てることができれば、その仮説に基づいて情報を見直したり、さらに新たな情報を収集したりして検証していきます。そして、仮説をもとに再現を試みたり、解決方法を考えて実行します。これらがうまくいけば問題は解決です。

検索について

Web検索はどの段階でも役に立つのですが、事象をきちんと把握し、仮説を持った上で検索すると精度が上がります。ピント外れの記事に惑わされることがなくなり、数多の記事の中から有用な情報を得やすくなります。

問題解決の例

抽象的な話だけだと分かりにくいでしょうから、具体的な事例をあげてみます。

ボトルネックを突き止めろ

これはperfでボトルネックを突き止めた例です。

とあるシステムではログ転送にfluentdを使っているのですが、集約側のパフォーマンス不足でログが遅延したり、待機系に切り替わったりすることがしばしばありました。fluentdはデフォルトではひとつのWorkerで全てのログを処理するので、シングルコアCPU性能で処理能力が制限されてしまいます。マルチWorkerで動作させるとこの問題を回避できるのですが、そうするとログが複数ファイルに分散して利便性が下がってしまうので、どうしたものか悩んでいました。

perfでcall graphを表示してみたところ、rb_parser_compile_string_pathで30%近くの時間を消費していることが分かりました。これはRubyのコードをパースする関数です。

    |--49.15%--0x28fb74
    |          |
    |          |--29.43%--0x2781ac
    |          |          |
    |          |           --29.37%--rb_parser_compile_string_path
    |          |                     |
    |          |                      --28.54%--0x299f1c
    |          |                                |
    |          |                                |--25.76%--0x19c19c

どうやらレコードを処理する度にRubyのコードをパースしているようです。ここで、fluentdのrecord_transformerのドキュメントに次の記述があったことを思い出しました。

By historical reason, enable_ruby true is too slow. If you need this option, consider record_modifier filter instead. See also Need more performance? section.

record_transformerのソースコードを読むと、レコードを処理する度にinstance_evalしています。record_modifierは初期化時にメソッド化してしまうのでこのオーバーヘッドはありません。

record_modifierでは提供されない機能があるとのことだったので、調査が億劫で試していませんでしたが、30%近くパフォーマンスが改善するなら話は別です。調査したところ、このプラグインが提供しない機能は特殊で、我々が利用していないものであることが分かったので、プラグインを変更しました。

変更後の負荷は半減しました。実はcompileなどの処理でも20%程度使っていたため想像以上の効果が得られました。

fluentdの公式ドキュメント内でPerformanceで検索すれば辿り着けた解決方法なのですが、当てずっぽうではなく効果があることをある程度予測した上で実施できたことはよかったと思います。また、この調査で初めてperfを使ったので勉強になりました。

おわりに

私が問題解決に取り組むにあたって意識している2つのことについて書いてきました。

情報を集める
情報をもとに仮説を立てる

仮説が当たって問題を解決できると嬉しいですが、たとえ外れても仮説を考える過程で学べることは多いです。一緒に楽しく問題解決できる人が増えたらいいなと思います。

TECHSCORE BLOG

クラウドCRMを提供するシナジーマーケティングのエンジニアブログです。