dockerのコンテナを楽に選択するpecoを使ったalias

ブログ書くの怠ってたから、カジュアルにアウトプットしていくぞ!!!

本題

環境

  • peco
  • zsh(zshのグローバルエイリアスという機能を使っているみたいなのでzshしかできないと思います。)
  • docker

手順

~/.zshrc に以下を書くだけ

alias -g C='`docker ps -a|peco| cut -d" " -f 1`'

使い方

  • docker logs C
  • dcoker exec -it C bash

これぐらいしか思いつかないけど、まあ便利

go run main.goとすると別ファイルのmainパッケージのグローバル関数がundefinedで怒られる

めっちゃ久しぶりのブログになってしまった。

書くことなんか何個でもあるのに、バタバタしてたりでアウトプットを疎かにしていた。(言い訳)

本題

少し前から気になってたことだったんだけど、go run main.go で実行すると、mainパッケージの別ファイルのグローバルな関数の呼び出しができない。

github.com

最小構成のリポジトリを作った。

これを、適当にcloneして、 go run main.go すると実行できない。

解決策

buildする。 go build -o main && ./main で buildすると実行できる。

どうしてもgo runしたいときの解決策

1. go run main.go lib.go ファイルを列挙する

ルートにファイルが増えると面倒なので、できたらやめたほうがいいと思う。

2. go run *.go *でごまかす

この方法は楽なんだけど、テストのファイル(例) main_test.go)があると破綻する。

同じようにハマってる人がいた

stackoverflow.com

この件で不思議なのは、main以外のパッケージだと普通に読み込めるところ。 例えば、こういう構成だったら大丈夫。

root/
  --- main.go
  --- lib/
  ------ hello.go

この場合は import "host/username/root/lib" というふうにimport文を書くからそこから解決して実行できるんだろうな(想像)

これ、初めて遭遇したときはびっくりするんだよな。

kamakura.go #4 に登壇しました!

昨日(2018年5月25日)行われた、kamakura.goのLTで以前から書いているGoのパッケージであるgraqt(がらくた)の紹介をしてきました。

前回のgraqtの記事

serinuntius.hatenablog.jp

発表資料

speakerdeck.com

登壇後に質問されたこととか

(あいまいな)記憶と #kamakurago のハッシュタグを辿りながら書いてます。

Q. トレーサーのオーバーヘッドは? 5%以下の性能低下なら、良いよねってなんかの本で書いてたよ〜。

A. 実際、オーバーヘッドはあります。以前検証したベンチマークでは、以下のようなことがわかっています。

1リクエストで発行クエリが増えれば増えるほど、オーバーヘッドは大きくなる。(当たり前ですが)

1リクエストで、1クエリーだった場合のオーバーヘッドは、

  • ログあり1547.08 Requests/sec
  • ログなし1607.31 Requests/sec

1547.08 / 1607.31 * 100 = 96.25274527 となり、5%以下になっている。

しかし、1リクエストで、100クエリーだった場合のオーバーヘッドは、

  • ログあり 58.89 Requests/sec
  • ログなし 54.56 Requests/sec

で、

54.56 / 58.89 * 100 = 92.6473085413 となり、5%を超えてしまっている。

便利そうですね。応援しています。

ありがとうございます。そういってもらえて嬉しいです。

まとめ

今後もGo書いてくぞ。

【追記アリ】Golangで1行1行がJSONのログを効率的にパースする

この記事でも書いたけど、ISUCON用のロガーを作ったので、そのログをパースするツールを書こうと思った。

serinuntius.hatenablog.jp

少しパフォーマンスを意識して書いてみたけど、きっともっとパフォーマンスが良くなる気がするのでマサカリウェルカムです。

続きを読む

Go専用対ISUCON兵器 「graqt」を書いた

f:id:serinuntius:20180430224626p:plain

はじめに

この記事でも書いたけど、最近ISUCONの面白さに気づいた。 serinuntius.hatenablog.jp

