GCP Cloud Traceを使ってみた

こんにちは。次世代システム研究室のM.Mです。

最近、サーバー・アプリケーションの監視関連の作業をしていたこともあり、GCP Cloud Traceってどのようなことができるのか気になっていました。
そこで今回は、GCP Cloud Traceでどのようなことができるのか試してみました。

1. GCP Cloud Traceとは

Googleの資料には以下の記載があります。

Cloud Trace は分散トレース システムであり、アプリケーションからレイテンシ データを収集し、Google Cloud Console に表示します。アプリケーション内でやり取りされるリクエストのプロパゲートをトラックし、ほぼリアルタイムでパフォーマンスの分析情報を提供します。Cloud Trace は、アプリケーションのすべてのトレースを自動的に分析し、パフォーマンス低下の原因となるレイテンシの詳細レポートを生成します。また、すべての VM、コンテナ、App Engine プロジェクトからもトレースを取得できます。

アプリケーションからレイテンシデータを収集して、可視化、ボトルネックの検出ができるようなサービスとなっています。

2. GCP Cloud Traceを試す前の前提

GCP Cloud Traceを試すアプリケーションは、python Flask, mariaDB接続, 外部API通信ありのWEBアプリケーションとします。
以下がそのソースコードとなります。

app.py

import time

from flask import Flask
from testapp.logics.testdb import TestDb
from testapp.logics.testapi import TestApi

app = Flask(__name__)

@app.route("/")
def hello_world():
    time.sleep(0.1)
    test_db = TestDb()
    test_db.exec_db_a()
    test_db.exec_db_b()

    test_api = TestApi()
    test_api.exec_api_a()
    test_api.exec_api_b()

    return "Hello, World!"

11行目: トレース表示を分かりやすくするため0.1秒スリープしています。
12～14行目: DB操作をするTestDBクラスのexec_db_aメソッド、exec_db_bメソッドでSQL文を実行しています。
16～18行目: API操作をするTestApiクラスのexec_api_aメソッド、exec_api_bメソッドでAPIを実行しています。
最後に Hello, World!と出力しています。

DB操作とAPI操作をトレースしてほしいという意図があります。
次は、DB操作をするTestDBクラスになります。

logics/testdb.py

import time
import pymysql.cursors

class TestDb():

    def __init__(self):
        self.conn = pymysql.connect(...)

    def exec_db_a(self):
        time.sleep(0.1)
        c = self.conn.cursor()

        sql = 'select * from users;'
        c.execute(sql)

        sql = 'select * from users where id = 1;'
        c.execute(sql)

    def exec_db_b(self):
        time.sleep(0.1)
        c = self.conn.cursor()

        sql = 'select * from users;'
        c.execute(sql)

        sql = 'select * from users where id = 1;'
        c.execute(sql)

exec_db_aメソッドとexec_db_bメソッドは同じ内容になっています。
これはメソッド毎にトレースしてほしいという意図があります。

次は、API操作をするTestApiクラスになります。

logics/testapi.py

import time
import requests

class TestApi():

    def exec_api_a(self):
        time.sleep(0.1)
        r = requests.get(url='https://...')

    def exec_api_b(self):
        time.sleep(0.1)
        r = requests.get(url='https://...')

exec_api_aメソッドとexec_api_bメソッドは同じ内容になっています。
先ほどと同様、メソッド毎にトレースしてほしいという意図があります。

ソースコードはこれだけです。
では、GCP Cloud Traceを導入していきましょう。

3. GCP Cloud Traceを導入してみる

GCP Cloud Traceのマニュアルをベースに進めます

トレース用のモジュールをインストールします

pip install opentelemetry-exporter-gcp-trace \
    opentelemetry-propagator-gcp \
    opentelemetry-api \
    opentelemetry-sdk \
    opentelemetry-instrumentation-flask

ソースコードにトレースの設定を追加します

import time

from flask import Flask
from testapp.logics.testdb import TestDb
from testapp.logics.testapi import TestApi

from opentelemetry import trace
from opentelemetry.exporter.cloud_trace import (
    CloudTraceSpanExporter,
)
from opentelemetry.instrumentation.flask import (
    FlaskInstrumentor,
)
from opentelemetry.propagate import set_global_textmap
from opentelemetry.propagators.cloud_trace_propagator import (
    CloudTraceFormatPropagator,
)
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor

set_global_textmap(CloudTraceFormatPropagator())

tracer_provider = TracerProvider()
cloud_trace_exporter = CloudTraceSpanExporter()
tracer_provider.add_span_processor(
    BatchSpanProcessor(cloud_trace_exporter)
)
trace.set_tracer_provider(tracer_provider)
tracer = trace.get_tracer(__name__)


app = Flask(__name__)
FlaskInstrumentor().instrument_app(app)

@app.route("/")
def hello_world():
    with tracer.start_as_current_span("do_work"):
        time.sleep(0.1)
        test_db = TestDb()
        test_db.exec_db_a()
        test_db.exec_db_b()

        test_api = TestApi()
        test_api.exec_api_a()
        test_api.exec_api_b()

    return "Hello, World!"

7～33行目にトーレス関連のimport処理と設定が追加されています。
また、既存のhello_worldメソッド内の37行目に

