Kubernetes環境でのGoのアプリケーションのトレーシング

## はじめに
最近Kubernetes上に自作のアプリケーションをデプロイすることが多いのですが、思ったよりパフォーマンスが出なくてボトルネックを調査しようとした時に、サーバにsshで入ってプロファイラを起動して遅い処理を特定するといったことが気軽にできず困ったことがありました。  

またVMでアプリケーション開発をしているときよりもサービスのコンポーネントも細かく別れているので、今までのようなアプローチではボトルネックの調査に時間がかかってしまうと思います。  

細かくわかれたサービス全体の振る舞いを把握したり、パフォーマンス分析するための分散トレーシングのOSSがいくつか出ているので、そちらを利用してKubernetes上にデプロイしたGoのアプリケーションの分析してみたいと思います。  

## 環境
**アプリケーション**
https://github.com/amber-lamp/opencensus-sample

**実行環境**
Docker for MacのKubernetes連携の機能を利用して構築したローカルのKubernetesクラスタ

**トレーシングツール**
今回はCNCFでホストされている[Jaeger](https://github.com/jaegertracing/jaeger)を使います。

## Jaegerとは
### 概要
[Dapper](https://ai.google/research/pubs/pub36356)と [OpenZipkin](https://zipkin.apache.org/)に影響を受けてUber Technologiesで開発されたOSSの分散トレーシングシステムです。
マイクロサービスのモニタリングやトラブルシューティングに利用されます。
具体的には下記のようなことができるようです。

 - 分散コンテキストの伝播
 - 分散トランザクションの監視
 - 根本原因の分析
 - サービス依存関係の分析
 - パフォーマンス/レイテンシの最適化

[OpenTracing](https://opentracing.io/)というプロジェクトで標準仕様が定められており、それに準拠する形で各言語のclientライブラリが用意されています。Goの場合は[jaeger-client-go](https://github.com/jaegertracing/jaeger-client-go)というライブラリを使えばよさそうです。
一方で[OpenCensus](https://opencensus.io/)という「サービスのメトリクスと分散トレースを取得するためのライブラリ群」も存在していて、OpenCensusにもJaegerにトレース情報を送るための[exporter](https://godoc.org/contrib.go.opencensus.io/exporter/jaeger)が存在しています。

この[２つのプロジェクトは統合されるようですし](https://medium.com/opentracing/merging-opentracing-and-opencensus-f0fe9c7ca6f0)、Jaeger以外のバックエンド(例えばDatadogとかStackdriver等)のexporterも用意されていて、複数のバックエンドへの送信や切り替えも簡単そうですので今回はOpenCensusのJaeger用のexpoterを使ってJaegerにデータを送信するようにしてみたいと思います。


### アーキテクチャ
Jaegerのアーキテクチャの全体は下記のようになっています。
<img width="997" alt="スクリーンショット 2019-06-01 20.45.49.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/80181/4a38424c-ed6e-e19e-9da4-4798c841a58b.png">
参考：https://www.jaegertracing.io/docs/1.12/architecture/

アーキテクチャの説明の前に用語の説明をしたいと思います。
分散トレーシングではSpanという処理の開始時間と終了時間をもつ論理的な単位と、関係するSpanの集合の最初から最後までの集合であるTraceというものがあります。
SpanとTraceの関係については下記の図がわかりやすいと思います。
<img width="976" alt="スクリーンショット 2019-06-02 15.01.25.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/80181/88df98d5-c667-1db9-5d4a-85a5acaf9ecd.png">
参考：https://www.jaegertracing.io/docs/1.8/architecture/#terminology

ではアーキテクチャの各コンポーネントについて見ていきたいと思います。
#### jaeger-agent
Spanの情報を定期的にjaeger-collectorに送るためのデーモンです。
情報を収集するすべてのホストにデプロイされるようになっており、送信先であるjaeger-collectorを見つけて情報を送信する部分を抽象化してくれます。

#### jaeger-collector
jaeger-agentから送られてきた情報にindexをつけるなどの変換処理をしてデータストアに保存するためのコンポーネントです。

#### jaeger-query
データストアに保存されているTrace情報を取得してUIに表示させるためのコンポーネントです。

## やってみる
### Jaegerの構築
では実際に環境を構築してみたいと思います。
今回はローカルのKubernetesクラスタを使うので、[jaeger-kubernetes](https://github.com/jaegertracing/jaeger-kubernetes)というKubernetes上でJaegerを構築するためのKubernetesのマニフェストファイルを利用します。

上記とは別に[Kubernetes Operator](https://github.com/jaegertracing/jaeger-operator)も用意されているので、Kubernetes上に環境を構築するハードルは低そうです。


jaeger-collectorとjaeger-queryが更新/参照するためのデータストアが必要なので、KubernetesのマニフェストファイルとしてCassandraとElasticsearch用のマニフェストが用意されています。  

**Cassandra用**  

```
$ kubectl create -f https://raw.githubusercontent.com/jaegertracing/jaeger-kubernetes/master/production/configmap.yml
$ kubectl create -f https://raw.githubusercontent.com/jaegertracing/jaeger-kubernetes/master/production/cassandra.yml
```

**Elasticsearch用**

```
$ kubectl create -f https://raw.githubusercontent.com/jaegertracing/jaeger-kubernetes/master/production-elasticsearch/configmap.yml
$ kubectl create -f https://raw.githubusercontent.com/jaegertracing/jaeger-kubernetes/master/production-elasticsearch/elasticsearch.yml
```

テストや開発用としてデータをインメモリに保存するall-in-one-templateというマニフェストファイルも用意されています。今回は検証用として、こちらを利用してみたいと思います。
  
```
$ kubectl create -f https://raw.githubusercontent.com/jaegertracing/jaeger-kubernetes/master/all-in-one/jaeger-all-in-one-template.yml
```

上記のall-in-one-templateをKubernetesクラスタ上にデプロイすると下記の通りリソースが作成されます。

```
deployment.extensions/jaeger created
service/jaeger-query created
service/jaeger-collector created
service/jaeger-agent created
service/zipkin created
```

all-in-one-templateのマニフェストを元に作成されたKubernetesのServiceを確認してみます。
TYPEの列がLoadBalancerとなっているjaeger-queryというServiceがあるのでこちらに対してブラウザでアクセスしてみます。

```
$ kubectl get service
NAME               TYPE           CLUSTER-IP    EXTERNAL-IP   PORT(S)                               AGE
jaeger-agent       ClusterIP      None          <none>        5775/UDP,6831/UDP,6832/UDP,5778/TCP   32m
jaeger-collector   ClusterIP      10.100.80.4   <none>        14267/TCP,14268/TCP,9411/TCP          32m
jaeger-query       LoadBalancer   10.99.72.71   localhost     80:30762/TCP                          32m
zipkin             ClusterIP      None          <none>        9411/TCP                              32m
```
ブラウザから`http://localhost:80`にアクセスすると下記の通りJaegerのUIが表示されることが確認できます。
<img width="1673" alt="スクリーンショット 2019-05-14 0.40.37.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/80181/92980bb6-58cb-63f1-07db-91383b4ac888.png">

jaeger-agent,jaeger-collector,jaeger-query,UIなどの各コンポーネントがKubernetesクラスタ上でどのような構成になっているかというと、全て１つのDeploymentにまとまっているようです。

```
$ kubectl get deployment
NAME     DESIRED   CURRENT   UP-TO-DATE   AVAILABLE   AGE
jaeger   1         1         1            1           10m
```
参考：https://www.jaegertracing.io/docs/1.8/getting-started/#all-in-one

all-in-one-templateをKubernetesクラスタ上にデプロイするだけで、準備が整いましたので、あとはアプリケーションのトレース情報をjaeger-agentに送れば上記のUIで確認することができそうです。

### アプリケーション側の設定

設定は[opencensus-go-exporter-jaegerのexample](https://github.com/census-ecosystem/opencensus-go-exporter-jaeger/blob/master/example/main.go)を参考に行います。
ソースコードの全体はgithubにpushしてありますので、下記のレポジトリを適宜参照してください。
https://github.com/amber-lamp/opencensus-sample

最初に下記の２つのパッケージをimportしてください。

```golang:main.go
import (
	~~省略~~
	"contrib.go.opencensus.io/exporter/jaeger"
	"go.opencensus.io/trace"
)
```

main関数でexporterとsamplerの設定をしています。
jaeger.OptionsのAgentEndpointにjaeger-agentのKubernetesのService名とportを指定しています。
また、trace.ApplyConfigの部分でDefaultSamplerにtrace.AlwaysSample()を設定しています。今回は検証のためアクセスした情報を全てサンプルとして取得してUIに表示する設定にしています。

```golang:main.go
func main() {
	exporter, err := jaeger.NewExporter(jaeger.Options{
		AgentEndpoint: "jaeger-agent:6831",
		Process: jaeger.Process{
			ServiceName: "demo",
		},
	})
	if err != nil {
		log.Fatal(err)
	}
	defer exporter.Flush()

	trace.RegisterExporter(exporter)
	trace.ApplyConfig(trace.Config{DefaultSampler: trace.AlwaysSample()})

	log.Println("Start demo server...")
	http.HandleFunc("/", handler)
	log.Fatal(http.ListenAndServe(":8080", nil))
	
}
```

handler関数の中でSpanを開始しています。第１引数にcontextを第２引数にSpanを識別する文字を入れています。

```golang:main.go
func handler(w http.ResponseWriter, r *http.Request) {
	ctx, span := trace.StartSpan(context.Background(), "/handler")
	defer span.End()

	omikuji := omikuji(ctx)
	fmt.Fprintf(w, "運勢は[%s]です", omikuji)
}
```

最後にhandler関数呼ばれているomikuji関数を見てみます。
trace.StartSpanの第１引数にhandler関数でSpanを開始したときの戻り値のcontextを設定しています。
このようにすることでJaegerのUIで見たときにomikuji関数で開始したSpanがhandlerのSpanの子Spanのように表示されます。

また関数の下の方にchildSpan.Annotateとありますが、これでSpanにアノテーションを付けることができます。
omikuji関数をよく見ると"凶"のときだけ1秒スリープしていて処理時間が長くなっているのですが、おみくじの結果と結果に対応するメッセージをアノテーション情報として付与することで、どの条件の時に処理が遅いのか、JaegerのUI上で見た時に判断をすることができるようになります。

```golang:main.go
func omikuji(ctx context.Context) string{
	_, childSpan := trace.StartSpan(ctx, "/omikuji")
	defer childSpan.End()
	t := time.Now()

	var omikuji string
	var msg string
	if (t.Month() == 1 && t.Day() >= 1 && t.Day() <= 3){
		omikuji = "大吉"
		msg = "お正月は大吉"
	} else {
		t := t.UnixNano()
		rand.Seed(t)
		s := rand.Intn(6)
		switch s + 1 {
		case 1:
			omikuji = "凶"
			msg = "残念でした"
			time.Sleep(time.Second)
		case 2, 3:
			omikuji = "吉"
			msg = "そこそこでした"
		case 4, 5:
			omikuji = "中吉"
			msg = "まあまあでした"
		case 6:
			omikuji = "大吉"
			msg = "いいですね"
		}
	}
	childSpan.Annotate([]trace.Attribute{
		trace.StringAttribute("omikuji", omikuji),
	}, msg)
	return omikuji
}
```

では作成したアプリケーションをKubernetes上にデプロイしてどのようになるか見てみます。
作成したGoのアプリケーションはDockerHubにpushしてありますので、ローカルのKubernetesクラスタにデプロイします。
本来はKubernetesのマニフェストファイルからデプロイした方が良いですが、ここでは`kubectl run`コマンドでデプロイを実施します。

```
$ kubectl run opencensus-sample --image=yuuyamad/opencensus-sample:latest
```

`kubectl get pods`コマンドでデプロイしたPodが起動していることを確認します。
全てRunningになっているので上手く行っているようです。

```
$ kubectl get pods
NAME                                 READY   STATUS    RESTARTS   AGE
jaeger-796dcb98cb-xjj26              1/1     Running   0          7m
opencensus-sample-6996b4f94b-pfskk   1/1     Running   0          39s
```

Kubernetesクラスタ上にデプロイされたアプリケーションにアクセスするにはServiceやIngress等のLBの機能を利用してクラスタの外部からアクセスするのが普通ではありますが、ここではPortForwardをして直接Podにアクセスして確認を行います。

```
$ kubectl port-forward deployment/opencensus-sample 8080 8080
```
上記のコマンドでPodの8080番ポートにlocalhostの8080番ポートからPortForwardした状態で`localhost:8080`にアクセスすると今回サンプルで作成したおみくじアプリケーションが動いていることが確認できるかと思います。
<img width="365" alt="スクリーンショット 2019-06-03 2.13.50.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/80181/c6268070-d0e1-5eb2-909f-2ecc096a9ab3.png">

では何度かアプリケーションにアクセスしてからJaegerのUIを確認してみましょう。
ServiceのプルダウンでdemoというServiceが選べるようになるので選択して「Find Traces」ボタンを押してください。下記のような画面が確認できると思います。
<img width="1670" alt="スクリーンショット 2019-06-03 2.06.42.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/80181/562d9a6e-f068-8fb7-d818-26a6019c933c.png">

表示された検索結果の中から１つを選んでクリックすると下記のような画面が表示されます。
/handlerと/omikujiのSpanが表示されています。/omikujiのSpanを展開してLogsを部分を見ると、omikuji関数で設定したアノテーションの情報を見ることができるので、おみくじの結果が凶の時に処理に1秒かかっていることを確認することができます。
<img width="1676" alt="スクリーンショット 2019-06-03 2.07.02.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/80181/fe0fa03c-1bf9-939d-69ac-639f5d4f2d67.png">

## まとめ
分散トレーシングのOSSの[Jaeger](https://github.com/jaegertracing/jaeger)を使ってGoのアプリケーションを分析してみました。
今回は1つのサービスのトレーシングをしただけではありますが、複数のサービスにまたがるような場合も同様にトレーシングを行えるようなので、Microservicesアーキテクチャで構築されたシステムを運用していく上では必須の技術なのではと感じました。