BETA

GCPのStackdriver traceが面白いし有用だった

投稿日:2020-03-09
最終更新:2020-03-09

ちょっと大きめだったりゴリゴリ処理が走るタイプのAPIとか作ると、処理速度が気になりますよね。
自前の測定方法とかだと、処理の開始時間と終了時間の差分を取ってログ出力、とかができますけど、まあ見やすいかと言われると...そんなことないですよね。

今回GCPを使っていて、そこらへんを良きように可視化してくれる Stackdriver traceを自分で入れてみたので紹介します。

前提となる環境

  • APIのアプリケーション(Golang)をGAEに載せている

やってみる

(公式ページ)[https://cloud.google.com/trace/docs]に基づいてやっていきます....
と言いたいのですが、GAEに載せたアプリケーションだと、自動的にStackdriver traceが動いてくれるんですよね。
GAEのダッシュボードを開いてみると、こんな感じで

ここで[現在の不可]に各リクエストがあり、右の方には「トレースの表示」があります。ここから、各リクエストの状況が見られるようになっているのです。

リクエストにかかった時間の分布もありますので、異常に遅い処理がないかなどがとても簡単に分かるのです。

ね、簡単でしょ?

カスタマイズしてみる

これで「もうできていました」で終わっては面白く無いので、このトレースをちょっとカスタマイズします。
現在は1つのAPIリクエスト全体でかかった時間だけが出ていましたが、実際にそのAPIリクエストの中のそれぞれの処理における所要時間も可視化しましょう。
やり方をざっくり言うと以下を行います

  1. 提供されているライブラリを用いて、HTTPリクエストに情報追加する
  2. 「スパン」と呼ばれる計測単位を作り、計測したい区間でStart,End処理を行う

1.ライブラリのセットアップ

import )  
 ...  
    "contrib.go.opencensus.io/exporter/stackdriver"  
    "contrib.go.opencensus.io/exporter/stackdriver/propagation"  
    "go.opencensus.io/plugin/ochttp"  
    "go.opencensus.io/trace"  
)  
func main() {  
    //a. Initialze  
    // Create and register a OpenCensus Stackdriver Trace exporter.  
    exporter, err := stackdriver.NewExporter(stackdriver.Options{})  
    if err != nil {  
        log.Fatal(err)  
    }  
    trace.RegisterExporter(exporter)  
    trace.ApplyConfig(trace.Config{DefaultSampler: trace.AlwaysSample()})   

     //b. set propagation  
    server := &http.Server{  
        Addr: ":8080",  
        Handler: &ochttp.Handler{  
            Handler:     http.DefaultServeMux,  
            Propagation: &propagation.HTTPFormat{},  
        },  
    }  

    http.HandleFunc("/hoge",hogeHandler)  
    http.HandleFunc("/", handler)  
    if err := server.ListenAndServe(); err != nil {  
        log.Fatal(err)  
    }  
}  

必要なライブラリは、stackdriver 系、 opencensus 系のものです。
ほぼほぼコピペですが、

  • a: stackdriverとtraceを使えるようにする
  • b: httpリクエストにpropagationを設定する

をやっているというくらいの認識でいいと思います。

  1. 「スパン」の作成
    上記1のソースコードの通り、今回は2つのAPIリクエスト、 //hogeを用意しています。
    GAEにデプロイしたアプリケーションでそれぞれ https://xxxxx.appspot.com/ , https://xxxxx.appspot.com/hoge を叩くと、/ のトレース、 /hogeの処理で1スパンという単位になり、トレースが出てくることになります。
    ここではそれぞれの処理に対してその中に処理もトレースできるように、「子スパン」を作ります。
func hogeHandler(w http.ResponseWriter, r *http.Request) {  
    ctx := r.Context()  
    ctx, span := trace.StartSpan(ctx, "/hoge")  
    defer span.End()  

    hoge(r)  
    time.Sleep(400)  
    fmt.Fprintf(w, "Hoge done %s", time.Now())  
}  
func hoge(r *http.Request) {  
    ctx := r.Context()  
    _, hogeSpan := trace.StartSpan(ctx, "childHoge")  
    defer hogeSpan.End()  

    time.Sleep(200)  
}  

やるべきことは以下のようなものです。

  • http.Requestからcontextを取得
  • trace.StartSpan()関数で、子スパンを作る
  • Startしたものを、Endで終了する。

ここでは、リクエストとして呼ばれたhogeHandler()処理完了を待つ子スパンと、さらにその子となるhoge()関数のスパンを作って呼び出しています。

見てみる

上記対応が終わったら、GAEにアプリケーションをデプロイし、実際にAPIを叩いてみましょう。
その後Traceで読み込まれた結果が以下のようになります。


/hogeというリクエストに対して、その子である/hoge、さらにその子であるchildHogeの実行時間がタイムラインで見られるようになりました。


いくつかのサイトを参考にしながら作ったのがなかなかうまくいかずに詰まっていたのですが、必要なことが全て見えてしまったらさほど難しいことはありません。
今回の記事のように、1リクエストだけでなくその中の処理も細かく処理時間をトレースしたいと言うことであれば、アプリケーションが大きくなく手を入れる箇所が少ないうちにやっておくことをお勧めします。

参考文献

技術ブログをはじめよう Qrunch(クランチ)は、プログラマの技術アプトプットに特化したブログサービスです
駆け出しエンジニアからエキスパートまで全ての方々のアウトプットを歓迎しております!
or 外部アカウントで 登録 / ログイン する
クランチについてもっと詳しく

この記事が掲載されているブログ

Tech memos

よく一緒に読まれる記事

0件のコメント

ブログ開設 or ログイン してコメントを送ってみよう