本番環境でのみ起こるようなパフォーマンス問題の調査は、簡単ではありません。そのようなボトルネックの調査では、どの処理がどのような入力で時間がかかるかを特定することが重要です。

本記事では、メトリクスの収集や処理のトレースを行うためのフレームワークであるOpenCensusとその可視化、分析サービスのStackdriver Traceを使ってGoのアプリケーションの処理時間を可視化する方法を紹介します。

OpenCensus

OpenCensusは分散システムのメトリクス収集や処理をトレースするためのフレームワークです。Go, Node, Python, Rubyなど様々な言語で提供されており、単純な記述でメトリクスの修正や処理のトレースを行うことができます。収集したデータの可視化する基盤としては、Stackdriver、Datadog、AWS X-Ray、Prometheusなどが対応しています。

公式ドキュメント: https://opencensus.io/

Stackdriver Trace

Stackdriver Trace は GCP で提供されている分散トレース可視化サービスです。下図のようにリクエスト毎に詳しいレイテンシ情報を分析したり、アプリケーション全体のレイテンシを確認したりすることができます。また、分析レポートを作成して週次でレイテンシの分布を確認したり、アプリケーションのレイテンシに大きな変化が見つかったら通知するよう設定したりできます。

公式ドキュメント: https://cloud.google.com/trace/

OpenCensus + Stackdriver Trace で Goアプリケーションのトレースを表示する

それでは、アプリケーションのトレースを表示するように実装していきます。必要なのは下記の3つです。

プロジェクトの設定
アプリケーションの実装
トレース処理の実装

プロジェクトの設定

まず、以下のようにトレース情報を送信するプロジェクトの設定を行います。3は今回作るアプリケーションのようにFirebaseを使う場合に行ってください。今回は時間課金されず、安くDBを使えるためFirestoreを使います。Firestoreはドキュメント指向のDBです。

GCPのプロジェクトを作成する
コンソール画面左のトレースタブから Stackdriver Trace APIを有効にする
1 で作成したプロジェクトにFirebaseを追加(今回実装するアプリケーションの場合)

作成したGCPのプロジェクトの権限を持ったGoogle アカウントで Firebaseのコンソールを開き、プロジェクトを追加からGCPの既存プロジェクトにFirebaseを追加できます。

アプリケーションの実装

アプリケーションを実装していきます。APIを定期的に叩いて、結果をDBに格納するアプリケーションを作成します。 APIには仮想通貨の相場情報を取得できるCoinMarketCap APIを、DBにはFirestoreを使用します。

APIから定期的に時価総額が上位10件の通貨の価格情報を取得し、DBへ保存します(仮想通貨の時価総額は、価格 x 流通している通貨量で表されます)。実装方法によってどのようにトレースが変わるかを可視化したいので、2種類の方法でFirestoreへデータを保存します。

下記が実装結果です。processTickがAPIから時価総額上位10件の通貨の価格情報を取得し、1つずつDBへ格納する関数です。batchProcessTickは全ての価格情報をまとめてDBへ格納する関数です。main関数でこれらの関数を定期的に呼び出します。GetCoinMarketInfos関数が実際にAPIを叩き、CoinMarketInfo型にUnmarshalしています。本題からそれるので説明を割愛しますが、実装は下記リポジトリで公開しています。

github.com/soichisumi/opencensus-test

type CoinMarketInfo struct {
	ID              int32       `json:"id"`
	Name            string      `json:"name"`
	Symbol          string      `json:"symbol"`
    Rank            int32       `json:"cmc_rank"`
    Quotes          Quotes      `json:"quote"`
}

type Quotes struct {
	JPY Quote `json:"JPY"`
}

type Quote struct {
	Price            json.Number `json:"price"`
	PercentChange24h json.Number `json:"percent_change_24h"`
}

var ctx = context.Background()

// 価格情報をFirestoreに逐次追加する
func processTick(client *firestore.Client) {
    // (ctx context.Context) => ([]CoinMarketInfo, error)
	infos, err := GetCoinMarketInfos(ctx)
	if err != nil {
		log.Printf("error: %+v", err)
		return
	}

	for _, info := range infos {
		fmt.Printf("add coin: %s\n", info.Symbol)
		client.Doc(fmt.Sprintf("Market/%s", info.Symbol)).Set(ctx, map[string]interface{}{
			"Name": info.Name,
			"Rank": info.Rank,
			"Symbol":  info.Symbol,
		})
	}

	fmt.Println("market info is updated.")
}

// 価格情報をFirestoreにまとめて追加する
func batchProcessTick(client *firestore.Client) {
    // (ctx context.Context) => ([]CoinMarketInfo, error)
	infos, err := GetCoinMarketInfos(ctx)
	if err != nil {
		log.Printf("error: %+v", err)
		return
	}

	batch := client.Batch()
	for _, info := range infos {
		docRef := client.Doc(fmt.Sprintf("Market/%s", info.Symbol))
		batch.Set(docRef, map[string]interface{}{
			"Name": info.Name,
			"Rank": info.Rank,
			"Symbol":  info.Symbol,
		})
	}
	batch.Commit(ctx)
	fmt.Printf("market info is updated.\n")
}

