はじめに
OpenTelemetryのトレーシングには色々な情報が付与されるため、パフォーマンスやエラーの調査に利用することが出来ます。
この記事ではOpenTelemetryを使った調査方法について紹介します。
※コードのサンプルにGoを使用していますが、Go以外の言語でも変わりません。
TraceとSpan
はじめにOpenTelemetryのトレーシングについて。
トレーシングは主にSpanとTraceで出来ています。
Spanはプログラムが実行した処理を表すデータ構造で、開始時間やAttribute(任意のキーバリュー)を持っています。
また、TraceはSpanをノードとした木構造です。
Traceを可視化すると上図のようになり、線一本ずつがSpanです。
ただし、Traceはどこかで一括管理されているものでもなければ、実体があるわけでもありません。
トレーシングとしてプログラムから送信されるデータはSpanしかなく、TraceはJaegerなどのバックエンドで理解される仮想的な存在です。
パフォーマンス改善に役立てる
バックエンドが集めたSpanからTraceを構築すると、Spanの情報からTrace全体の実行時間や実行時の詳細がわかります。
例えば、以下のコードでTraceを作った場合、
func CreateTrace() {
ctx, span := tracer.Start(context.Background(), "hello-span")
defer span.End()
span.SetAttributes(attribute.Int("user_id", 1234))
time.Sleep(1 * time.Second)
ctx, span = tracer.Start(ctx, "child-span")
defer span.End()
span.SetAttributes(attribute.String("db.statement", "SELECT * FROM users WHERE user_id = 1234"))
time.Sleep(1 * time.Second)
}
このコードでは、下のようなSpanが作られます。
child-spanだけで1秒かかりTrace全体では2秒かかったことがわかるとともに、Attributeに設定した値が使われていることも確認できます。
{
"Name": "child-span",
"StartTime": "2001-02-03T00:52:17.000+09:00", // <- 開始時間
"EndTime": "2001-02-03T00:52:18.000+09:00", // <- 終了時間
"Attributes": [
{
"Key": "db.statement", // <- 追加したAttribute
"Value": {
"Value": "SELECT * FROM users WHERE user_id = 1234"
}
}
]
}
{
"Name": "hello-span",
"StartTime": "2001-02-03T00:52:16.000+09:00", // <- 開始時間
"EndTime": "2001-02-03T00:52:18.000+09:00", // <- 終了時間
"Attributes": [
{
"Key": "user_id", // <- 追加したAttribute
"Value": {
"Value": 1234
}
}
]
}
これを可視化すると、画像のように、どこにどれだけ時間を使ったかがわかります。
こうして出来たデータを基に
- 遅いTraceを探す
- 遅いサービスを探す
- 遅いTraceに共通するAttributeを見つける
などができるわけです。
エラー調査に役立てる
Spanにはエラー時の情報を付与することも出来ます。
エラーの情報はEventフィールドに付与します。
Eventはクリックやエラーなど、何かイベントがあったときに時刻などを記録するためのフィールドです。
例えば、下のようにすればスタックトレースと一緒に例外を記録できます。
func RecordError() {
_, span := tracer.Start(context.Background(), "hello-span")
defer span.End()
err := someOperation()
if err != nil {
span.AddEvent(
"exception",
trace.WithAttributes(
attribute.String("exception.message", err.Error()),
attribute.String("exception.stacktrace", recordStackTrace()),
),
)
}
}
func recordStackTrace() string {
stackTrace := make([]byte, 2048)
n := runtime.Stack(stackTrace, false)
return string(stackTrace[0:n])
}
また、RecordErrorのような関数が用意されているのであれば、下のように使うことも出来ます。
func RecordError() {
ctx, span := tracer.Start(context.Background(), "hello-span")
defer span.End()
err := someOperation()
if err != nil {
opts := buildErrorOptions(err)
span.RecordError(err, opts...)
}
}
func buildErrorOptions(err error) []trace.EventOption {
var opts []trace.EventOption
// cockroachdb/errorsのように、errorの中にスタックトレースがある場合はそれを使う方が適切です。
if details := errors.GetSafeDetails(err).SafeDetails; len(details) > 0 {
opts = append(opts, trace.WithAttributes(semconv.ExceptionStacktrace(details[0])))
} else {
opts = append(opts, trace.WithStackTrace(true))
}
return opts
}
こうすると、下のようにスタックトレースやエラーメッセージの情報が付与されます。
{
"Name": "hello-span",
"StartTime": "2001-02-03T00:01:02.000+09:00",
"EndTime": "2001-02-03T00:01:02.000+09:00",
"Events": [
{
"Name": "exception", // <- 付与されたイベント名
"Attributes": [
{
"Key": "exception.message",
"Value": {
"Value": "some error occurred" // <- エラーメッセージ
}
},
{
"Key": "exception.stacktrace",
"Value": { // <- スタックトレース (改行追加)
"Value": `goroutine 1 [running]:\n
main.recordStackTrace(...)\n
\t/path/to/main.go:67\nmain.RecordError()\n
\t/path/to/main.go:57 +0x20c\nmain.main()\n
\t/path/to/main.go:18 +0x1c\n`
}
}
],
"Time": "2001-02-03T00:01:02.000+09:00" // <- エラー発生時刻
}
]
}
こうしたデータを使うと
- バックエンドがエラーがあったことを把握する
- エラーをグルーピングする
- エラーの時に共通するAttributeを見つける
などができるわけです。
終わりに
以上、OpenTelemetryでパフォーマンスやエラー調査に使っている要素の紹介でした。
Discussion