Datadog Advent Calendar 2025

Datadog & ISUCONで始めるパフォーマンスチューニング入門

Last updated at 2025-11-30Posted at 2025-11-30

この記事では、Datadogを活用してパフォーマンスチューニングを行う方法について、ISUCON（Iikanjini Speed Up Contest：お題となるWebサービスを高速化するコンテスト）を題材に解説します。

この記事では、以下のような初学者〜中級者を対象としています。

パフォーマンスチューニングやObservabilityに興味があるけど、何から始めて良いかわからない人
多機能なDatadogの使いこなし方を知りたい人
ISUCONで計測するための環境構築に苦戦している人

サマリ

Datadogを活用することで、CPUやメモリなどのホストのメトリクス、プロセスの情報、ログの解析やDBのスロークエリの可視化を用いて、ボトルネックの特定が容易になります。さらに、Profilerやクエリの実行計画の情報を活用することで、パフォーマンスの改善に繋げることもできます。Datadogを使うことで、Observability全体を一つのUIに集約することができ、管理が非常に楽になります。

なお、Datadogには無料プランが存在します。メトリクスの保存期間が1日だったり、最大で5ホストまでしか管理できなかったり制約は存在しますが、ISUCONを行う上では十分無料プランの範囲内でも活用することが可能です。

本記事では、次の画像のようなDatadogのダッシュボードを作成し、ISUCON14の環境でパフォーマンスチューニングを行う手順を解説します。

ISUCON14の概要

本記事では、2024年12月に開催されたISUCON14を例に取り上げます。ISUCON14では、椅子のライドシェアのマッチングサービスが題材となっています。

参考：ISUCON14の解説記事

サービスの構成は以下の通りです。

ISUCON14環境の構築

ISUCON14の環境をローカルで構築するには、以下のリポジトリのREADMEから、ISUCON14のAMIをクリックします。AWSマネジメントコンソールに遷移するので、インスタンスタイプはc5.large、インスタンス数は3を選択して、EC2インスタンスを立ち上げます。

インスタンスが立ち上がったら、インスタンスを選択→接続→EC2 Instance Connectを使ってrootユーザーで実行し、isuconユーザーでsshできるように以下のコマンドを実行します。

sudo -i -u isucon

=== User: isucon ===

mkdir -p ~/.ssh
sudo cp /home/ubuntu/.ssh/authorized_keys ~/.ssh/
sudo chown isucon:isucon ~/.ssh/authorized_keys

必要に応じて、SSH configを設定します（以下、本記事では、この設定を前提とします）。

~/.ssh/config

Host isucon*
    IdentityFile <path-to-your-private-key>
    User isucon
Host isucon-1
    HostName <Public-IP-address-of-instance-1>
Host isucon-2
    HostName <Public-IP-address-of-instance-2>
Host isucon-3
    HostName <Public-IP-address-of-instance-3>

ベンチマークを実行するインスタンスとサービスを実行するインスタンスを分離するため、HTTPS(443番ポート)の通信を許可するセキュリティグループを設定します。（なお、ISUCON本番で行うとレギュレーション違反になる可能性があるため、注意してください。）

また、証明書の有効期限が切れているため、isuride-matcher.serviceのcurlコマンドに-kオプションを追加して、証明書の検証をスキップするように修正します。

/etc/systemd/system/isuride-matcher.service

[Service]
- ExecStart=/bin/sh -c "while true; do curl -s https://isuride.xiv.isucon.net/api/internal/matching; sleep $ISUCON_MATCHING_INTERVAL; done"
+ ExecStart=/bin/sh -c "while true; do curl -sk https://isuride.xiv.isucon.net/api/internal/matching; sleep $ISUCON_MATCHING_INTERVAL; done"

まずは、何もチューニングしていない状態でベンチマークを実行し、スコアが確認できたら準備は完了です。

ssh isucon-3

=== Host: isucon-3 ===

./bench run . run --addr <Public-IP-address-of-instance-1>:443 --target https://isuride.xiv.isucon.net --payment-url http://127.0.0.1:12346 --payment-bind-port 12346
# time=13:26:46.656 level=INFO msg=結果 pass=true スコア=568 種別エラー数="map[5:199 26:1]"

では、ここからDatadogを活用してパフォーマンスチューニングを進めていきます。

Datadogエージェントのインストール

インスタンスのイベントやメトリクスを収集するため、Datadogエージェントをインストールします。Datadogエージェントの設定はインストール時に環境変数で指定することもできますが、より明示的に設定するため、事前に設定ファイルを用意しておきます。

ホスト名は各インスタンスごとにisucon-1、isucon-2、isucon-3のように設定したので、hostname_fileオプションを利用すると設定ファイルは共通化できて便利です。各インスタンスごとに/var/lib/cloud/data/instance-nameファイルにインスタンス名を保存しておきます。

/var/lib/cloud/data/instance-name

isucon-1

/etc/datadog-agent/datadog.yaml

#########################
## Basic Configuration ##
#########################

api_key: <your-datadog-api-key>
site: ap1.datadoghq.com
dd_url: https://ap1.datadoghq.com
hostname_file: /var/lib/cloud/data/instance-name
# env: isucon
collect_ec2_instance_info: true

