ISUCON9 予選で Cloud Trace 使った

id:hitode909 と id:tkzwtks と「ミッシングマグネティックストレージ」チームで出たけど予選敗退となった。最終スコアは5110点で、瞬間最大風速でも6700点ぐらい。

今回は Cloud Trace を投入してあれこれやってて悪くなかったのでそれについて。

f:id:side_tana:20190909205504p:plain

練習のときにつかってみて悪くないねということになったので投入した。Express だと import するだけでそれっぽく使えるのだけれど、8 の予選問題をみたところ fastify が使われているようで、一工夫必要だった。一工夫っていうのは

// setup cloud trace
const tracer = require('@google-cloud/trace-agent').start()
const fastify_connect = function(method: string, path: string, option: Object, callback: any){
  if (process.env['ENABLE_CLOUD_TRACE'] === "true") {
    fastify[method](path, option, async (req: FastifyRequest, reply: FastifyReply<ServerResponse>) => {
        tracer.runInRootSpan({ name: method + ":" + path }, async(rootSpan) => {
        try {
          await callback(req, reply)
        } catch (e) {
          rootSpan.endSpan();
          throw e;
        }
        rootSpan.endSpan();
      })
    });
  } else {
    fastify[method](path, option, async (req: FastifyRequest, reply: FastifyReply<ServerResponse>) => {
      await callback(req, reply)
    });
  }
}

みたいなラッパを用意して、すべてのハンドラをのラッパ経由に書き換える、みたいな感じ。env.sh の ENABLE_CLOUD_TRACE を書き換えることでバイパスできるようにしてある。このラッパはひとでさんがアイデアくれました。

この状態でベンチを回すと Cloud Trace に mysql にクエリを送ったタイミングが記録される。たとえば post /login であれば

f:id:side_tana:20190909210735p:plain

こんなふうに記録すされ、スタックを見ると 2064: const [rows] = await db.query("SELECT * FROM `users` WHERE `account_name` = ?", [accountName])は一瞬で終わっているのにその後の処理でかなり時間を食っていることからハッシュ計算がボトルネックになっていることが推察できる*1。

苦しめられた /buy はこんな感じ。

f:id:side_tana:20190909211232p:plain