【3,4日目】graqt開発日誌 ~PercentileとStddev(標準偏差)~

GitHub Golang ISUCON ISHOCON2

f:id:serinuntius:20180820080328p:plain

「べ、別に土日早起き出来なかったからブログ書けなかったわけじゃないんだからね。。。」

冗談はさておき、土日はISHOCON2やgraqtの開発に力を入れてしまい、記事を書けませんでした。

いろいろ機能が追加されたので、紹介したいと思います。

新機能

Percentileが見れるようになりました

graqtはbetter than alpを標語として、作っているのですが、alpにあるPercentileを移植しました。

P1, P50, P99とかのことです。

なんで、これが必要なのか調べていると、レスポンスタイムの平均(Avg)だけ見てしまうと、スロークライアントの結果に引っ張られる可能性があるからです。

参考 takeshiyako.blogspot.com

Nginxの$request_timeは、nginxがリクエストを受けてからレスポンスをクライアントに返しきるまでの時間なので、変に遅いクライアントが居ないとも限らない・・・。 平均値だと、極端な異常値が少しでもあったばあい、これに引きづられて数字が大きくなったりして、あまり信用できなくなったりします。 測定誤差をできるだけ減らしたいので、平均値ではなくてパーセンタイルを取ろうという考え方です。

ベンチマーカー相手だとあんまり考えなくてもいいかもですが(わざわざスロークライアントになるようなベンチマーカーって過去のISUCONでないよね？)、本番のアプリケーションでは重要ですね。

Stddev(標準偏差)が見れるようになりました

標準偏差も、かなりわかりにくい指標なのですが、こちらの記事にわかりやすく書いてありました。詳しく知りたい方はこちらの記事をお読みください。

atarimae.biz

この機能もalpについている機能で、そのままパクリましたリスペクトして実装しました。

Pathを集約して見れるようになりました

これもalpリスペクトの機能で、alpではAggregate機能として実装されています。

例えばですけど、

/diary/entry/1
/diary/entry/2
/diary/entry/3

こういう感じのリクエストがあると、集約しないとそのまま3行で表示されてしまいますが、設定ファイルに正規表現を書いておくと集約して1行でまとめて表示できます。

graqt.yamlに

aggregates:
  - /diary/entry/\d+

このように書いておくと、集約され表示されるようになります。

実際の例を見たほうがわかりやすいと思うので、貼っておきます。

これが、 f:id:serinuntius:20180820074544p:plain

こうなります！！！ f:id:serinuntius:20180820074624p:plain

けど、これ使うと「一部のページだけ異様に遅い！」みたいなのがあった場合わかりにくいので気をつけてください。

レスポンスボディのサイズが表示されるようになりました

今まで項目としてはちゃんと用意されていたのですが、ロガーの方で取得していなかったので、ちゃんとレスポンスボディのサイズを取得してロガーに載せるようにしました。

f:id:serinuntius:20180820075216p:plain

やったぜ！

ginというフレームワークに(一部)対応しました

ginというフレームワークは、http.Handlerを準拠して作られているわけではないので、それようのmiddlewareを作るしかありませんでした。(たぶん)

個人的には、http.Handlerに準拠しないフレームワークはgo wayじゃないと思っていて、いろいろな制約がつきまとって非常に面倒くさいことになります。

会社の先輩方が、「Go書くときは薄いフレームワークしか使わなくて良い」とおっしゃっていた理由が今回とても身にしみました。

具体的には、Ginのmiddlewareのシグネチャーにあわせて書いてあげるという感じです。めっちゃ処理が増えるとかではないですが、わざわざ1つのフレームワークのためにどんどんを作るのは非常に面倒です・・・。

func RequestIdForGin() gin.HandlerFunc {
    return func(c *gin.Context) {
        t1 := time.Now()

        id := newRequestID()

        c.Set(string(RequestIDKey), id)

        c.Next()

        RLogger.Info("",
            zap.Duration("time", time.Since(t1)),
            zap.String("request_id", id),
            zap.String("path", c.Request.RequestURI),
            zap.String("method", c.Request.Method),
            zap.Uint64("content_length", uint64(c.Writer.Size())),
        )

    }
}

https://github.com/serinuntius/graqt/blob/master/middleware.go#L38-L57

今回は、ISHOCON2でGinが利用されていたので、実装せざるおえませんでした。

一部対応と書いたのは、クエリのロガーの方で、contextに仕込んでいるはずのrequest id(uuid)が取れてないので、クエリのログは出ているのですが、紐付けることができていません 。たぶん、改善できるはずなので、いずれ改善いたします。

まとめ

やっぱり、実際のISUCON(ISHOCON2)を解きながら、graqtの開発をすると、

「うおぉぉぉぉ〜、この情報知りたいんだけどぉ！！！！」

とか

「ginに対応してないやん！！！対応せねば！！」

みたいな気持ちがわいてきて、モチベーションになりやすいです。

どんどん開発して、素晴らしいソフトウェアにするので、今後共よろしくお願いいたします。