社内ISUCONはRubyで書かれていたけど、本家ISUCONでは使用言語が選択できる。 そうなったら、今なら迷わずにGoを選ぶ

それは、何故かと言うとGoが速いとかそういう理由よりも、GolandというIDEのおかげである。 こいつの補完やらなんやらがとても良くできているので、ソースを読むのも書くのも爆速になるからである。

RubyにもJetbrains製の Rubymine というのがあるけれど、動的言語だからか完全にはコードジャンプできない。 同名のメソッドがあったときには、選択肢が出てユーザにどのメソッドですか?みたいな感じで問いかける感じ。

けど、Golandは型があるからか100%の精度でコードジャンプできる。 そのおかげで、爆速コードリーディングが可能になる

Golangが最高という話はおいておいて、Go用のクエリのロガーとアクセスログを出すミドルウェアを書いたので、その説明をしたいと思う。

graqtとは

github.com

go-request-and-query-loggerです。*1

発音は、 グラクトか、ガラクタでお願いします。

僕はガラクタって読んでるw*2

Go用のアクセスログとクエリのログを記録するためのhttp handlerミドルウェアです。*3

主にISUCONで使うだろうな〜と思って書いたけど、全然普通のプロジェクトでも使えば便利そう。

alpとpt-query-digestを合体させたものが作りたいな〜というのが、この構想の始まり。

どんなログが出るの?