##################################
## Log collection Configuration ##
##################################

logs_enabled: true

####################################
## Trace Collection Configuration ##
####################################

apm_config:
  enabled: true

######################################
## Process Collection Configuration ##
######################################

process_config:
  process_collection:
    enabled: true

Datadogエージェントのインストールは、以下のコマンドで行います。

bash -c "$$(curl -L https://install.datadoghq.com/scripts/install_script_agent7.sh)"

なお、Datadogエージェントのインストールは各インスタンスで行う必要があります。

ここまでの設定が完了したら、Datadogの画面上で、各インスタンスのメトリクスが収集されていることを確認します。

Infrastructure > Hostsを開くと、Datadogエージェントがインストールされた各インスタンスが表示されていることが確認できます。（反映されるまでには10分程度の時間がかかります。）

また、各インスタンスをクリックすると、CPUコア数やインスタンスのリージョンなどの情報を確認することができます。

この状態でベンチマークを再度実行すると、Infrastructure > Processesからプロセスの一覧も取得することができるようになっています。CPUが高負荷になっており、isucon-1のmysqldプロセスがボトルネックになっていることが確認できます。

Datadog APMの設定

Orchestrionの導入

Goアプリケーションの場合、Orchestrionを導入することで、自動的にトレースを収集することができます。Orchestrionはコンパイル時にアプリケーションのコードを解析し、必要なトレースコードを自動的に挿入するため、非常に簡単に導入することができます。

ただし、ISUCON14のGoアプリケーションはGo 1.23で動作しているため、Orchestrionの最新バージョンを利用するにはGoのバージョンを1.24以上にアップグレードする必要があります。
加えて、Orchestrionは依存関係が多いため、ディスク容量に余裕がないISUCON環境では利用しない言語の開発ツールを削除することをお勧めします。

# Go1.24.10のインストール
cd /tmp
wget https://go.dev/dl/go1.24.10.linux-amd64.tar.gz
rm -rf /home/isucon/local/golang
mkdir -p /home/isucon/local
tar -C /home/isucon/local -xzf /tmp/go1.24.10.linux-amd64.tar.gz
rm -rf /tmp/go1.24.10.linux-amd64.tar.gz
echo 'export PATH=/home/isucon/local/go/bin:$PATH' >> /home/isucon/.bash_profile

# golang以外の開発ツールを削除してディスク容量を節約
	rm -rf \
		/home/isucon/.rustup\
		/home/isucon/.cargo \
		/home/isucon/.perl-cpm \
		/home/isucon/.npm \
		/home/isucon/.bundle \
		/home/isucon/.cpanm \
		/home/isucon/local/php \
		/home/isucon/local/node \
		/home/isucon/local/ruby \
		/home/isucon/local/perl \
		/home/isucon/webapp/rust \
		/home/isucon/webapp/nodejs \

Goアプリケーションのディレクトリに移動し、Orchestrionをインストールします。

cd webapp/golang
go install github.com/DataDog/orchestrion@latest
go mod tidy
orchestrion pin

アプリケーションのコードは変更不要ですが、ビルドコマンドをOrchestrionを使ったものに変更します。

- go build -o isuride
+ orchestrion go build -o isuride

# ビルド後には、アプリケーションを再起動します
sudo systemctl restart --now isuride-go.service

再度ベンチマークを実行すると、APM > Software Catalog > Servicesから、Goアプリケーションのサービスを含めいくつかのサービスが表示されていることが確認できます。

isurideサービスをクリックし、Queriesを確認すると、isurideから発行されたSQLクエリの一覧とそのレスポンスタイムが表示されていることがわかります。

また、chi.routerサービス（chiはGoのHTTPルーターライブラリ）をクリックし、Endpointsを確認すると、各エンドポイントのレスポンスタイムや呼び出し回数などの情報が表示されていることが確認できます。

Goアプリケーションのプロファイリング設定

Orchestrionを導入しただけでも基本的なトレースは収集できますが、より詳細なプロファイリング情報を収集するために、Datadogのプロファイラーを導入します。プロファイラーを導入することで、アプリケーション内のボトルネックを詳細に特定することができます。

Goアプリケーションのディレクトリに移動し、Datadogのトレーサー（プロファイラーを含む）をインストールします。

go get gopkg.in/DataDog/dd-trace-go.v1/profiler

アプリケーションのコードに以下のようにプロファイラーの初期化コードを追加します。

go/main.go

import (
    "log"
    "gopkg.in/DataDog/dd-trace-go.v1/profiler"
)

func main() {
    os.Setenv("DD_PROFILING_EXECUTION_TRACE_ENABLED", "true")
    os.Setenv("DD_PROFILING_EXECUTION_TRACE_PERIOD", "1m")

    ...

    err := profiler.Start(
		profiler.WithService("isuride"),
		profiler.WithProfileTypes(
			profiler.CPUProfile,
			profiler.HeapProfile,
			profiler.BlockProfile,
			profiler.MutexProfile,
			profiler.GoroutineProfile,
    	),
	)
	if err != nil {
		log.Fatal(err)
	}
	defer profiler.Stop()

    // http.ListenAndServe(":8080", mux)よりも前に呼び出すこと
}

