Tail Sampling Processorを使ってAPMの使用量を効率化しよう

はじめに

こんにちは、Google Cloudでオブザーバビリティの担当をしているものです。このエントリーはOpenTelemetry Advent Calendar 2022の2日目の記事です。1日目は @katzchang の「OpenTelemetry Collectorでログファイルの更新を取り込む」でした。

さて、みなさんは分散トレースを活用しているでしょうか。分散トレースはマイクロサービスアーキテクチャのみならず、モノリスなシステムにおいてもレイテンシーのボトルネックを発見する上で有用なテレメトリーです。まだ活用されていないという方はぜひ活用していきましょう！

分散トレースのサンプリング

活用されているみなさまにおかれましては、分散トレースの取得において、トレースのサンプリング方法について頭を悩ませていることと思います。テスト環境などではサンプリングレートを100%にして、あらゆる処理のトレースを取得することが可能かもしれませんが、本番環境でそれを行うと、APMサービスで従量課金となっている場合に使用料金が跳ね上がってしまいます。そこで、通常は取得するトレースのサンプリングを行うわけですが、どのような基準でサンプリングを行うかが悩みの種となります。

一番簡単な方法はランダムサンプリングです。すべてのトレースの中から、中身によらず一定の割合のトレースだけ取得するというものです。たとえば全体のうち1%だけ取得する、といった具合です。しかしながらこの手法の課題点は、レイテンシーに問題があった場合のトレースが取得できない可能性があるということです。（レイテンシーに問題があるかどうかは事前にはわからないので仕方がない）

そこでテイルサンプリングという手法を用いて、特別なトレースのみを送信するという手法が求められます。これは、アプリケーションから直接APMバックエンドに送信する場合には、アプリケーション内でトレースのレイテンシーを計算した上で選別するという作業を行わなければなりませんが、各種エージェントを使っている場合にはエージェント内で特定のトレース以外をドロップしてくれれば実現できます。

OpenTelemetry Collectorにおいてもテイルサンプリングを実現するための Tail Sampling Processor があるのでそれを利用してみましょう。

Tail Sampling Processor

github.com

Tail Sampling Processorはコントリビューションレポジトリで提供されているCollector用のプロセッサーの一つです。これはトレースの様々な条件をもとに、エクスポートするトレースをサンプリングしてくれるプロセッサーです。このプロセッサーのサンプリング用ポリシーの一つに latency というものがあって、これを使うことで一定時間以上のレイテンシーがかかっているトレースのみをバックエンドに送信する事が可能です。

実際に次のような設定をしてみます。（processors.tail_sampling.policies のところで、600ms以上のトレースのみをサンプリングする設定をしています。）

receivers:
  otlp:
    protocols:
      grpc:

processors:
  tail_sampling:
    decision_wait: 10s
    num_traces: 10
    policies:
      [
        {
          name: longer-than-600s,
          type: latency,
          latency: { threshold_ms: 600 },
        },
      ]

exporters:
  googlecloud:
    project: sample-project-1234
    retry_on_failure:
      enabled: true
    log:
      default_log_name: opentelemetry.io/collector-exported-log

extensions:
  memory_ballast:
    size_in_percentage: 30
  zpages:

service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [tail_sampling]
      exporters: [googlecloud]
  telemetry:
    logs:
      level: "debug"
  extensions: [zpages, memory_ballast]

実際にこの設定をしたコレクターに対してトレースを投げてみます。意図的に600ms以上のトレースを3つ、続いて600ms未満のトレースを4つ生成してみると、次のようなログが表示されました。（これは service.telemetry.logs.level を debug にしているから得られる表示で、通常は出てきません。）

2022-12-02T14:26:43.351+0900    debug   tailsamplingprocessor@v0.66.0/processor.go:202  Sampling policy evaluation completed    {"kind": "processor", "name": "tail_sampling", "pipeline": "traces", "batch.len": 3, "sampled": 3, "notSampled": 0, "droppedPriorToEvaluation": 0, "policyEvaluationErrors": 0}
...
2022-12-02T14:27:18.350+0900    debug   tailsamplingprocessor@v0.66.0/processor.go:202  Sampling policy evaluation completed    {"kind": "processor", "name": "tail_sampling", "pipeline": "traces", "batch.len": 4, "sampled": 0, "notSampled": 4, "droppedPriorToEvaluation": 0, "policyEvaluationErrors": 0}
...