with tracer.start_as_current_span(“do_work”):

といったspanが追加されています。

数回アクセスして、GCPトレース画面にて結果を確認します

GCP Console画面のCloud Traceにアクセスすると以下の図のような画面が表示されます。

アクセスがあった時間帯に、青い丸が印されています。
さらにその青い丸をクリックすると、以下の図のようにトレースの詳細が見れます。

残念ながら勝手にモジュールやメソッド単位でトレースされるとかではなく、上記ソースコードの37行目にあったspanの設定をしないと細かくは確認できない模様。
また、詳細に見たいのはDBの処理時間やAPIの処理時間だったりするけど確認できず。
確認したい個所のソースコードを修正して、いちいちspanの設定追加なんてしてられない。

調べていくと、いろいろopentelemetry用のモジュールが存在していました。

opentelemetry-instrumentation-pymysql
opentelemetry-instrumentation-requests

上記モジュールを導入して、DB、API通信のトレースができるか確認してみます。

4. DB接続やAPI連携をトレースしてみる

mariaDB(mysql), API通信のモジュールインストール

pip install opentelemetry-instrumentation-pymysql
pip install opentelemetry-instrumentation-requests

mariaDB, API通信のトレース設定追加

app.pyに以下を追加するのみです

...
from opentelemetry.instrumentation.pymysql import PyMySQLInstrumentor
from opentelemetry.instrumentation.requests import RequestsInstrumentor
...
PyMySQLInstrumentor().instrument()
RequestsInstrumentor().instrument()
...

数回アクセスして、GCPトレース画面にて結果を確認します

mariaDB(mysql)、API通信のモジュールを追加しただけで、以下の図のような結果になりました。

select、HTTP GETにどれぐらい時間がかかったのか分かるようになりました。

selectの個所を選択すると、以下の図のようにどのSQLか分かるようになっています。

同様にHTTP GETの個所を選択すると、以下の図のようにどのURL、ステータスコードだったかも分かるようになっています。

DB処理やAPI処理についてのトレースもできることが分かりました。
ただ、どのメソッドの処理であるかを分かるようにするには、やはりspanの追加が必要になりそうです。
非常に面倒です。せいぜいデコレータを作って楽にするぐらいでしょうか・・。
デコレータを作って各メソッドに設定して試してみます。

5. メソッド単位でトレースしてみる

作ったデコレータは以下になります。

logics/trace_deco.py

from functools import wraps
from opentelemetry import trace

def add_trace_span(f):
    @wraps(f)
    def wrapper(*args, **kwargs):
      tracer = trace.get_tracer(__name__)
      with tracer.start_as_current_span(name=f.__qualname__):
        return f(*args, **kwargs)

    return wrapper

8行目でspanの設定をしています。

後は、このデコレータをimportして以下のように各種メソッドに追加するのみです。

from testapp.logics.trace_deco import add_trace_span

@add_trace_span
def exec_db_a(self):

すると以下の図のようにメソッド毎に表示させることができました。

それほど大きなソースコードの修正はなく、各メソッドやDB、API処理のパフォーマンスが分かるようになりました。
ただ、トレース処理を追加したことでのパフォーマンス影響が気になります。

6. GCP Cloud Traceのパフォーマンス影響

Cloud Traceを導入していない初期の状態と、上記で実施したCloud Traceを導入した最後の状態で比較してみます。
以下は、すべて秒間3リクエストを2分間実行した結果になります。

初期の状態

非常に安定しています。

Cloud Trace導入後の状態

初期の状態と比べて定期的に遅くなっているのが分かります。

やはり多少影響があるのが分かりました。
ただ、たまに発生する外れ値的な大きな遅延を調べたいとかではない限り、全リクエストをサンプリングする必要もないので、サンプリング率を変えて実行してみます。

app.pyのtrace_providerの設定を以下のように変更します。

from opentelemetry.sdk.trace.sampling import TraceIdRatioBased
sampler = TraceIdRatioBased(1/50)

tracer_provider = TracerProvider(sampler=sampler)

すると、以下の図のように遅延は目立たなくなりました。

初期の状態と比べても大きな違いがなくなりました。
また、実際にサンプリングされた数は以下の図のように、少なくなっているのが分かります。

左側の大量にある青い丸がサンプリング設定なしの結果、右側がサンプリング設定ありの結果になっています。
リクエスト数が同じなのに、サンプリングされた数が減っているのが分かります。

まとめ

Google Cloud Traceを簡単に導入することができました。
ただ多少実装が必要であったり、パフォーマンス影響もあったので、既存のすでにパフォーマンス改善が求められている大規模なサービスへの導入は慎重に進めたほうがよいと感じました。
理想は、パフォーマンス改善が求められていない初期の段階で導入し、さらにCPU利用率などの情報も見れるGCP Cloud Profilerと合わせて導入できるといいなと感じました。

最後に、次世代システム研究室では、グループ全体のインテグレーションを支援してくれるアーキテクトを募集しています。アプリケーション開発の方、次世代システム研究室にご興味を持って頂ける方がいらっしゃいましたら、ぜひ募集職種一覧からご応募をお願いします。

皆さんのご応募をお待ちしています。