筋トレっていいですよね。 💪
BIG3の総重量が280kg(5RM)になりました。サーバーサイドエンジニアの花井(id:hiroyuki-hanai)です。
弊チームではサービスのコアになるAPIをRailsとMySQLをベースに開発しております。 インフラにはAWSを利用しています。
スタディプラスを初期から支えているAPIなので、モノリシックな部分や性能のよろしくない部分が少なからず存在しております。
先日、突然DBサーバーのCPUがスパイクしてサービスにアクセスしづらくなる障害が発生しました。
今回はサービスに影響を与えてしまった原因をあぶり出すために実施した、pt-query-digestによる性能改善の取り組みを紹介します。
intro
RDSの一般クエリーログやスロークエリログでもよかったのですが、本番のRDSに負荷をかけず、サーバーの設定を変更しなくても実行できるような方法が求められました。 また、本番のサーバーはオートスケーリングによっていつのまにかいなくなってしまうことがあるので、ローカルにログを残すわけにはいきませんでした。
上記の事情から、EC2上でtcpdumpを取得してS3へ結果を流すようにしました。
注: long_query_time に01.以上の値を指定することで、1秒未満のスロークエリについても記録ができるようになるそうです。 参考 - Amazon RDS における MySQL の既知の問題と制限
what is pt-query-digest?
pt-query-digestはpercona toolkitの一つで、slow logなどからMySQLのクエリを解析して、見やすい統計情報を表示してくれます。
what we did?
tcpdumpをいったんS3へ送り、サービスとは切り離されたサーバー上でpt-query-digestによる解析を実行します。
Step1
こちらを参考に、ログを取りたいサーバーでtcp dumpを取得し、S3へ流します。
# tcpdump -G60 -w - -W1 port 3306 | aws s3 cp - s3://example.com/slow-query/dump.cap
各オプションについては以下のような意図で指定しました。
tcpdump
-G60: 本番環境で実行するので、他の通信へ影響がでないように/出ても軽微で済むように、60秒で様子見したい。-w -: S3へ送るために、キャプチャ結果を標準出力に書き出します。-W1: サンプリング目的なので、とりあえず1ファイルに収まる範囲で見たい。
aws s3 cp
-: パイプの前半部分から流れてきた標準出力をそのまま受けます。
Step2
こちらを参考に、取得したtcpdumpをtxtファイルにして、pt-query-digestにかけます。
まず、S3から解析を行うサーバーへファイルを持ってきます。
$ aws s3 cp s3://example.com/slow-query/dump.cap ~/
pt-query-digestにかけます。
$ tcpdump -r dump.cap -s 65535 -x -n -q -tttt | pt-query-digest --type tcpdump >> dump.txt
オプションについては
tcpdump
-x: パケットを16進数で表示します。-n: アドレスやポート番号をそのまま出します。-q: 限定したプロトコルだけの簡易的な表示にします。-tttt: タイムスタンプを見やすい形(年-月-日 時:分:秒.ミリ秒)にします。指定しないと時間だけ出ます。
(このオプションはマニュアルの方で、tcpdumpを扱う時のおまじない的に指定して欲しい旨が書かれています。)
-r dump.cap: 読み込むファイルを指定します。-s 65535: CentOS 6のデフォルトサイズに従っておきます。0を指定すると全部になります。
output
こうして以下のような解析結果が得られます。
# Query 2: 55.40 QPS, 0.15x concurrency, ID 0xXXXX at byte 305728800 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: 2018-04-17 04:52:29.618996 to 04:53:29.005168 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 6 3290 # Exec time 6 9s 3ms 16ms 3ms 3ms 426us 3ms # Rows affecte 0 0 0 0 0 0 0 0 # Query size 8 776.48k 235 243 241.68 234.30 0.00 234.30 # Warning coun 0 0 0 0 0 0 0 0 # String: # Hosts XX.XX.XX.XX # Query_time distribution # 1us # 10us # 100us # 1ms ################################################################ # 10ms # # 100ms # 1s # 10s+ # Tables # SHOW TABLE STATUS LIKE 'xx_xxxs'\G # SHOW CREATE TABLE `xx_xxxs`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT `xx_xxxs`.* FROM `xx_xxxs` WHERE `xx_xxxs`.`user_id` = xxx AND `xx_xxxs`.`xxxxx_id` = xxx ORDER BY created_at desc LIMIT 1\G # Query 3: 51.35 QPS, 0.13x concurrency, ID 0x9DXX at byte 71527245 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: 2018-04-17 04:52:29.616751 to 04:53:28.978729 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 5 3048 # Exec time 5 7s 2ms 5ms 2ms 2ms 91us 2ms # Rows affecte 0 0 0 0 0 0 0 0 # Query size 3 315.27k 104 106 105.92 102.22 0 102.22 # Warning coun 0 0 0 0 0 0 0 0 # String: # Hosts 10.3.2.218 # Query_time distribution # 1us # 10us # 100us # 1ms ################################################################ # 10ms # 100ms # 1s # 10s+ # Tables # SHOW TABLE STATUS LIKE 'xxxs'\G # SHOW CREATE TABLE `xxxs`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT 1 AS one FROM `xxxs` WHERE `xxxs`.`xxxxx_id` = xxxxx AND `xxxs`.`user_id` = xxxxx LIMIT 1\G
この結果から、上位20件のうち15%ほどが同じテーブルに対するアクセスであることが判明しました。 詳しく調査してみたところ、n+1問題が発見され、問題の解消をすることができました。
conclusion
今回は問題が起きてからその原因を特定するために利用しましたが、後日こうした情報をきちんと監視して、改善につなげていく必要があるという話になりました。 上記コマンドをcronで定期的に実行するなどしていく予定です。