その後、以下のコマンドでアプリケーションを再ビルドし、再起動します。

go mod tidy
orchestrion go build -o isuride
sudo systemctl restart --now isuride-go.service

プロファイラーの設定が完了したら、APM > Profilesからisuride-goサービスを選択して、プロファイル情報が収集されていることを確認します。

また、DD_GIT_REPOSITORY_URLおよびDD_GIT_COMMIT_SHA環境変数を設定することで、ProfilesやError Trackingなどの情報にソースコードを紐付けることができます。これにより、ボトルネックやエラーの分析時に、該当するソースコードを確認することができ、原因の特定が容易になります。

ただし、ISUCON環境ではsystemdのサービスファイルが用意されているため、環境変数を直接設定することができません。そのため、EnvironmentFileオプションを利用して、環境変数を設定します。

config/isuride-go.service

[Service]
EnvironmentFile=-/home/isucon/env_extra.sh

ExecStartPre=/bin/bash -c '\
    echo "" > /home/isucon/env_extra.sh; \
    echo DD_GIT_REPOSITORY_URL="<your-git-repository-url>" >> /home/isucon/env_extra.sh; \
    echo DD_GIT_COMMIT_SHA="$(git -C /home/isucon/webapp rev-parse HEAD)" >> /home/isucon/env_extra.sh; \
'
ExecStart=/home/isucon/webapp/go/isuride

Database Monitoringの設定

Orchestrionを導入しただけでも基本的なクエリの情報は収集できますが、クエリの実行計画など、より詳細な情報を収集するために、Database Monitoringの設定を行います。

設定手順については、IntegrationsからMySQLを選択したり、以下のドキュメントを参照したりすることで確認できますので、特にハマったポイントのみをコメントを記載しています。（MySQLに限らず、各種ツールとのIntegrationを行う場合は、Integrationsから該当のサービスのドキュメントを確認して設定することをお勧めします。）

https://docs.datadoghq.com/ja/integrations/mysql/?tab=host
https://docs.datadoghq.com/ja/database_monitoring/setup_mysql/selfhosted/?tab=mysql57

Database Monitoringの設定詳細

/etc/mysql/mysql.conf.d/mysqld.cnf

performance_schema=ON
# 4096では不足したクエリがあったため、8192に増加
max_digest_length=8192
performance_schema_max_digest_length=8192
performance_schema_max_sql_text_length=8192
performance-schema-consumer-events-statements-current=ON
performance-schema-consumer-events-waits-current=ON
performance-schema-consumer-events-statements-history-long=ON
performance-schema-consumer-events-statements-history=ON

mysql -u isucon -pisucon isuride

=== MySQL Client ===

CREATE USER 'datadog'@'%' IDENTIFIED BY 'password';
ALTER USER datadog@'%' WITH MAX_USER_CONNECTIONS 5;
GRANT REPLICATION CLIENT ON *.* TO datadog@'%';
GRANT PROCESS ON *.* TO datadog@'%';
--  Schema collection用にすべてのデータベースに対するSELECT権限を付与
GRANT SELECT ON *.* TO datadog@'%';

CREATE SCHEMA IF NOT EXISTS datadog;
GRANT EXECUTE ON datadog.* to datadog@'%';
GRANT CREATE TEMPORARY TABLES ON datadog.* TO datadog@'%';

DELIMITER $$
CREATE PROCEDURE datadog.explain_statement(IN query TEXT)
    SQL SECURITY DEFINER
BEGIN
    SET @explain := CONCAT('EXPLAIN FORMAT=json ', query);
    PREPARE stmt FROM @explain;
    EXECUTE stmt;
    DEALLOCATE PREPARE stmt;
END $$
DELIMITER ;

DELIMITER $$
CREATE PROCEDURE isuride.explain_statement(IN query TEXT)
    SQL SECURITY DEFINER
BEGIN
    SET @explain := CONCAT('EXPLAIN FORMAT=json ', query);
    PREPARE stmt FROM @explain;
    EXECUTE stmt;
    DEALLOCATE PREPARE stmt;
END $$
DELIMITER ;
GRANT EXECUTE ON PROCEDURE isuride.explain_statement TO datadog@'%';

DELIMITER $$
CREATE PROCEDURE datadog.enable_events_statements_consumers()
    SQL SECURITY DEFINER
BEGIN
    UPDATE performance_schema.setup_consumers SET enabled='YES' WHERE name LIKE 'events_statements_%';
    UPDATE performance_schema.setup_consumers SET enabled='YES' WHERE name = 'events_waits_current';
END $$
DELIMITER ;
GRANT EXECUTE ON PROCEDURE datadog.enable_events_statements_consumers TO datadog@'%';

/etc/datadog-agent/conf.d/mysql.d/conf.yaml

init_config:

instances:
  - dbm: true
    host: 127.0.0.1
    username: datadog
    password: password
    port: 3306
    database_autodiscovery: true
    collect_schemas:
      enabled: true
      collection_interval: 60
    query_metrics:
        enabled: true
    options:
      replication: false
      galera_cluster: true
      extra_status_metrics: true
      extra_innodb_metrics: true
      schema_size_metrics: false
      disable_innodb_metrics: false
logs:
  - type: file
    path: "/var/log/mysql/error.log"
    source: mysql
    service: "mysql"

