Always-On Profiling & DB Query Performance

15 minutes

前の章で見てきたように、APMを使用して、コードに触れることなく、さまざまなサービス間のインタラクション (interaction) をトレース (trace) することができ、問題をより迅速に特定できます。

トレーシング (tracing) に加えて、automatic discovery and configurationは、問題をさらに迅速に発見するのに役立つ追加機能を最初から提供します。このセクションでは、そのうちの2つを見ていきます：

Always-on Profiling and Java Metrics
Database Query Performance

Always-on ProfilingまたはDB-Queryパフォーマンス (performance) についてさらに深く学びたい場合は、Debug Problems in Microservicesという別のNinja Workshopがありますので、そちらをご覧ください。

Always-On Profiling & Metrics

先ほどHelmチャート (chart) を使用してSplunk Distribution of the OpenTelemetry Collectorをインストール (install) した際、AlwaysOn ProfilingとMetricsを有効にするように設定しました。これにより、OpenTelemetry Javaはアプリケーション (application) のCPUとメモリ (memory) のプロファイリング (profiling) を自動的に生成し、Splunk Observability Cloudに送信します。

PetClinicアプリケーションをデプロイ (deploy) してアノテーション (annotation) を設定すると、collectorは自動的にアプリケーションを検出し、トレース (trace) とプロファイリング (profiling) のためにインストルメント (instrument) します。これを確認するために、次のスクリプト (script) を実行して、インストルメント (instrument) しているJavaコンテナ (container) の1つの起動ログ (log) を調べることができます：

ログ (log) には、Javaの自動検出と設定によって取得されたフラグ (flag) が表示されます：

.  ~/workshop/petclinic/scripts/get_logs.sh