このログを見ると、600ms以上かかっているトレースは "sampled": 3 として、サンプリングされたことがわかります。一方で、 600ms未満のトレースはどうだったかというと "notSampled": 4 と表示されていて、サンプリングされていないようです。

実際にこれが送信されたか、Cloud Traceのダッシュボードで確認してみましょう。

小さいのでアップしてみると

14:26:43の付近に800ms前後のトレースが3つ記録されているのがわかります！一方で、14:27:18付近には生成した4つの600ms未満のトレースは記録されていません。これはコレクターでドロップされて、エクスポートされなかったことを意味しています。

このようにTail Sampling Processorを使うと、トレースの中身（レイテンシー、アトリビュート、ステータスなど）によって柔軟にフィルタリングが可能になります！

おわりに

OpenTelemetry Collectorはまだまだ実運用のノウハウが共有されていません。このような便利なプロセッサーやレシーバーの情報がどんどん共有されることをきたしています！

明日は @munisystem さんです。

日本学生支援機構の奨学金を完済した

はじめに

こんにちは、Google CloudでオブザーバビリティやSREの関連技術の普及と製品の改善を担当しているものです。このエントリーはPySpaアドベントカレンダー 2022の1日目の記事です。

2008年4月に大学院（修士）を修了して就職し、その半年後の10月から数えて丸14年かけて高校、大学、大学院と借りていた日本学生支援機構の奨学金を2022年9月の支払いで完済し、無事全奨学金の完済証明書が揃いました。本記事はせっかく完済したので自分の記録として残すために書きました。これは知人の本間さん（@CkReal）がちょうど同じようなタイミングで完済されていたので、刺激されたものです。

blog.ckreal.net

奨学金を借りるに至った経緯

単純に家計が厳しかったからです。自分の家庭は父親が小売業の従業員（正社員）で母親が農業（準社員）で仕事をしていたものの、給与は決して良いほうではありませんでした。ただ子供の教育にはお金をかけてくれる家庭ではあったので中高は私立に行かせてくれていました。（「大学は国立大学でないと無理」と言われていて、それなりにプレッシャーを感じてはいました。）弟がいたこともあり、高校から奨学金を借り、そこから大学、大学院と日本育英会（現「日本学生支援機構」）から貸与型奨学金を借りることとなりました。また大学時代には地元の信金が行っていた給付型奨学金を月に1万円余いただいていました。

高校三年時に父親の勤務先が債務超過に陥って、事業縮小のためにリストラにあったこともあり、大学時代は奨学金とアルバイトで生活費を賄っていました。*1東京は家賃も高かったので、大学から離れた安い賃貸に住んでいました。*2

在学中の心境

アルバイトで生活費を賄って切り詰めた上で、余剰のお金でそれなりに大学生活自体は楽しんでいました。しかし、東京圏出身の友人が実家暮らしで家賃も必要ないためアルバイトで稼いだお金を全部交遊費に使ったりとしているのを見て、羨ましく思ったことが無いと言えば嘘になります。いつも頭のどこかでお金に関する不安を抱えたまま在学しているというのはあまり精神的には良いものではありませんでした。

大学院に入ってから、より効率良くお金を稼ぎたいと思い、知人のツテでプログラミングのアルバイトを始めて、だいぶ余裕がでました。たまたま運良く多少のコードが書けたことで生活が多少なりとも良くなったのは、今の職業の原体験だったなと思います。

奨学金を借りているという事実は大学院修了後に就職先を決める際にも影響しました。すでに崩壊しつつはありましたが、まだ根強く残っていた日系企業の終身雇用型の給与体系では奨学金の返済がままならないと感じ、自分のスキルを活かせそうな外資系のIT企業を中心に就職活動を進めていました。*3

奨学金の返済中の心境