APM > DatabasesのQuery Metricsから、適当なSQLクエリを選択すると、実行計画の情報が収集されていることが確認できます。ただし、本設定では、一部のクエリにしか実行計画が収集されないようです。（いろいろ試しましたが、原因は不明でした。）

Datadog Logsの設定

Datadogエージェントの設定ファイルでlogs_enabled: trueを設定しているため、Datadogエージェントはログ収集が有効になっています。各種サービスのログ収集設定を行うことで、ログデータをDatadogに送信されます。

例えば、Goアプリケーションはsystemdで管理されているため、journaldからログを収集するように設定します。

/etc/datadog-agent/conf.d/journald.d/conf.yaml

logs:
  - type: journald
    tags:
      - source:journald

なお、ログを収集するためには、dd-agentユーザーをsystemd-journalグループに所属させることが必要です。

sudo usermod -a -G systemd-journal dd-agent

LogsのLog Explorer画面では、ログレベルやサービス単位でのフィルタリングを行ったり、特定のキーワードでログを検索したりすることができます。また、メッセージのパターンを分析することができる非常に強力な機能も備わっており、簡単にログの分析が可能です。

Dashboardsの作成

これまで各ページで確認してきた情報を一つのダッシュボードにまとめることで、パフォーマンスチューニングの効率を向上させられます。

DashboardsからNew Dashboardをクリックし、新しいダッシュボードを作成します。各種ウィジェットを追加し、必要な情報を表示するように設定します。

まず、widgetを以下の基準で選択します。

メトリクスを時系列で表示したい場合：Timeseries
プロセスなどのランキングを表示したい場合：Top List
ログなどをリストで表示したい場合：List
ランキングを複数のカラムで表示したい場合：Query Table
Host Mapを表示したい場合：Host Map
Profilerの情報を表示したい場合：Profiling Flame Graph
要素をグループ化したい場合：Empty Group

データとしてはsystem.cpu.userなどのホストメトリクス以外にも、ProcessではTotal CPU %のようなプロセスごとのメトリクス、APM Metricsでは各サービスごとにRequestsやLatencyなどのメトリクス、LogsではLog Explorerで利用できるログデータを利用することができます。

具体的なsystem.cpu.userのようなメトリクス名はChatGPTなどの生成AIが意外と答えられるので、聞きながらダッシュボードを作成していくのが良いでしょう。

各Queryの左側の青いアルファベットをクリックすると、そのQueryをWidgetsに表示するかを選択することができます。

必要に応じてY-Axis Controlsを0から100などに設定し、見やすく調整します。

以下はISUCON14用のDatadogダッシュボードの例です。

ISUCON14用のDatadogダッシュボードの例

dashboard.json