2024/02/15 09:42:00 Problem with dial: dial tcp 10.43.104.25:8761: connect: connection refused. Sleeping 1s
2024/02/15 09:42:01 Problem with dial: dial tcp 10.43.104.25:8761: connect: connection refused. Sleeping 1s
2024/02/15 09:42:02 Connected to tcp://discovery-server:8761
Picked up JAVA_TOOL_OPTIONS:  -javaagent:/otel-auto-instrumentation-java/javaagent.jar
Picked up _JAVA_OPTIONS: -Dspring.profiles.active=docker,mysql -Dsplunk.profiler.call.stack.interval=150
OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
[otel.javaagent 2024-02-15 09:42:03:056 +0000] [main] INFO io.opentelemetry.javaagent.tooling.VersionLogger - opentelemetry-javaagent - version: splunk-1.30.1-otel-1.32.1
[otel.javaagent 2024-02-15 09:42:03:768 +0000] [main] INFO com.splunk.javaagent.shaded.io.micrometer.core.instrument.push.PushMeterRegistry - publishing metrics for SignalFxMeterRegistry every 30s
[otel.javaagent 2024-02-15 09:42:07:478 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger - -----------------------
[otel.javaagent 2024-02-15 09:42:07:478 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger - Profiler configuration:
[otel.javaagent 2024-02-15 09:42:07:480 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -                  splunk.profiler.enabled : true
[otel.javaagent 2024-02-15 09:42:07:505 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -                splunk.profiler.directory : /tmp
[otel.javaagent 2024-02-15 09:42:07:505 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -       splunk.profiler.recording.duration : 20s
[otel.javaagent 2024-02-15 09:42:07:506 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -               splunk.profiler.keep-files : false
[otel.javaagent 2024-02-15 09:42:07:510 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -            splunk.profiler.logs-endpoint : http://10.13.2.38:4317
[otel.javaagent 2024-02-15 09:42:07:513 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -              otel.exporter.otlp.endpoint : http://10.13.2.38:4317
[otel.javaagent 2024-02-15 09:42:07:513 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -           splunk.profiler.memory.enabled : true
[otel.javaagent 2024-02-15 09:42:07:515 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -             splunk.profiler.tlab.enabled : true
[otel.javaagent 2024-02-15 09:42:07:516 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -        splunk.profiler.memory.event.rate : 150/s
[otel.javaagent 2024-02-15 09:42:07:516 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -      splunk.profiler.call.stack.interval : PT0.15S
[otel.javaagent 2024-02-15 09:42:07:517 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -  splunk.profiler.include.internal.stacks : false
[otel.javaagent 2024-02-15 09:42:07:517 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger -      splunk.profiler.tracing.stacks.only : false
[otel.javaagent 2024-02-15 09:42:07:517 +0000] [main] INFO com.splunk.opentelemetry.profiler.ConfigurationLogger - -----------------------
[otel.javaagent 2024-02-15 09:42:07:518 +0000] [main] INFO com.splunk.opentelemetry.profiler.JfrActivator - Profiler is active.

私たちが注目しているのは、com.splunk.opentelemetry.profiler.ConfigurationLoggerによって書き込まれたセクション、つまりProfiling Configurationです。

splunk.profiler.directoryなど、制御できるさまざまな設定を確認できます。これは、エージェント (agent) がSplunkに送信する前にコールスタック (call stack) を書き込む場所です。（これは、コンテナ (container) の設定方法によって異なる場合があります。）

変更したいもう1つのパラメータ (parameter) はsplunk.profiler.call.stack.intervalです。これは、システム (system) がCPU Stack traceをキャプチャ (capture) する頻度です。Pet Clinicアプリケーションのような短いスパン (span) がある場合は、このインターバル (interval) 設定を短くすることをお勧めします。デモ (demo) アプリケーションでは、デフォルト (default) のインターバル (interval) 値を変更しなかったため、スパン (span) に常にCPU Call Stackが関連付けられているとは限りません。

これらのパラメータ (parameter) を設定する方法はこちらで確認できます。以下の例では、deployment.yamlでコールスタック (call stack) のより高い収集レート (rate) を設定する方法を示しています。これは、JAVA_OPTIONS configセクション (section) でこの値を設定することで行います。

env:
- name: JAVA_OPTIONS
  value: "-Xdebug -Dsplunk.profiler.call.stack.interval=150"

Trace Waterfall内のAlways-On Profiling

APM Waterfall ビューでオリジナルの Trace & Span (1)（または類似のもの）を選択し、右側のペイン (pane) から**Memory Stack Traces (2)**を選択してください：

ペイン (pane) に Memory Stack Trace Flame Graph **(3)**が表示されます。スクロール (scroll) するか、ペイン (pane) の右側をドラッグ (drag) して拡大できます。

AlwaysOn Profiling は、アプリケーション (application) のコード (code) のスナップショット (snapshot)、つまりスタックトレース (stack trace) を常に取得しています。何千ものスタックトレース (stack trace) を読まなければならないことを想像してみてください！それは現実的ではありません。これを支援するために、AlwaysOn Profiling はプロファイリング (profiling) データ (data) を集約して要約し、Flame Graphと呼ばれるビュー (view) で Call Stacks を探索する便利な方法を提供します。これは、アプリケーション (application) からキャプチャ (capture) されたすべてのスタックトレース (stack trace) の要約を表します。Flame Graph を使用して、パフォーマンス (performance) の問題を引き起こしている可能性のあるコード (code) の行を発見し、コード (code) に加えた変更が意図した効果を持っているかどうかを確認できます。

Always-on Profiling をさらに詳しく調べるには、Memory Stack Tracesの下の Profiling Pane で上の画像で参照されている Span **(3)**を選択してください。これにより、Always-on Profiling のメイン (main) 画面が開き、Memory ビュー (view) があらかじめ選択されています：

Time フィルタ (filter) は、選択したスパン (span) の時間枠に設定されます (1)
Java Memory Metric Charts **(2)**では、Heap Memoryのモニター (monitor)、Memory Allocation RateやGarbage Collecting Metrics などのApplication Activityを確認できます。
スパン (span) **(3)**に関連するメトリクス (metrics) と Stack Traces のみにフォーカス/表示する機能。これにより、必要に応じて Java アプリケーション (application) で実行されているバックグラウンド (background) アクティビティ (activity) をフィルタ (filter) で除外できます。
識別された Java Function calls **(4)**により、その関数から呼び出されたメソッド (method) にドリルダウン (drill down) できます。
プロファイル (profile) されたサービス (service) のスタックトレース (stack trace) に基づく階層の視覚化を持つ Flame Graph (5)。
サービス (service) が複数のバージョン (version) を起動する場合に備えて、Service instance **(6)**を選択する機能。

さらなる調査のために、UI ではスタックトレース (stack trace) をクリックして、呼び出された関数と、フレームチャート (flame chart) から関連する行を確認できます。これを使用して、コーディング (coding) プラットフォーム (platform) で実際のコード (code) の行を表示できます（もちろん、お好みのコーディング (coding) プラットフォーム (platform) によって異なります）。

Database Query Performance

Database Query Performanceを使用すると、Splunk APMで直接、データベース (database) クエリ (query) がサービス (service) の可用性に与える影響をモニター (monitor) できます。これにより、データベース (database) をインストルメント (instrument) することなく、長時間実行されるクエリ (query)、最適化されていないクエリ (query)、または重いクエリ (query) を迅速に特定し、それらが引き起こしている可能性のある問題を軽減できます。

データベース (database) クエリ (query) のパフォーマンス (performance) を確認するには、ブラウザ (browser) で戻るか、メニュー (menu) バー (bar) のAPMセクション (section) に移動してAPMのService Mapページ (page) に移動し、Service Mapタイル (tile) をクリックします。

Dependency mapで推論されたデータベース (database) サービス (service) mysql:petclinic Inferred Database serverを選択し (1)、次に右側のペイン (pane) をスクロール (scroll) してDatabase Query Performance Pane **(2)**を見つけます。

マップ (map) で選択したサービス (service) が実際に（推論された）データベース (database) サーバー (server) である場合、このペイン (pane) には期間に基づく上位90%（P90）のデータベース (database) コール (call) が表示されます。db-queryパフォーマンス (performance) 機能をさらに詳しく調べるには、ペイン (pane) の上部にあるDatabase Query Performanceという単語のどこかをクリックします。

これにより、DB-query Performanceの概要画面が表示されます：

Database Query Normalization

デフォルト (default) では、Splunk APMインストルメンテーション (instrumentation) はデータベース (database) クエリ (query) をサニタイズ (sanitize) して、db.statementsからシークレット (secret) や個人を特定できる情報（PII）などの機密データ (data) を削除またはマスク (mask) します。データベース (database) クエリ (query) の正規化 (normalization) をオフにする方法はこちらで確認できます。

この画面には、Splunk Observability Cloudに送信されたTraces & Spansに基づいて、アプリケーション (application) からデータベース (database) に対して実行されたすべてのDatabase queries **(1)**が表示されます。時間ブロック (block) 間で比較したり、Total Time、P90 Latency & Requests **(2)**でソート (sort) したりできることに注意してください。

リスト (list) 内の各Database queryについて、時間ウィンドウ (window) 中の最高レイテンシ (latency)、コール (call) の総数、および1秒あたりのリクエスト (request) 数 **(3)**が表示されます。これにより、クエリ (query) を最適化できる場所を特定できます。

右側のペイン (pane) **(5)**の2つのチャート (chart) を使用して、Database Callsを含むトレース (trace) を選択できます。Tag Spotlightペイン (pane) **(6)**を使用して、エンドポイント (endpoint) やタグ (tag) に基づいて、データベース (database) コール (call) に関連するタグ (tag) を確認します。

クエリ (query) の詳細ビュー (view) を表示する必要がある場合：

特定のQuery **(1)**をクリックします。これにより、Query Details pane **(2)**が開き、より詳細な調査に使用できます。

Always-On Profiling & DB Query Performance

6. Advanced Featuresのサブセクション

Always-On Profiling & Metrics

Trace Waterfall内のAlways-On Profiling

Database Query Performance