就職してから、毎月奨学金の支払いが手取りの一定以上の割合を占めているというのは本当に精神衛生上良くなく、就職後5年くらいはちょっと大きな買い物をしたときに「奨学金の支払いが無かったら贅沢できたな」とか思ったりしてました。困窮はしていませんでしたが、何かを購入する際には支払った金額に対する機能が見合うものなのか、いわゆる「コストパフォーマンス」を重要視するような買い物を常に心がけていたことをよく覚えています。これは今でも染み付いています。

ある程度以上の収入になってからは余裕が出てきたので、各支払いの際に奨学金のことを思い出すことはありませんでしたが、それでもなお、毎月メインバンクのネット銀行から、引き落とし用のメガバンクの口座に定期振込が実行されるたびに「この支払いで本が買えたな」とか考えることはしょっちゅうでした。

奨学金を完済しての心境

特に生活に大きな変化はありませんが、それでもこれからは年間で数十万円の返済がなくなって、年に1回はちょっとした良い旅行に行けるかと思うと、ささやかな喜びを感じます。

奨学金を貸与してもらえなければ、大学にも行けていなかったし、自分がプログラミングのアルバイトをすることもなかったし、きっと外資系IT企業に勤めることもなかったので、今のこの状況にはなってなかったと考えると、感謝しています。しかしながら、贅沢を言うならば、自分も給付型の奨学金が得られていたら、もう少し精神的にすり減ること無く過ごせた時間はあっただろうなと感じています。ルサンチマンとまでは言わないけれど、あの鬱屈した心境はこれから先の生活ではしていきたくないと感じています。

www.jiji.com

給付型奨学金の拡充を行う政策が発表されました。試験一発でキャリアをつかめるチャンスがあるというのは公平性の観点でとても素晴らしいことだと考えています。そして奨学金は家庭の経済状況の差によるハンデを埋めるための素晴らしい制度だと思います。より多くの人にチャンスが行き渡る制度がこれからも維持されることを願っています。

明日は @hiroakis_ の「マンション・リノベ・郊外」に関する話の予定です。

*1:大学の授業料は大学1年後期から半期ごとに免除の申請をして全額免除や半額免除にしてもらっていたので、なんとかなっていました。

*2:今見てみたらまだその物件が残っていて、専有面積10平米とかで驚きました。

*3:当時はGoogle日本法人のエンジニア採用が始まったばかりで、一応応募したけれどレベルが高すぎて通らなかったことを思い出しました。

OpenTelemetryでgRPCのヘルスチェックのトレースを無視する

はじめに

OpenTelemetryを使ってgRPCのトレースを楽に取ろうと思うと otelgrpc を使ってよしなにリクエストのトレースを取っていることと思います。

たとえばサーバー側であれば

interceptorOpt := otelgrpc.WithTracerProvider(otel.GetTracerProvider())
srv := grpc.NewServer(
        grpc.UnaryInterceptor(otelgrpc.UnaryServerInterceptor(interceptorOpt)),
        grpc.StreamInterceptor(otelgrpc.StreamServerInterceptor(interceptorOpt)),
    )

クライアント側であれば

interceptorOpt := otelgrpc.WithTracerProvider(otel.GetTracerProvider())
*conn, err = grpc.DialContext(ctx, addr,
    grpc.WithTransportCredentials(insecure.NewCredentials()),
    grpc.WithUnaryInterceptor(otelgrpc.UnaryClientInterceptor(interceptorOpt)),
    grpc.WithStreamInterceptor(otelgrpc.StreamClientInterceptor(interceptorOpt)),
)

といった具合にOpenTelemetry用のインターセプターを挿入することになると思います。（あえて明示的にTracerProviderを指定していますが、globalなものを使うのであればこれは必要ありません）

しかし、これをこのまま実行すると、KubernetesなどでgRPCのヘルスチェックをしているようなときに、そのトレースまで送られてしまいます。つぎのスクリーンショットで大量の grpc.health.v1.Health/Check のトレースが見えています。（分布図の最下部あるトレースがそれ。スクリーンショットは1つだけハイライトしたもの。）

