ソフトウェア開発部バックオフィス基盤グループの廖です。普段開発されたサービスの中、処理速度が遅くなったり、メモリ/CPU消費率が高くなったりすることを経験したことがありますでしょうか？この記事では今までサーバーサイドの開発でパフォーマンス改善の取り組みについてご紹介したいと思います。
前提
下記の調査/改善方法のご紹介では、APM(アプリケーションパフォーマンス管理)ツールが使えない場合を前提としてます。もしAPMが使える場合、もっと簡単に効率的にパフォーマンス関連の調査/改善が行えますが、導入/使うにはコストもそれなりにコストがかかるので、気をつけていただければと思います。
ボトルネックの調査方法
何をどうやって改善するかを決めるには、まずどこでパフォーマンス(速度やメモリなど)がよくないのかを特定する必要があります。ここで、いくつか調査方法をご紹介します。
SQLクエリの場合、まずは実行計画の確認
エンジニアの方々には、言うまでもなくEXPLAINを使うことが少なくないでしょう。
RDBのSQL実行計画の使い方/見方にお詳しい方が多いかと思いますので、ここで紹介を省略します。
また、SQLクエリの実行についてサーバ処理の一部しかないので、SQLクエリの実行時間がサーバ処理全体の実行時間の何パーセントを占めるか、SQLクエリだけが遅い/メモリを大量に食っているのかを確認することも大切です。
モニタリング/監視ツールの活用
APIのRPS/Response Time/DBアクセス/CPU/メモリなどの実際の利用状況などを監視できるサービス/ツールを活用することもお勧めします。
MoTの多くのサービスにはNewRelicが監視ツールとして採用されています。
実際のサービス稼働状況をこういった監視ツールのグラフで確認でき、どこの負荷が高いのかなどを把握やすいです。
そして、AWS RDSを使っている場合、AWS RDSのPerformance Insightsを使うとどのクエリが遅いかなども簡単に確認できます。
計測ログを入れる
これまで紹介した方法だけでは、実装したサービスの中、どこの処理の速度が遅いか、どこを改善すればいいかがまだわからないこともあるかと思います。こういった場合、計測ログを埋めて実際の各内部メソッドの処理時間を計測と分析するのも一つの手です。
下記はGoで計測ログの実装例になります。
ロガーの定義
package timelog type Logger struct { *zap.Logger enabled bool // false:計測ログを止める } func New(enabled bool, zl *zap.Logger) *Logger { return &Logger{ Logger: zl, enabled: enabled, } } func (l *Logger) LogExecutionTime(methodName string) func() { if !l.enabled { return func() {} // OFFの場合、何もしない } start := time.Now() return func() { l.Info(fmt.Sprintf("method %s execution time info", methodName), zap.String("method", methodName), zap.Time("start", start), zap.Duration("execution_time", time.Since(start)), ) } }
計測ログの埋め込み
type PaymentTransactionInteractor struct { logger *Logger ... } func (i *PaymentTransactionInteractor) NewPaymentTransactionInteractor() *PaymentTransactionInteractor { return &PaymentTransactionInteractor{ logger: timelog.New(true, zap.NewExample()) ... } } ... func (i *PaymentTransactionInteractor) CreatePaymentTransaction() error { // 計測ログの呼び出し defer i.logger.LogExecutionTime("PaymentTransactionCreator.CreatePaymentTransaction")() ... }
この方法により、サービス内部の処理時間のログが下記のように出力されます。
{"method": "Method A", "start": "xxxx(実行開始日時)", "execution_time": "xxx µs"}
{"method": "Method B", "start": "xxxx(実行開始日時)", "execution_time": "xxx µs"}
こういったログが溜まってきたら、EXCEL/Google Speadsheetにインポートして、各メソッドの平均実行時間/実行回数/合計実行時間などの計算結果を出すことにより、どこの処理がボトルネックになっているかが明確になってくることが多いです。
Go言語で開発した場合の方法
Goで開発する場合、パフォーマンス測定に関する標準機能もあるので、こういった便利機能を利用すると簡単に計測することができます。
１. Go Benchmark
Go標準のtestingパッケージで用意されているBenchmark機能を使うと、メソッドの実行時間を計測することができます。
基本はテストファイルにfunc BenchmarkXxx(*testing.B)のベンチマークメソッドを定義し、中で計測したいメソッドを呼び出し、テストを実行したら、平均実行時間が出力されます。
前に紹介した計測用ログの追加と同じく内部メソッドの計測ではありますが、使い分けとしては：
- 計測ログを使う
- 内部のどのメソッドが遅いかがわからない時（ボトルネックの箇所を特定したい）
- Benchmarkで計測しても問題箇所が不明で、ローカル環境/開発環境ではなく、本番環境で外部サービス/DBとの通信も含めて実際の実行時間を全体的に確認したい場合
- Go Benchmarkを使う
- 問題がある/疑っているメソッド対象がすでにわかっている場合
- 同じメソッドで違うパラメーターでの実行時間の差異を確認したい場合 例： 元メソッド：
type CreatePaymentTransactionRequest struct{ TransactionType int Amount int } func CreatePaymentTransaction(req *CreatePaymentTransactionRequest) error{ // 仮に内部でreqの値によって処理分岐があるとします ... }
下記のBenchmarkテストの実行でどの入力条件下で平均的に実行時間が長いか、確保されたメモリが大きいかが一目瞭然になります。
func BenchmarkCreatePaymentTransaction(b *testing.B) { // 違う入力パラメーターの組み合わせを羅列 tests := []struct{ name string args *CreatePaymentTransactionRequest }{ { name: "条件1", args: &CreatePaymentTransactionRequest{ TransactionType: xxx, Amount: xxxx, }, }, { name: "条件2", args: &CreatePaymentTransactionRequest{ TransactionType: xxx, Amount: xxxx, }, }, ... } for _, tt := range tests { b.ResetTimer() for i := 0; i < b.N; i++ { _ = CreatePaymentTransaction(tt.args) } } }
結果：
BenchmarkCreatePaymentTransaction/条件1 BenchmarkCreatePaymentTransaction/条件1-8 xxx xxxx ns/op xxx B/op xxx allocs/op BenchmarkCreatePaymentTransaction/条件2 BenchmarkCreatePaymentTransaction/条件2-8 xxx xxxx ns/op xxx B/op xxx allocs/op```
２. Go Profiling
profilingもBenchmarkと同じくGo標準で備えられている機能です。これを利用することで、Goプログラムのメモリ/CPU使用状況の解析ができ、さらに解析結果を可視化にすることもできます。
参考公式資料：
https://pkg.go.dev/net/http/pprof
https://golang.org/pkg/runtime/pprof/
改善策の紹介
これまではいくつかパフォーマンス関連の調査方法を紹介してきました。調査結果によってサービスのパフォーマンス（API応答速度、DBアクセス速度など）をインフラ側の施策（サーバ数、メモリを増やす、ロードバランサーの設定見直しなどなど）や新しい技術選択などで改善できるかもしれませんが、以下は開発の面から一般的な改善方法を紹介していきたいと思います。
SQLクエリの改善
- インデックスの追加
エンジニアの方々にとって、インデックス追加は皆やったことがあるかと思います。経験上、参照系のクエリの検索条件に対して適切なインデックスを追加することによって、クエリの実行が速くなることが多いです。
インデックスの追加に伴って、INSERT/UPDATE/DELETE系の操作にパフォーマンスの悪影響に与えてしまう可能性もあるので、別の検索クエリの改善方法を考えずに、何に対してもインデックスを追加することは控えましょう。
- クエリの見直し
インデックスが適用されても、SQLクエリの検索はまだ遅い場合が多々あります。違うSQLクエリでも同じ検索結果が得られるので、クエリ自体の改善を検討するといいです。
例えば、下記のようなポイントを確認するといいかもしれません。
- LEFT JOINがたくさん使われている時に、LEFT JOINの代替案がないか
- JOIN系のテーブルに対して検索条件が足りてないか
- クエリの検索条件で追加されたインデックスが適用されてないか
- サブクエリが多くないか、JOINに変更できるか
DBアクセス分散
- レプリケーションDBを使うように
DBの参照/書き込みと関係なく全て同じDBにアクセスするといつの間にか限界を迎えてくる可能性があります。
過去に、私のチームが担当している支払請求関連の検索機能が月初にいきなりアクセス率が上がり、一時検索エラーが頻繁に起きたことがあります。よく聞いたことがある話かもしれませんが、こういう時にサーバ側の設定を見直す前に、レプリケーションDBが用意されている場合、参照系クエリはレプリケーションDBを使うように修正すると書き込み系クエリと参照系クエリのアクアス先が別々になるので、アクセス分散によって同じDBサーバへの負荷が下がります。
同期処理を非同期/並行処理に変える
普段お金に関わる開発をやってきた中、正確性を保つために同期処理を実装したことが圧倒的に多いですが、この中でも非同期/並行処理に変えられるところがあるかを考え、メイン処理から一部の処理を分離して非同期/並行処理にすることによって、元のメイン処理の処理速度/API応答速度が速くなることが期待できます。
非同期処理または並行処理について、AWS SQS/Step Functionsなどの外部サービスを使うか、プログラムの実装だけで実現するかといった選択肢は色々あります。
ここで、Goのgoroutine/channelを使う方法について少し話します。
- Goのgoroutine/channel
Goにはgoroutine/channelという軽量並行処理を実現できる標準機能（Goの目玉機能でもある）があります。
普段の仕事の開発で使う機会がそこまで多くないですが、下記の参考リンクで書かれているようなgoroutine/channelで実装されたワーカープールの仕組みを応用することで、並行処理を実現できます。
https://oohira.github.io/gobyexample-jp/worker-pools.html
http://marcio.io/2015/07/handling-1-million-requests-per-minute-with-golang/
また、goroutine/channelを使って、必ず速度が上がるわけではなく、逆に全体速度が落ちることもあることを気をつけていただきたいです。goroutine自体も軽量とはいえ、作成自体も多少コストがかかります。
検証例：
func worker(id int, sleepTime time.Duration, results chan<- bool) { fmt.Print(id) time.Sleep(sleepTime) results <- true } func nonConcurrentWorker(id int, sleepTime time.Duration) { fmt.Print(id) time.Sleep(sleepTime) } func RunConcurrentWorker(sleepTime time.Duration) { results := make(chan bool, 3) for i := 1; i < 4; i++ { go worker(i, sleepTime, results) } for i := 1; i < 4; i++ { <-results } } func RunWorker(sleepTime time.Duration) { for i := 1; i < 4; i++ { nonConcurrentWorker(i, sleepTime) } }
上の処理に対してBenchmarkで検証します。
func BenchmarkRunWorker(b *testing.B) { testArgs := []time.Duration{ time.Microsecond, time.Nanosecond, } for _, arg := range testArgs { b.Run(fmt.Sprint("Concurrent test", arg), func(b *testing.B) { b.ResetTimer() for i := 0; i < b.N; i++ { RunConcurrentWorker(arg) } }) b.Run(fmt.Sprint("Non-concurrent test", arg), func(b *testing.B) { b.ResetTimer() for i := 0; i < b.N; i++ { RunWorker(arg) } }) } }
Benchmarkで計測した結果、同期処理自体の処理は時間がそんなにかからない場合にgoroutine/channelを使ったら逆に時間がかかってしまいそうです。
BenchmarkRunWorker/Concurrent_test1µs BenchmarkRunWorker/Concurrent_test1µs-8 70944 16243 ns/op 449 B/op 7 allocs/op BenchmarkRunWorker/Non-concurrent_test1µs BenchmarkRunWorker/Non-concurrent_test1µs-8 51496 22890 ns/op 0 B/op 0 allocs/op BenchmarkRunWorker/Concurrent_test1ns BenchmarkRunWorker/Concurrent_test1ns-8 110527 13053 ns/op 448 B/op 7 allocs/op BenchmarkRunWorker/Non-concurrent_test1ns BenchmarkRunWorker/Non-concurrent_test1ns-8 154518 7060 ns/op 0 B/op 0 allocs/op
APIアクセス回数を下げる
今年開発したあるジョブの内部処理の計測ログを分析した結果、あるデータ取得用のGET系APIの呼び出しの回数/合計応答時間の数値が結構高いことが判明しました。該当APIの平均応答時間はそんなに時間がかかるものではありませんでしたが、同じジョブ内で使われる回数が多いせいで、結果的にジョブの平均実行時間の2/3まで占めたという驚きの結果になってしまいました。呼び出されるAPIの内部で特に複雑な処理も多くなくて、どれだけAPIの内部処理を修正しても、呼び出す側で呼び出す回数が多くなると合計処理時間が長くなります。ここで、元々データを一件ずつ取ってくる処理をやめて、一括で1000件ずつデータを取ってくるように処理を修正することによって、ジョブの平均実行時間が結構改善されました。
処理分割
大量データを扱う処理では、気づかないうちにメモリ消費量が上がりやすいです。
例えば、別のサービスから一定期間のデータリストを全て取ってきて一括でDBに保存する処理があるとして、取ってきたデータ量が多いほど、メモリ消費量が一気に上がり、何も気にせずそのままDBに保存するとDBが耐えられない場合も発生する可能性が出てきます。こういう場合、こういったデータ処理に対して一回で全てのデータを対象とせずに、データの件数/期間などを限定して複数回分けて処理するとメモリ/CPU消費量が改善されるかと思います。
また、並行処理と併用することでさらに処理速度も改善できる可能性があります。
終わりに
ここまで紹介してきた内容はそんなに難しい/新しいものではないかもしれませんが、普段の開発の中で機能面の実現にフォーカスしすぎて、パフォーマンスに対して忘れがちな部分もあります。こういったところに対して今回の紹介がもしヒントになれたら嬉しいです。