access.log には 主に time, request_id, path, method が記録される。

  • time => このリクエストにかかった時間
  • request_id => 1リクエストごとにユニークなid
  • path => リクエストされたpath
  • method => GET, POSTとか
{"level":"info","ts":1525082389.1337767,"caller":"graqt/middleware.go:25","msg":"","time":0.011566198,"request_id":"5914e629-6746-42c5-b342-702f224f48e1","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.2157433,"caller":"graqt/middleware.go:25","msg":"","time":0.003945689,"request_id":"4e743b2a-59be-4692-b36b-3b6a9ba78b01","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.2983494,"caller":"graqt/middleware.go:25","msg":"","time":0.014426681,"request_id":"f1d68fb3-5450-48f3-9f46-1ea5ad2370fb","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.3756797,"caller":"graqt/middleware.go:25","msg":"","time":0.004002398,"request_id":"e727db2b-df12-410c-91a4-4dd3117b9452","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.47504,"caller":"graqt/middleware.go:25","msg":"","time":0.005889232,"request_id":"57df4708-9705-4401-98b2-fad4bacfe585","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.554212,"caller":"graqt/middleware.go:25","msg":"","time":0.016009073,"request_id":"58957516-c7b2-4f64-8889-b39496e6597f","path":"/user","method":"POST"}

query.log には 主にquery,args, time, request_id が記録される。

  • query => クエリ
  • args => prepareステートメントだと、その引数が入る
  • time => そのクエリにかかった時間
  • request_id => さっき↑で出てきた、リクエストごとに一意のid。これのおかげで、どのリクエストでどんだけのクエリが呼ばれるかを調べるという寸法
{"level":"info","ts":1525082389.1336403,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389130688404@hoge.com"},{"Name":"","Ordinal":2,"Value":57}],"time":0.001157627,"request_id":"5914e629-6746-42c5-b342-702f224f48e1"}
{"level":"info","ts":1525082389.215664,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389213632765@hoge.com"},{"Name":"","Ordinal":2,"Value":37}],"time":0.002013919,"request_id":"4e743b2a-59be-4692-b36b-3b6a9ba78b01"}
{"level":"info","ts":1525082389.2982852,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389287262677@hoge.com"},{"Name":"","Ordinal":2,"Value":74}],"time":0.011005944,"request_id":"f1d68fb3-5450-48f3-9f46-1ea5ad2370fb"}
{"level":"info","ts":1525082389.37562,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389372293507@hoge.com"},{"Name":"","Ordinal":2,"Value":64}],"time":0.003297617,"request_id":"e727db2b-df12-410c-91a4-4dd3117b9452"}
{"level":"info","ts":1525082389.474928,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389470871128@hoge.com"},{"Name":"","Ordinal":2,"Value":73}],"time":0.001937477,"request_id":"57df4708-9705-4401-98b2-fad4bacfe585"}
{"level":"info","ts":1525082389.5541484,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389550824448@hoge.com"},{"Name":"","Ordinal":2,"Value":39}],"time":0.001194376,"request_id":"58957516-c7b2-4f64-8889-b39496e6597f"}

使い方

変更しなくちゃいけないだろうな〜というところにコメントしておいた。簡単に移行できるはず。

package main

import (
    "database/sql"
    "fmt"
    "math/rand"
    "net/http"
    "os"
    "time"

    _ "github.com/go-sql-driver/mysql"

    // 2つパッケージを追加してください
    "github.com/justinas/alice"
    "github.com/serinuntius/graqt"
)

var (
    // 2つ変数を追加してください
    traceEnabled = os.Getenv("GRAQT_TRACE")
    driverName   = "mysql"

    db *sql.DB
)

func init() {
    rand.Seed(time.Now().UnixNano())
}
func main() {

    // ifを追加して 環境変数 GRAQT_TRACEが1のときだけログを吐きます。
    // ISUCONで本番ベンチのときは オフにしておいたほうがいいと思います。
    // しかし、パフォーマンスには結構気を使ったので、そんなに低下はしないと思います。
    if traceEnabled == "1" {
        // driverNameは絶対にこれでお願いします。
        driverName = "mysql-tracer"

        // もし、ログを吐く場所を変えたかったら以下のメソッドを呼んで下さい。
        // デフォルトは、 query.logとrequest.logが このGoファイル(main.go)と同じディレクトリに出ると思います。
        // graqt.SetQueryLogger("log/query.log")
        // graqt.SetRequestLogger("log/request.log")
    }

    var err error

    // ここを先程の変数に変更してください
    db, err = sql.Open(driverName, "root:@/graqt")
    if err != nil {
        panic(err)
    }
    defer db.Close()

    mux := http.NewServeMux()
    mux.HandleFunc("/user", createUser)

    // ミドルウェアを追加します。
    var chain alice.Chain
    if traceEnabled == "1" {
        chain = alice.New(graqt.RequestId)
    } else {
        chain = alice.New()
    }

    // ミドルウェアを渡します
    http.ListenAndServe(":8080", chain.Then(mux))
}

func createUser(w http.ResponseWriter, r *http.Request) {
    // contextを使用する方のメソッドに変えてください。
    ctx := r.Context()
    stmt, _ := db.PrepareContext(ctx, "INSERT INTO `user` (email,age) VALUES (?, ?)")
    t1 := time.Now().UnixNano()
    age := rand.Intn(80)

    stmt.ExecContext(ctx, fmt.Sprintf("hoge%d@hoge.com", t1), age)

    w.Write([]byte(`ok`))
}

仕組み(ミドルウェア側)

まずはhttp handlerのミドルウェアの説明から。

http.Handler を返す 関数を作ればそれをミドルウェアとして登録できる。 今回いろいろなミドルウェアを追加するときに面倒かな〜と思って、alice を利用した。

github.com

http.Handlerを返す関数はこんな感じ↓。 時間を測って、uuid-v4のrequestIDを生成してcontextに突っ込む。 next.ServeHTTPで本来の処理をして、終わってからログを吐くという形。

func RequestId(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        t1 := time.Now()

        id := newRequestID()
        ctx := setRequestID(r.Context(), id)

        next.ServeHTTP(w, r.WithContext(ctx))
        // 終わったあとにログを吐く

        RLogger.Info("",
            zap.Duration("time", time.Since(t1)),
            zap.String("request_id", id),
            zap.String("path", r.RequestURI),
            zap.String("method", r.Method),
        )
    })
}

仕組み(クエリロガー側)

shogo82148さんの go-sql-proxy がめちゃくちゃ便利でした。*4 github.com

こんな感じで、Execする前に何をするか、Execした後に何をするかっていうのを書けるので、好みの処理を書くだけ。 今回は、クエリごとの時間を計測することと、クエリのログを吐くっていうのが目的なので、以下のような感じにしている。

sql.Register("mysql-tracer", proxy.NewProxyContext(&mysql.MySQLDriver{}, &proxy.HooksContext{
        PreExec: func(_ context.Context, _ *proxy.Stmt, _ []driver.NamedValue) (interface{}, error) {
            return time.Now(), nil
        },
        PostExec: func(c context.Context, ctx interface{}, stmt *proxy.Stmt, args []driver.NamedValue, _ driver.Result, _ error) error {
            QLogger.Info("Exec",
                zap.String("query", stmt.QueryString),
                zap.Any("args", args),
                zap.Duration("time", time.Since(ctx.(time.Time))),
                zap.String("request_id", c.Value(RequestIDKey).(string)),
            )
            return nil
        },
         ...
    }))

go-sql-proxyにもデフォルトでほぼ同じ機能のロガーがあるのだけど、今回のポイントはリクエストごとに一意になるIDを付け加えたいというのと、構造化されたログ(json)を吐きたいというところなので、手を加えさせて貰った。

構造化ログを吐くのにパフォーマンスがいいと謳われている、zapを利用した。 github.com

パフォーマンスをそんなに気にしなくていいと言ったのはこのため。 ~実際wrkでベンチしたけど、ログを入れたからっといって有意な差はあまりなかった。~

追記

流石に雑すぎるので、次の項目でベンチ結果を貼る。

パフォーマンス

100query/recのアプリでログあり

$ wrk http://localhost:8080/user
Running 10s test @ http://localhost:8080/user
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   181.55ms   44.71ms 346.20ms   70.86%
    Req/Sec    27.58     10.54    50.00     63.02%
  549 requests in 10.06s, 63.26KB read
Requests/sec:     54.56
Transfer/sec:      6.29KB

100query/reqのアプリでログなし

$ wrk http://localhost:8080/user
Running 10s test @ http://localhost:8080/user
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   168.48ms   40.87ms 308.79ms   68.35%
    Req/Sec    29.59     11.74    50.00     78.87%
  594 requests in 10.09s, 68.45KB read
Requests/sec:     58.89
Transfer/sec:      6.79KB

1query/reqのアプリでログあり

wrk http://localhost:8080/user
Running 10s test @ http://localhost:8080/user
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     8.74ms   14.81ms 270.78ms   95.19%
    Req/Sec   780.89    156.08     1.19k    69.65%
  15628 requests in 10.10s, 1.76MB read
Requests/sec:   1547.08
Transfer/sec:    178.28KB

1query/reqのアプリでログなし

wrk http://localhost:8080/user
Running 10s test @ http://localhost:8080/user
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     7.55ms    7.72ms 107.14ms   89.51%
    Req/Sec   811.16    187.08     1.55k    69.65%
  16235 requests in 10.10s, 1.83MB read
Requests/sec:   1607.31
Transfer/sec:    185.22KB

まぁ、遅くなるけど、本気ベンチじゃないときにこれぐらいのスコア下がってもまぁ良いよねって感じ。

TODO

  • このリクエストやクエリのログを読み込んで、ボトルネックをわかりやすくするための「graqtクライアント」作成*5
  • mysql固定で書いたけど、ドライバーの登録部分を変えるだけで他のドライバーにもできるはずなので、そこを調整する
  • context対応してないorm?だったらどうしよう?
    • ISUCONで使用されたorm?はsqlxかdatabase/sqlだけなのでcontext対応しているので大丈夫!

まとめ

対ISUCON兵器とか釣りっぽく書いてしまったけど、まだログを吐けるだけでボトルネックは簡単には探せないw

graqtクライアントを書いたときに真価が問われる。

graqtクライアントはこんな感じで考えている。

リクエストモード

全体的に俯瞰して、どのリクエストが重いかを調べるモード。

  • COUNT => そのリクエストの回数
  • AVG => 平均リクエスト時間
  • MIN => 最小リクエスト時間
  • MAX => 最大リクエスト時間
  • PATH => リクエストパス
  • METHOD => メソッド
  • QueryCount => 1リクエストのクエリの数
  • DB Rate => クエリの合計時間/リクエストの時間 (これで、1リクエストでどれだけDBが支配してるかわかる)
COUNT AVG MIN MAX PATH METHOD QueryCount DB Rate
300 20 13 30 / GET 30 0.39
300 20 20 40 /user POST 49 0.79
300 20 30 50 /hoge GET 59 0.38
300 20 50 80 /fuga GET 492 0.58
300 20 70 90 /fuga GET 543 0.33

クエリモード

重いリクエストがわかったら、そのリクエストを選んでそのリクエストで飛んでるクエリが閲覧出来るモード。

  • QueryTime => 1クエリの時間
  • Count => そのクエリが1リクエストで呼ばれた数
  • Args => Prepareステートメントの引数(サンプル1つだけ)
  • Caller => どこでそのクエリが発行されてるかを示す(今はない)
QueryTime Count Query Args Caller
300ms 30 SELECT * FROM USER WHERE id = ? 3 main.go:23
30ms 1 INSERT INTO user (email,age) VALUES (?, ?) ["hoge@hoge", 30] main.go:43

たぶん初めて自分のOSS書いたけど、浸透するまで時間かかりそう。(別にしなくてもいいけどw)

一番の浸透させる方法は、これを使って(または、使った人が)ISUCONに優勝することだろうな〜。 (けど、DBの負荷を減らすのなんて決勝に出る人達はこんなツールがなくても余裕でやってのけるんだろうな〜とかw)

*1:tはどこからきてlはどこ行ってしまったのかw

*2:作者にガラクタ扱いを受けるっていう

*3:正しい表現なのかは不明

*4:というか、まんま

*5:alpみたいなもん

ISUCON7優勝者と社内ISUCONに出て学んだ12のこと

昨日新卒研修向けの社内ISUCONがあり、ISUCON7の優勝者であるsuzukiくんとペアを組んで去年の新卒という枠*1で出させてもらった。*2

僕のISUCONレベルは、社内ISUCONを新卒研修のときに1回やったことがある程度で、レベル5まであるとすれば僕は確実に1ですね。一度やったことがあるというだけですw

レベル1の僕が学んだことなので、ISUCONの常連さんには当たり前のことなのかもしれませんが、順番に書いていきたいと思います。

*1:1年で学んだことを魅せつけてやれ!みたいな役割ですね

*2:恐ろしいことにsuzukiくんはISUCON本選で優勝してるけど僕と同期なんです!!!

続きを読む

git blameとpecoとhubで特定行のGitHubのPRを一発で開くのを実現するgit alias

via GIPHY

tl;dr

大規模なプロジェクトでコード書いてると、「なんでこういう設計になってるのか」とか「当時はどういう仕様だったのか」みたいなのを知りたいことがよくある。

そういったときに、プルリクエストを見ることで知りたい情報を手に入れられることがある。

この行のプルリクエストをみたいな〜と思ったときに、参考にあるCommit Hashから調べる方法で解決していたのだけど、Commit Hashを調べてコピーして git openpr <commit hash> ってやるのが手間だな〜と思ったので一発でこれができるコマンド(blamepr)を作った。

依存ツール

両方brewで入る

設定

~/.gitconfigに↓を追記する。

別にblamepr という名前じゃなくてもいい。自分で好きな名前にしてください。

[alias]
    openpr = "!f() { hub browse -- `git log --merges --oneline --reverse --ancestry-path $1...master | grep 'Merge pull request #' | head -n 1 | cut -f5 -d' ' | sed -e 's%#%pull/%'`; }; f"
    blamepr = "!f() { git blame $1 |peco| cut -f 1 -d ' ' | xargs -I@ git openpr @; };f"

使い方

とても簡単で、 git blamepr <file_name> とやるとpecoにgit blameされたものが出てくるので該当行を絞り込んで、Enterを押すだけ。

参考