{"title":"ISUCON","description":"[[suggested_dashboards]]","widgets":[{"id":5979718763968765,"definition":{"title":"Host Metric","background_color":"vivid_green","show_title":true,"type":"group","layout_type":"ordered","widgets":[{"id":4766443929175260,"definition":{"title":"Host Map","title_size":"16","title_align":"left","type":"hostmap","requests":{"fill":{"q":"avg:system.cpu.user{*} by {host}"}},"node_type":"host","no_metric_hosts":true,"no_group_hosts":true,"group":["region"],"style":{"palette":"green_to_orange","palette_flip":false}},"layout":{"x":0,"y":0,"width":6,"height":3}},{"id":6361532927842443,"definition":{"title":"ホスト数","title_size":"16","title_align":"left","show_legend":true,"legend_layout":"auto","legend_columns":["avg","min","max","value","sum"],"type":"timeseries","requests":[{"formulas":[{"formula":"count_nonzero(query1)"}],"queries":[{"name":"query1","data_source":"metrics","query":"sum:system.cpu.user{*} by {host}"}],"response_format":"timeseries","style":{"palette":"dog_classic","order_by":"values","line_type":"solid","line_width":"normal"},"display_type":"line"}]},"layout":{"x":6,"y":0,"width":6,"height":3}},{"id":7719411257012859,"definition":{"title":"CPU usage(user + system)","title_size":"16","title_align":"left","show_legend":true,"legend_layout":"auto","legend_columns":["avg","min","max","value","sum"],"type":"timeseries","requests":[{"response_format":"timeseries","queries":[{"name":"query1","data_source":"metrics","query":"sum:system.cpu.user{*} by {host}"},{"name":"query2","data_source":"metrics","query":"sum:system.cpu.system{*} by {host}"}],"formulas":[{"formula":"query1 + query2"}],"style":{"palette":"dog_classic","order_by":"values","line_type":"solid","line_width":"normal"},"display_type":"line"}],"yaxis":{"include_zero":true,"min":"0","max":"101"}},"layout":{"x":0,"y":3,"width":6,"height":3}},{"id":2729374559256606,"definition":{"title":"Memory usage(used/total)","title_size":"16","title_align":"left","show_legend":true,"legend_layout":"auto","legend_columns":["avg","min","max","value","sum"],"type":"timeseries","requests":[{"response_format":"timeseries","queries":[{"name":"query1","data_source":"metrics","query":"avg:system.mem.used{*} by {host}"},{"name":"query2","data_source":"metrics","query":"avg:system.mem.total{*} by {host}"}],"formulas":[{"formula":"query1 / query2 * 100"}],"style":{"palette":"dog_classic","order_by":"values","line_type":"solid","line_width":"normal"},"display_type":"line"}],"yaxis":{"include_zero":true,"min":"0","max":"100"},"custom_links":[]},"layout":{"x":6,"y":3,"width":6,"height":3}},{"id":4546434110274569,"definition":{"title":"Disk usage(in_use{device_label:/})","title_size":"16","title_align":"left","show_legend":true,"legend_layout":"auto","legend_columns":["avg","min","max","value","sum"],"type":"timeseries","requests":[{"response_format":"timeseries","queries":[{"data_source":"metrics","name":"query1","query":"avg:system.disk.in_use{device_label:cloudimg-rootfs} by {host,device}"}],"formulas":[{"formula":"query1"}],"style":{"palette":"dog_classic","order_by":"values","line_type":"solid","line_width":"normal"},"display_type":"line"}],"yaxis":{"include_zero":true,"min":"0","max":"1"}},"layout":{"x":0,"y":6,"width":6,"height":3}}]},"layout":{"x":0,"y":0,"width":12,"height":10}},{"id":4421769091912804,"definition":{"title":"Processes","background_color":"vivid_green","show_title":true,"type":"group","layout_type":"ordered","widgets":[{"id":7781275093271728,"definition":{"title":"Top CPU Processes(Total CPU)","title_size":"16","title_align":"left","type":"toplist","requests":[{"queries":[{"limit":10,"data_source":"process","name":"query1","query_filter":"","metric":"process.stat.cpu.total_pct","aggregator":"avg"}],"response_format":"scalar","formulas":[{"formula":"query1"}],"sort":{"count":10,"order_by":[{"type":"formula","index":0,"order":"desc"}]}}],"style":{"display":{"type":"stacked","legend":"automatic"}}},"layout":{"x":0,"y":0,"width":6,"height":3}},{"id":46677504244553,"definition":{"title":"Top RSS Processes(RSS Memory)","title_size":"16","title_align":"left","type":"toplist","requests":[{"queries":[{"limit":10,"data_source":"process","name":"query1","query_filter":"","metric":"process.stat.memory.rss.pct","aggregator":"avg"}],"response_format":"scalar","formulas":[{"formula":"query1"}],"sort":{"count":10,"order_by":[{"type":"formula","index":0,"order":"desc"}]}}],"style":{"display":{"type":"stacked","legend":"automatic"}}},"layout":{"x":6,"y":0,"width":6,"height":3}},{"id":794460463038895,"definition":{"title":"Top CPU Processes(Total CPU)","title_size":"16","title_align":"left","show_legend":true,"legend_layout":"auto","legend_columns":["avg","min","max","value","sum"],"type":"timeseries","requests":[{"response_format":"timeseries","queries":[{"limit":100,"data_source":"process","name":"query1","query_filter":"","metric":"process.stat.cpu.total_pct"}],"formulas":[{"formula":"query1"}],"style":{"palette":"dog_classic","order_by":"values","line_type":"solid","line_width":"normal"},"display_type":"line"}],"yaxis":{"include_zero":true,"min":"0","max":"200"}},"layout":{"x":0,"y":3,"width":6,"height":3}},{"id":4332289756586695,"definition":{"title":"Top RSS Processes(RSS Memory)","title_size":"16","title_align":"left","show_legend":true,"legend_layout":"auto","legend_columns":["avg","min","max","value","sum"],"type":"timeseries","requests":[{"response_format":"timeseries","queries":[{"limit":100,"data_source":"process","name":"query1","query_filter":"","metric":"process.stat.memory.rss.pct"}],"formulas":[{"formula":"query1"}],"style":{"palette":"dog_classic","order_by":"values","line_type":"solid","line_width":"normal"},"display_type":"line"}],"yaxis":{"include_zero":true,"min":"0","max":"100"}},"layout":{"x":6,"y":3,"width":6,"height":3}}]},"layout":{"x":0,"y":10,"width":12,"height":7}},{"id":1052029932072286,"definition":{"title":"Application Metric","background_color":"vivid_green","show_title":true,"type":"group","layout_type":"ordered","widgets":[{"id":6699949135361373,"definition":{"title":"Endpoint Performance","title_size":"16","title_align":"left","type":"query_table","requests":[{"queries":[{"data_source":"apm_metrics","name":"query1","stat":"total_time","service":"http.router","group_by":["resource_name"]},{"data_source":"apm_metrics","name":"query2","stat":"hits","service":"http.router","group_by":["resource_name"]},{"data_source":"apm_metrics","name":"query3","stat":"latency_avg","service":"http.router","group_by":["resource_name"]},{"data_source":"apm_metrics","name":"query4","stat":"latency_p95","service":"http.router","group_by":["resource_name"]},{"data_source":"apm_metrics","name":"query6","stat":"error_rate","service":"http.router","group_by":["resource_name"]}],"response_format":"scalar","sort":{"count":25,"order_by":[{"type":"formula","index":0,"order":"desc"}]},"formulas":[{"cell_display_mode":"bar","alias":"Total Time","formula":"query1"},{"cell_display_mode":"bar","alias":"Requests","formula":"query2"},{"cell_display_mode":"bar","alias":"Latency(avg)","formula":"query3"},{"cell_display_mode":"bar","alias":"Latency(95%)","formula":"query4"},{"cell_display_mode":"bar","alias":"Error Rate","formula":"query6"}]}],"has_search_bar":"auto"},"layout":{"x":0,"y":0,"width":12,"height":4}},{"id":693880429831119,"definition":{"title":"Database Performance","title_size":"16","title_align":"left","type":"query_table","requests":[{"queries":[{"data_source":"apm_metrics","name":"query1","stat":"total_time","service":"isuride","group_by":["resource_name"]},{"data_source":"apm_metrics","name":"query2","stat":"hits","service":"isuride","group_by":["resource_name"]},{"data_source":"apm_metrics","name":"query3","stat":"latency_avg","service":"isuride","group_by":["resource_name"]},{"data_source":"apm_metrics","name":"query4","stat":"latency_p95","service":"isuride","group_by":["resource_name"]},{"data_source":"apm_metrics","name":"query5","stat":"error_rate","service":"isuride","group_by":["resource_name"]}],"response_format":"scalar","sort":{"count":25,"order_by":[{"type":"formula","index":0,"order":"desc"}]},"formulas":[{"cell_display_mode":"bar","alias":"Total Time","formula":"query1"},{"cell_display_mode":"bar","alias":"Requests","formula":"query2"},{"cell_display_mode":"bar","alias":"Latency(avg)","formula":"query3"},{"cell_display_mode":"bar","alias":"Latency(95%)","formula":"query4"},{"cell_display_mode":"bar","alias":"Error Rate","formula":"query5"}]}],"has_search_bar":"auto"},"layout":{"x":0,"y":4,"width":12,"height":4}},{"id":6713610528355070,"definition":{"title":"Profiler(CPU Time)","title_size":"16","title_align":"left","requests":[{"request_type":"flame_graph","query":{"data_source":"profiling_aggregated_profile","family":"go","profile_type_id":"","limit":100,"query_string":"service:isuride-go","filter_operations":[],"favorite_query_id":"d48cd6f6-1aca-4e08-a2f3-399ddd74bd99"}}],"type":"flame_graph"},"layout":{"x":0,"y":8,"width":12,"height":5}}]},"layout":{"x":0,"y":17,"width":12,"height":14}},{"id":2855665471133285,"definition":{"title":"Issues","background_color":"vivid_green","show_title":true,"type":"group","layout_type":"ordered","widgets":[{"id":1728117595074901,"definition":{"title":"","title_size":"16","title_align":"left","requests":[{"response_format":"event_list","query":{"data_source":"issue_stream","query_string":"","indexes":[],"sort":{"order":"desc","column":"FIRST_SEEN"}},"columns":[{"field":"details","width":"auto"},{"field":"count","width":"auto"},{"field":"volume","width":"auto"}]}],"type":"list_stream"},"layout":{"x":0,"y":20,"width":12,"height":4}}]},"layout":{"x":0,"y":31,"width":12,"height":25}}],"template_variables":[],"layout_type":"ordered","notify_list":[],"reflow_type":"fixed","pause_auto_refresh":false}