実際にこれが鬱陶しいのでフィルターをOpenTelemetry側でしてほしいという要望がいくつか出ています。（1つは私が起票したものですが...）

• Filter out health check request in grpc · Issue #373 · open-telemetry/opentelemetry-python-contrib · GitHub
• Investigate GRPC Tracer to support filtering or exclude the Health Checking Protocol. · Issue #355 · open-telemetry/opentelemetry-go-contrib · GitHub

これは当然で、単純に無駄なトレースが大量に表示されてダッシュボードが見づらくなるだけでなく、従量課金になっているようなサービスではコストの無駄になります。そこでワークアラウンドが欲しくなります。

WithSamplerでワークアラウンドする

特定のトレースを取得するかどうかをAPIで差し込める余地は実は殆ど無く、あるとしたら

• 自らexporterを書いて特定のトレースはバックエンドに送らないようにする（あるいはexporterによってはそのようなオプションがあるかも）
• Samplerを自分で書く

くらいしかありません。前者は実現したい事柄に対してのワークアラウンドが大きすぎるので非現実的です。後者は多少コードは多くなるけれど、まだ許容できる範囲なので、こちらでやっていこうと思います。

import sdktrace "go.opentelemetry.io/otel/sdk/trace"

func IgnoreWithNameSampler(targets []string) sdktrace.Sampler {
    return ignoreWithNameSampler{
        targets: targets,
    }
}

type ignoreWithNameSampler struct {
    targets []string
}

func (s ignoreWithNameSampler) Description() string {
    return "drop all spans with the name that contains one of targets."
}

func (s ignoreWithNameSampler) ShouldSample(p sdktrace.SamplingParameters) sdktrace.SamplingResult {
    ts := trace.SpanContextFromContext(p.ParentContext).TraceState()
    for _, t := range s.targets {
        if strings.Contains(p.Name, t) {
            return sdktrace.SamplingResult{
                Decision:   sdktrace.Drop,
                Tracestate: ts,
            }
        }
    }
    return sdktrace.SamplingResult{
        Decision:   sdktrace.RecordAndSample,
        Tracestate: ts,
    }
}

これを作ったらあとは普通にTraceProviderにSamplerとして指定するだけです。

tp := sdktrace.NewTracerProvider(
    sdktrace.WithSampler(IgnoreWithNameSampler([]string{"grpc.health.v1.Health/Check"})),
    sdktrace.WithBatcher(exporter),
)

紹介してきましたが、本来であれば TraceIDRatioBasedなどと組み合わせて簡単にやりたいはずなので、標準で持っていてくれていいはずなのにとは思います。

追記（2022.07.12 14:30）

レポートと共にPull Requestを出した。

github.com

追記（2022.08.17 16:30）

Pull Requestが無事にマージされたのでこれからは go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc/filters を使えば簡単にフィルターできます。

github.com

OpenTelemetryでSpanのレイテンシーを取得する

はじめに

分散トレースでリクエスト全体の中でのボトルネックを発見すると同時に、ユーザーに対するSLOとしてトレース全体のレイテンシーを取得することもあると思います。その場合OpenTelemetryではすんなりとルートSpanのレイテンシーを取得できないため、その方法をメモしておきます。

バージョン

• OpenTelemetry for Go: v1.7.0

通常の計装

まずこういう典型的な計装があったとします。

func sleepHandler(w http.ResponseWriter, r *http.Request) {
    tracer := otel.Tracer("handler.sleep")
    ctx := context.Background()
    ctx, span := tracer.Start(ctx, "request.sleep")
    defer span.End()
    ...(なにかする)...
}

この span にかかったレイテンシーを取得したいとします。しかし go.opentelemetry.io/otel/trace.Span には開始時刻と終了時刻のタイムスタンプを取得するメソッドが定義されていません。

しかし直感でも分かる通り、また仕様でも定義されている通り、Spanはその開始時刻と終了時刻を保持しているので、アクセスするためのインターフェースがどこかにあるはずです。

github.com

tracesdk.ReadOnlySpanに変換する

