Zenn
🐰

作ったアプリケーションが実行している SQL の収集 -パフォーマンスを意識する初手-

2022/07/14に公開
MySQL
SQL
パフォーマンス
tech

Web アプリケーションは DB と密接に連携して動作しています。
近年は ORM が高性能になったため、普段は SQL を意識することも減りました。

一方でパフォーマンスが低くなる原因の多くは DB アクセスです。
そして DB にアクセスするのは SQL です。

SQL を意識し、日頃からパフォーマンス改善に取り組む一歩目として。

  • 自分が作ったアプリケーションが実行している SQL を収集

する方法を記載します。

前提条件

  • MySQL 5.7 以上
  • ローカル開発環境
  • Docker を利用
  • 網羅的なテストの存在

手順

SQL を収集し、次のエントリーで実測およびパフォーマンスを確認します。

  • [基本]
    • MySQL の general_log
  • [画面系]
    • フレームワークのデバッガ
  • [バッチ処理]
    • フレームワークのクエリログ

では具体的な収集方法を見ていきます。

SQL 収集

実装範囲の SQL を、パターン別に収集する方法を記載します。

なお、各種ログを出力する場合はストレージ容量を意識する必要がありますが、Docker イメージを定期的に再構築しログファイルは削除される前提で進めます。

[基本] MySQL の general_log

テストが網羅的に書かれている前提ですと、general_log で SQL を収集するのが最も確実と言えます。
Docker コンテナ内で作業します。

  1. MySQL コンテナに入る
# MySQL コンテナに ssh ログイン
$ docker exec -it container_name bash

# MySQL にログイン
$ mysql -u [user name] -p [schema name]
  1. general_log 出力設定
    • general_log 出力設定用の SQL を Clipy などに登録しておくと便利
mysql> SET GLOBAL general_log = 'ON';
Query OK, 0 rows affected (0.01 sec)

mysql> SET GLOBAL general_log_file = '/var/mysql/mysql.log';
Query OK, 0 rows affected (0.00 sec)

ローカル開発環境で実施した内容を、本番と同等のステージング環境で実施したくなることがあります。
が、不特定多数のアクセスや cron バッチが流れる可能性のある環境での general_log の設定はやめましょう

  • 他に使う人がいた場合、大量のログが流れる
  • ログファイルのサイズも膨大になる可能性がある

今回はローカル開発環境にて 自分が実装した機能の全 SQL を抽出する ために使います

  1. tail で general_log を流す
    • 別コンソール推奨
    • テストを流し、全てのパターンの SQL を実行
    • SELECT 文など、パフォーマンスを確認したい SQL を収集
    • Fixture などテスト準備用の SQL も一緒に流れてくるので注意
$ tail -f /var/mysql/mysql.log
(ところどころ中略しています)
2022-04-14T10:00:20.416101Z	   10 Query	SHOW TABLES FROM `test_schema`
2022-04-14T10:00:20.423460Z	   10 Query	SHOW FULL COLUMNS FROM `test_schema`.`notifications`
2022-04-14T10:00:20.445936Z	   10 Query	SELECT CHARACTER_SET_NAME FROM INFORMATION_SCHEMA.COLLATIONS WHERE COLLATION_NAME = 'utf8_general_ci'
2022-04-14T10:00:20.451145Z	   10 Query	SELECT COUNT(*) AS `count` FROM `test_schema`.`notifications` AS `Notification`   WHERE `user_id` = 1 
2022-04-14T10:00:20.550184Z	   10 Query	START TRANSACTION
2022-04-14T10:00:20.588995Z	   10 Query	INSERT INTO `test_schema`.`notifications` (`user_id`, `message`, ... `created`, `modified`) VALUES  (1, ... '2013-07-09 21:11:11', '2013-07-09 21:22:22') 2022-04-14T10:00:20.593192Z	   10 Query	COMMIT
(後略)
  • (余談) SELECT 時の接続ユーザーを確認
    master と replica の接続ユーザーを config で使い分けている場合は、general_log 中の Connect ログに表示される接続ユーザー名を確認することで、SELECT は replica を向いているか？を確認することもできます。
    クラスタ構成の場合、SELECT は負荷分散のため replica に接続していることが望ましく、うっかり master に接続したがために全体のパフォーマンスが低下することもあるのでチェックしておきましょう。
  1. general_log の停止
    MySQL コンテナを抜けることで genral_log 出力は停止されます。
    2. general_log 出力設定 がセッション単位で有効になっているため抜けると設定がクリアされます。
    永続化する場合は my.cnf に設定を記述する必要がありますが、常時 general_log が必要になったら考えましょう。

[画面系] フレームワークのデバッガ

フレームワークにはデバッガが備わっていて、その中に SqlLog 的な項目があります。
画面で実行したクエリが列挙されているので利用しましょう。

また、SqlLog には実行速度が載っているものもありますが、以下の理由でアテになりません。

  • ローカル開発環境はレコード数が少ない
    • 間引かれている
    • 開発に応じて動く範囲でレコードを作る
  • パフォーマンスを測るのに適していない
    • 本番と同等ではない
    • ローカル開発環境ではパフォーマンスの問題は起こりにくい

実測はステージング環境など 本番と同等の環境 での数値を用いましょう。
あくまでも SQL の収集目的で利用するのがベストだと考えます。

[バッチ] フレームワークのクエリログ

バッチは画面がないので、フレームワークのクエリログを出力し参照します。
大抵の場合は config で設定すれば出力されます。

パフォーマンスを考える

Web アプリケーションのパフォーマンスは簡単に低くなります。
そのパフォーマンスの多くは　DB　アクセスに左右されます。
DB アクセスは SQL で実現しているので、パフォーマンスを考える際、SQL 抜きでは語れません。

パフォーマンスが遅くなる原因は複数ありますが、その中でもフレームワークに任せているからこそ起きやすいものの例に以下があります。

  • Model のアソシエーションが正確とは限らない
    • 非効率はアソシエーションはパフォーマンスの低い SQL を生み出す
    • FK がない、正規化されていないなど問題は複数ある
  • ORM は n+1 を生み出しやすい

日頃からパフォーマンスを低くしないためにも、次のエントリーに記載する

  • 本番と同等の環境で実測
  • パフォーマンスをどう計測するのか知る
  • SQL が動く順序を知る

を実践していきましょう。

まとめ

  • SQL を余さず収集しよう
    • テストを書こう
  • パフォーマンスを意識しよう
    • あなたが作ったアプリケーションの SQL はあなたが作っている
    • あなたが作った SQL のパフォーマンスはあなたの責任

Discussion