これにより、本記事冒頭で示したダッシュボードを作成することができます。

パフォーマンスチューニングの実施

インデックスの追加

ダッシュボードが完成したら、ベンチマークを実行しながら、各種メトリクスやプロファイリング情報を確認し、ボトルネックの特定とパフォーマンスチューニングを進めていきます。

まず、初回の実行では、mysqldプロセスがCPUを大量に消費していることが確認できました。

クエリの中では、SELECT status FROM ride_statuses WHERE ride_id = ? ORDER BY created_at DESC LIMIT ?というクエリが多く実行されており時間がかかっているようです。

実行計画は取れていなかったので、EXPLAINコマンドで確認したところ、ride_statusesテーブルのride_idカラムにインデックスが貼られていないことがわかりました。

mysql> EXPLAIN SELECT status FROM ride_statuses WHERE ride_id = '01JDJ37JJ0QPX4D87D911C62H7' ORDER BY created_at DESC LIMIT 1;
+----+-------------+---------------+------------+------+---------------+------+---------+------+------+----------+-----------------------------+
| id | select_type | table         | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra                       |
+----+-------------+---------------+------------+------+---------------+------+---------+------+------+----------+-----------------------------+
|  1 | SIMPLE      | ride_statuses | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 4624 |    10.00 | Using where; Using filesort |
+----+-------------+---------------+------------+------+---------------+------+---------+------+------+----------+-----------------------------+
1 row in set, 1 warning (0.00 sec)

そこで、ride_idカラムにインデックスを追加しました。また、他のテーブルでも同様にインデックスが不足している箇所があったため、以下のインデックスを追加しました。

sql/1-schema.sql

...