で、よくコードを読んでみると go.opentelemetry.io/otel/sdk/trace.ReadOnlySpan にはそのためのインターフェースが定義されています。

pkg.go.dev

したがって、上記計装から次のようにすれば span のレイテンシーを取得できます。

func sleepHandler(w http.ResponseWriter, r *http.Request) {
    tracer := otel.Tracer("handler.sleep")
    ctx := context.Background()
    ctx, span := tracer.Start(ctx, "request.sleep")
    ...(なにかする)...
    span.End()
    ro := span.(tracesdk.ReadOnlySpan)
    start, end := ro.StartTime(), ro.EndTime()
    duration := end - start
    ...(durationをメトリクスとしてバックエンドに送る)...
}

注意することとしては span.End() を先に呼んでいないとspanのendtimeが打刻されないので、defer span.End() にしていた部分は何かしら書き換えないといけないということです。

他の言語でも同様

上記の例はすべてGoで書いていたけれど、OpenTelemetryは仕様が全言語でインターフェースレベルで共通で実装されているので、おおよそこういった実装は他の言語でも共通になっています。

• Java
  • Span - opentelemetry-api 1.14.0 javadoc
  • ReadableSpan - opentelemetry-sdk-trace 1.14.0 javadoc
• Python
  • opentelemetry.trace.span — OpenTelemetry Python documentation
  • opentelemetry.sdk.trace package — OpenTelemetry Python documentation

2022.06.15 追記

OpenTelemetryの仕様 によると、No-op Tracerの場合はそもそもReadOnlySpanにキャストできない様子なので、その場合の対応は考える必要がありそうです。

SimplerのSliceで切り取った音をMIDIノートに割り振って鳴らす

やりたかったこと

サンプリング音源（aac、mp3など）を更に切り取ってMIDIのノートに割り当て、アレンジした形で鳴らす

手順

まず Instruments > Simpler を選択して、適当にトラックにドラッグ・アンド・ドロップする。

すると画面下部のクリップビューにサンプルを指定するようにメッセージがでるので、サンプルをドラッグ・アンド・ドロップして指定する。

するとサンプルの波形が出てくるので、Sliceのボタンを押す。

このとき Sensitivity がデフォルトだと100%になっていて、切られすぎてしまうので感度を下げてあげるといい感じに切れるところが出てくる。またPlaybackはデフォルトだと Mono になっていて、この場合ある瞬間に1つのノートしか鳴らせないので、複数の音を出したい場合には Poly にしておく。Poly に変更すると Voices という項目が増えるが、これは同時に鳴らせる音の最大数。

ここでスライスは水色の線で切られるが、もし切り取り位置が気に入らなければ、水色の線の上部にある下三角を移動させれば切り取り位置が変更できる。

これで鳴らす準備ができたので、次にどのノートがどの音に割り当てられてるか簡単に確認する。画面を見て左から数えていってもいいのだけれども、鍵盤を押して確認するほうが楽なのでその方法で行う。MIDIコンがある場合はまた別だけども、とりあえずPCキーボードのまま確認する場合は、画面右上の鍵盤アイコンをクリックする。

また録音モードにしておかないと自由に鍵盤を鳴らせないのでSimplerを載せているトラックの右側にある音符アイコンを赤くなるようにクリックする。

適当にクリップを作成するとピアノロールが出てくるので、ここでキーボードのAをドに見立てて鍵盤の要領で押していくと、割り当てられた音が鳴る。このときデフォルトだとC3にになっているはずなので、Zを押してオクターブをC1まで下げることを忘れないようにする。鍵盤を押すとピアノロールで該当する鍵盤が赤くなるので何を押したかがわかる。もしその鍵盤に先程スライスした音源が割り当てられていれば音が鳴る。（キー配置に関してはこの記事を参照）

音がわかったら、あとは適当にピアノロールを使ってクリップ内にノートを配置していく。

配置したらスペースキーを押すか、画面上部の再生ボタン（三角）を押して再生。するとこういう感じに音が鳴らせます。

soundcloud.com

少しAbleton Liveの使い方を学べました。

Ableton Live11攻略BOOK