// 3分毎にprocessTickを、5分毎にbatchProcessTickを起動する
func main() {
	loadEnv() // load .env file

	app, err := firebase.NewApp(ctx, &firebase.Config{ProjectID: os.Getenv("PROJECT_ID")})
	if err != nil {
		log.Fatalf("failed to create new firebase app")
	}
	client, err := app.Firestore(ctx)

	ticker1 := time.NewTicker(3 * time.Minute)
	ticker2 := time.NewTicker(5 * time.Minute)
  
	fmt.Println("start market info updater.")
	for {
		select {
		case <-ticker1.C:
			fmt.Println("tick1")
			processTick(client)
		case <-ticker2.C:
			fmt.Println("tick2")
			batchProcessTick(client)
		}
	}
}

上記コードを実行すると次のようにFirestoreに価格情報が格納されます。

トレース処理の実装

トレースの表示は opencensus-go を用いて行います。OpenCensusで Stackdriverにトレースを表示するために必要なことは次の3つです。

Exporterの設定
トレース処理の追加

Exporterの設定

まず収集したデータを送信するExporterの設定をします。今回はStackdriverを利用するので、Stackdriverのexporterを初期化します。初期化時にGCPのどのプロジェクトに送信するのかと、どの程度の割合でサンプリングするのかを設定する必要があります。

下記のように、main関数で環境変数を読み込んだあと、Exporterを登録し、Samplerを適用すれば完了です。

exporter, err := stackdriver.NewExporter(stackdriver.Options{
    ProjectID: os.Getenv("PROJECT_ID"),
})
if err != nil {
    log.Fatal(err)
}
trace.RegisterExporter(exporter)
trace.ApplyConfig(trace.Config{DefaultSampler: trace.ProbabilitySampler(0.5)})

トレース処理の追加

次に処理時間を可視化したい箇所で、トレースを取る処理を追加していきます。OpenCensusではトレースしたい 1 まとまりの処理を Span と呼びます。主にHTTPリクエストやDBへのクエリを Span とします。

Span を追加する処理は次のようになります。例として、processTick 関数にSpanを追加する場合を紹介します。処理の最初で trace.Span() して contextとSpanを作成し、子Spanを作成したいmethodに渡していくようにします。

下記実装では GetCoinMarketInfos() と FirestoreClientのSetに context を渡しています。 GetCoinmarketInfos() では、受け取ったcontextを使って新しく子 Span を生成します。Firestore の clientは自動でSpanを生成してくれるので、 Set() に Span から生成された context を渡せば良いです。

func processTick(client *firestore.Client) {
	ctx, span := trace.StartSpan(context.Background(), "processTick.naive")
	defer span.End()

	infos, err := GetCoinMarketInfos(ctx)
	if err != nil {
		log.Printf("error: %+v", err)
		return
	}

	for _, info := range infos {
		fmt.Printf("add coin: %s\n", info.Symbol)
		client.Doc(fmt.Sprintf("Market/%s", info.Symbol)).Set(ctx, map[string]interface{}{
			"Name": info.Name,
			"Rank": info.Rank,
			"Symbol":  info.Symbol,
		})
	}

	fmt.Printf("market info is updated.\n")
}

// GetCoinMarketInfos ...
func GetCoinMarketInfos(ctx context.Context) ([]CoinMarketInfo, error) {
	_, span := trace.StartSpan(ctx, "getCMCInfos")
	defer span.End()

	url := fmt.Sprintf("%s/cryptocurrency/listings/latest?sort_dir=desc&limit=1000&convert=JPY", cmcAPIBaseURL)
	req, err := http.NewRequest("GET", url, nil)
	if err != nil {
		return nil, errors.WithStack(err)
	}
	req.Header.Set("X-CMC_PRO_API_KEY", coinMarketCapAPIKey)

	client := &http.Client{ Transport: &ochttp.Transport{ Propagation: &tracecontext.HTTPFormat{}}}
	resp, err := client.Do(req.WithContext(ctx))
	if err != nil {
		return nil, errors.WithStack(err)
	}
    // ここでレスポンスを型にUnmarshalする。割愛します
}

トレース情報の表示

収集したトレース情報を表示します。次の 3 つを行って下さい。

ターミナルで gcloud auth application-defalut loginを実行し、プロジェクトのオーナー権限があるアカウントでログイン
- 今回作成したアプリケーションは、gcloudのデフォルトクレデンシャルを使ってプロジェクトにトレース情報を送信するため
アプリケーションを go run でしばらく(長くて10分程度)実行
GCPのコンソール画面から、左タブのトレース -> トレースリストを開く

以上でトレースを表示できます。

収集したトレースは下記のように表示されます。processTick, batchProcessTickの処理時間と、それぞれの関数内でfirestoreへのクエリ、APIへのリクエストにどの程度時間がかかっているかが可視化されています。都度書き込むのは非効率であることと、通信箇所以外の実装はそこまで速度にこだわらなくても良いことが見て分かりますね。

processTickのトレース

batchProcessTickのトレース

まとめ

本記事では、OpenCensus と Stackdriver Traceを使って Go のアプリケーションの処理時間を可視化する方法を紹介しました。少しの実装と設定により本番環境で動作しているアプリケーションのトレースをリアルタイムに取得したり、Stackdriverで設定をすれば週次の分析レポートを作成することもできます。入れておくとデバッグ時に便利なのでぜひ導入してみてください。

参考リンク

github.com/soichisumi/opencensus-test

opencensus-go

OpenCensus 公式ドキュメント

Stackdriver Trace 公式ドキュメント

Stackdriver Traceと分散トレーシングフレームワークOpenCensusで処理時間を可視化する