ALTER TABLE ride_statuses ADD INDEX idx_ride_id_created_at(ride_id, created_at DESC);
ALTER TABLE chair_locations ADD INDEX idx_chair_id_created_at(chair_id, created_at);
ALTER TABLE rides ADD INDEX idx_chair_id_updated_at(chair_id, updated_at DESC);
ALTER TABLE chairs ADD INDEX idx_access_token(access_token);
ALTER TABLE chair_locations ADD INDEX idx_chair_id_created_at(chair_id, created_at);
ALTER TABLE ride_statuses ADD INDEX idx_ride_id_app_sent_at_created_at(ride_id, app_sent_at, created_at);
ALTER TABLE coupons ADD INDEX idx_used_by(used_by);

その結果、ベンチマークのスコアが向上しました。

time=13:46:53.037 level=INFO msg=結果 pass=false スコア=759 種別エラー数=map[5:206]

集計の事前計算

再度Datadogのダッシュボードを確認すると、さっきとは異なるクエリが一番時間がかかっていることがわかりました。

細かい解説は省略しますが、このクエリは、椅子の総移動距離を計算するためのクエリであり、chair_locationsテーブルのトランザクションデータから、LAG関数を利用して前回の位置情報との差分を計算し、その合計を求めています。
すなわち、chair_locationsテーブルのデータ量に応じてクエリの実行時間が増加するO(N)のクエリになっていたため、あらかじめ椅子の総移動距離をchairsテーブルに保持しておくことで、クエリの実行時間を大幅に削減することができます。

triggerを利用して、chair_locationsテーブルにinsertされたときに、chair_locations_distanceに計算済みの総移動距離を反映するようにします。

sql/1-schema.sql

...

DROP TABLE IF EXISTS chair_locations_distance;
CREATE TABLE chair_locations_distance
(
  chair_id         VARCHAR(26) NOT NULL PRIMARY KEY,
  total_latitude   INTEGER     NOT NULL,
  total_longitude INTEGER     NOT NULL,
  last_latitude   INTEGER     NOT NULL COMMENT '緯度',
  last_longitude  INTEGER     NOT NULL COMMENT '経度',
  last_updated_at  DATETIME(6)
);
CREATE INDEX chair_locations_distance_chair_id ON chair_locations_distance(`chair_id`);

DELIMITER //
-- update distance when new location is inserted
DROP TRIGGER IF EXISTS update_chair_location_distance //
CREATE TRIGGER update_chair_location_distance
BEFORE INSERT ON chair_locations FOR EACH ROW
BEGIN
  DECLARE current_latitude INTEGER;
  DECLARE current_longtitude INTEGER;
  
  IF (SELECT COUNT(*) FROM chair_locations_distance WHERE chair_id=NEW.chair_id)=0 THEN
    INSERT INTO chair_locations_distance(chair_id, total_latitude, total_longitude, last_latitude, last_longitude, last_updated_at)
          VALUES(NEW.chair_id, 0, 0, NEW.latitude, NEW.longitude, NEW.created_at);
  END IF;

  UPDATE chair_locations_distance
  SET total_latitude=total_latitude+IFNULL(ABS(NEW.latitude-last_latitude), 0),
      total_longitude=total_longitude+IFNULL(ABS(NEW.longitude-last_longitude), 0),
      last_latitude=NEW.latitude,
      last_longitude=NEW.longitude,
      last_updated_at=NEW.created_at
  WHERE `chair_id`=NEW.chair_id;
END //
DELIMITER ;

go/owner_handlers.go

func ownerGetChairs(w http.ResponseWriter, r *http.Request) {
	ctx := r.Context()
	owner := ctx.Value("owner").(*Owner)

	chairs := []chairWithDetail{}
	if err := db.SelectContext(ctx, &chairs, `SELECT id,
       owner_id,
       name,
       access_token,
       model,
       is_active,
       created_at,
       updated_at,
       IFNULL(total_distance, 0) AS total_distance,
       total_distance_updated_at
FROM chairs
-        LEFT JOIN (SELECT chair_id,
-                           SUM(IFNULL(distance, 0)) AS total_distance,
-                           MAX(created_at)          AS total_distance_updated_at
-                    FROM (SELECT chair_id,
-                                 created_at,
-                                 ABS(latitude - LAG(latitude) OVER (PARTITION BY chair_id ORDER BY created_at)) +
-                                 ABS(longitude - LAG(longitude) OVER (PARTITION BY chair_id ORDER BY created_at)) AS distance
-                          FROM chair_locations) tmp
-                    GROUP BY chair_id) distance_table ON distance_table.chair_id = chairs.id
+        LEFT JOIN (SELECT 
+           chair_id,
+           total_latitude + total_longitude AS total_distance,
+           last_updated_at AS total_distance_updated_at 
+         FROM chair_locations_distance
+                    ) distance_table ON distance_table.chair_id = chairs.id
WHERE owner_id = ?
`, owner.ID); err != nil {
		writeError(w, http.StatusInternalServerError, err)
		return
	}

  ...
	writeJSON(w, http.StatusOK, res)
}

この改善により、ベンチマークのスコアがさらに向上しました。

time=14:11:02.248 level=INFO msg=結果 pass=false スコア=967 種別エラー数="map[1:13 5:197]"

キャッシュの導入

現在、最も時間がかかっているクエリは、SELECT * FROM chairs WHERE access_token = ?というクエリです。

しかし、このクエリはindexを利用しており、実行計画を確認すると1行しかスキャンしていないことがわかります。

mysql> EXPLAIN SELECT * FROM chairs WHERE access_token = '3013d5ec84e1b230f913a17d71ef27c8d09d777b1cce7a3c1e2ffd4040848411';:
+----+-------------+--------+------------+------+------------------+------------------+---------+-------+------+----------+-------+
| id | select_type | table  | partitions | type | possible_keys    | key              | key_len | ref   | rows | filtered | Extra |
+----+-------------+--------+------------+------+------------------+------------------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | chairs | NULL       | ref  | idx_access_token | idx_access_token | 1022    | const |    1 |   100.00 | NULL  |
+----+-------------+--------+------------+------+------------------+------------------+---------+-------+------+----------+-------+
1 row in set, 1 warning (0.00 sec)

すなわち、MySQL側での最適化余地はほとんどないと考えられます。幸いなことに、アクセストークンの情報は更新されないため、アプリケーション側でのキャッシュを導入することでこのボトルネックを解消することが可能です。

go/middlewares.go

import (
  "time"
	"github.com/patrickmn/go-cache"
)

var cacheChairsByAccessToken = cache.New(60*time.Second, 60*time.Second)

...

func chairAuthMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		ctx := r.Context()
		c, err := r.Cookie("chair_session")
		if errors.Is(err, http.ErrNoCookie) || c.Value == "" {
			writeError(w, http.StatusUnauthorized, errors.New("chair_session cookie is required"))
			return
		}
		accessToken := c.Value
		chair := &Chair{}

+ 		if x, found := cacheChairsByAccessToken.Get(accessToken); found {
+ 			chair = x.(*Chair)
+ 		} else {
			err = db.GetContext(ctx, chair, "SELECT * FROM chairs WHERE access_token = ?", accessToken)
			if err != nil {
				if errors.Is(err, sql.ErrNoRows) {
					writeError(w, http.StatusUnauthorized, errors.New("invalid access token"))
					return
				}
				writeError(w, http.StatusInternalServerError, err)
				return
+ 			}
+ 			cacheChairsByAccessToken.Set(accessToken, chair, cache.DefaultExpiration)
		}

		ctx = context.WithValue(ctx, "chair", chair)
		next.ServeHTTP(w, r.WithContext(ctx))
	})
}

http://127.0.0.1:12346/payments へのconnection refusedエラー（直接 http://127.0.0.1:12345/payments をcurlで叩くと成功していそうなので、ベンチマーカーの仕様に起因する可能性があり、原因不明です）によりスコアは悪化してしまいましたが、DBアクセスのレスポンスタイムは改善しました。

time=14:25:02.119 level=INFO msg=結果 pass=false スコア=628 種別エラー数="map[1:16 5:193]"

通知エンドポイントの負荷軽減

改めて、プロセスのCPU使用率を確認すると、アプリケーション（isuride）のプロセスのCPU使用率も高くなっていることがわかりました。

エンドポイントの一覧をみてみると、GET /api/chair/notificationという椅子の状態を通知するエンドポイントに多くのリクエストが送信されていることがわかりました。

序盤は椅子の状態の変化がそれほど頻繁でないため、このエンドポイントの呼び出し頻度を下げることで、アプリケーションの負荷を軽減できます。

go/chair_handlers.go


func chairGetNotification(w http.ResponseWriter, r *http.Request) {
  ...

	if err := tx.GetContext(ctx, ride, `SELECT * FROM rides WHERE chair_id = ? ORDER BY updated_at DESC LIMIT 1`, chair.ID); err != nil {
		if errors.Is(err, sql.ErrNoRows) {
			writeJSON(w, http.StatusOK, &chairGetNotificationResponse{
- 				RetryAfterMs: 30,
+   			RetryAfterMs: 600,
			})
			return
		}
		writeError(w, http.StatusInternalServerError, err)
		return
	}

  ...

	writeJSON(w, http.StatusOK, &chairGetNotificationResponse{
		Data: &chairGetNotificationResponseData{
			RideID: ride.ID,
			User: simpleUser{
				ID:   user.ID,
				Name: fmt.Sprintf("%s %s", user.Firstname, user.Lastname),
			},
			PickupCoordinate: Coordinate{
				Latitude:  ride.PickupLatitude,
				Longitude: ride.PickupLongitude,
			},
			DestinationCoordinate: Coordinate{
				Latitude:  ride.DestinationLatitude,
				Longitude: ride.DestinationLongitude,
			},
			Status: status,
		},
- 		RetryAfterMs: 30,
+ 		RetryAfterMs: 600,
	})
}

また、GET /api/app/notificationというユーザーアプリ向けの通知エンドポイントも同様に呼び出し頻度を下げることが可能です。

これ以上のチューニングはISUCONの解説記事に譲りますが、これまでの改善と同様に、Datadogのダッシュボードを確認しながら、ボトルネックを特定し、パフォーマンスチューニングを進めていくことができます。

まとめ

本記事では、Datadogを用いたアプリケーションのパフォーマンスチューニング手法について解説しました。Datadogの各種機能を活用することで、ボトルネックの特定と改善を効率的に進めることができます。ぜひ、皆さんのアプリケーションでもDatadogを活用して、パフォーマンスチューニングに取り組んでみてください。

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up