Percona Toolkit を読む

このエントリは はてなエンジニア Advent Calendar 2019 の 18 日目のエントリです。

qiita.com

前日は id:ikesyo さんによる 2019年のSwiftモック事情 でした。

ikesyo.hatenablog.com

SQL を分析したい

今日の話。DB 負荷を継続的に計測していきたいのです。

そんなときに Percona Toolkit って良いライブラリがあるので、これを使っていきましょう。

SQL を分析するときは以下のようなことを考えます。

  1. 本番環境でログを採取
  2. normalize
  3. グルーピング
  4. EXPLAIN
  5. マズいクエリを見つけたらアラート発報

それぞれ見ていきましょう。

ログの採取

色々眺めたいので一旦 tcpdump を使います。

流れるクエリだけじゃなくて response も全部採取しているので、秒で GB 単位のデータが溜まっていくことに注意してください。

# pcap データをファイルに保存する
$ sudo /usr/sbin/tcpdump -i any port 3306 -G 60 -w /tmp/tcpdump_%Y%m%d_%H%M%S.pcap

# 再生する
$ /usr/sbin/tcpdump -r /tmp/tcpdump_20191218_000000.pcap -n -nn -tttt -x -q

この取得した pcap から、流れている SQL を取り出したいんですが、Percona Toolkit に TcpdumpParser と MySQLProtocolParser っていうイイやつがあります。

名前を見るとイメージ沸くかな。これらを繋ぐといい感じに流れたクエリを取り出すことができます。

use strict;
use warnings;
use utf8;
use English qw(OS_ERROR);

use lib '/path/to/percona-toolkit/lib';

use Data::Dumper;
$Data::Dumper::Sortkeys  = 1;

use TcpdumpParser;
use ProtocolParser;
use MySQLProtocolParser;

my $parser   = new TcpdumpParser();
my $protocol = new MySQLProtocolParser();
my $queries = [];

my $file = 'tcpdump_20191218_000000.txt';

sub _read {
    my ( $fh ) = @_;
    return <$fh>;
}

eval {
    open my $fh, "<", $file or die "Cannot open $file: $OS_ERROR";
    my $parser_args = {
        next_event => sub { return _read($fh); },
        tell       => sub { return tell($fh);  },
        fh         => $fh,
    };
    while ( my $p = $parser->parse_event(%$parser_args) ) {
        my $e = $protocol->parse_event(%$parser_args, event => $p);
        push @$queries, $e if $e;
    }
    close $fh;
};

print Dumper $queries;

こんな感じ。

$VAR1 = [
   {
     No_good_index_used => 'No',
     No_index_used => 'No',
     Query_time => '0.000126',
     Rows_affected => 0,
     Thread_id => 4294967299,
     Warning_count => 0,
     arg => 'SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1',
     bytes => 261,
     cmd => 'Query',
     db => undef,
     host => '127.0.0.1',
     ip => '127.0.0.1',
     port => '58430',
     pos_in_log => 130658,
     ts => '191218 23:46:08.915939',
     user => undef
   },
  ...

ところでレスポンスに NO_GOOD_INDEX_USED とか NO_INDEX_USED とかってフラグあったんですね。10 年以上ずっと MySQL 使ってきたけど知らなかった……。

normalize

SQL を取り出すと、

SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1

のような SQL 文字列が取得できたけど、id = 1 の部分は同一視して集計したいですよね。

これまた Percona Toolkit に QueryRewriter っていうイイやつがあります。

この fingerprint メソッドが、よくできた normalize 処理なので、いただきます。

use QueryParser;
use QueryRewriter;

my $queries = ...;

my $qp = new QueryParser();
my $qr = new QueryRewriter(QueryParser => $qp);
print Dumper [ map { $qr->fingerprint($_->{arg}) } @$queries ];

これを通すと

$VAR1 = [
  'select `users`.* from `users` where `users`.`id` = ?',
  'select `users`.* from `users` where `users`.`id` in(?+)',
  ...

のように normalize されたクエリが取得できます。

自分でこの正規表現書けるかというとまったく自信無いので、枯れてるライブラリは最高ですね。

グルーピング

normalize して、クエリごとに集計可能になったので、グルーピングして集計処理をします。

これまた Percona Toolkit に EventAggregator っていうイイやつがあります。

あ、event ってのは、最初に Parser から取り出していた、1 クエリを表現する HashRef のことですね。

使い方はこんな感じ？

use EventAggregator;

my $ea = new EventAggregator(
   groupby    => 'fingerprint',
   worst      => 'Query_time',
   attributes => {
      Query_time => [qw(Query_time)],
   },
);

for my $event (@$queries) {
    # fingerprint を埋めて
    $event->{fingerprint} = $qr->fingerprint($event->{arg});
    # 集計処理に渡す
    $ea->aggregate($event);
}

# 集計結果を取得
print Dumper $ea->results;

ログ貼ると長いので省略するけど

{
  classes => {
    fingerprint => { 集計結果 },
    fingerprint => { 集計結果 },
    ...
  },
  globals => { ... },
  samples => {
    fingerprint => { event },
    fingerprint => { event },
    ...
  },
}

のような hash が返ってきます。

classes は

{
  'select `users`.* from `users` where `users`.`id` = ?' => {
    Query_time => {
      all => {
        100 => 2,
        102 => 2,
        98 => 1
      },
      cnt => 5,
      max => '0.000143',
      min => '0.000116',
      sum => '0.000657'
    }
  },
  'select `users`.* from `users` where `users`.`id` in(?+)' => {
    Query_time => {
      all => {
        111 => 1,
        94 => 1,
        96 => 1
      },
      cnt => 3,
      max => '0.000221',
      min => '0.000096',
      sum => '0.000424'
    }
  },
  ...

のように、Query_time を集計したもの。cnt, sum だけじゃなくて分布も眺めることができます。

samples は worst で渡した集計軸で、一番遅かったクエリの event です。

集計軸を自分で設定できるので、Query_time 以外でも色んな方向から眺めて分析できそうですね。

EXPLAIN

normalize した結果はおそらく 数百〜2000 ぐらいに収まると思う。これを片っ端から EXPLAIN して、悪い SQL じゃないかを確かめたい。

これまた Percona Toolkit に QueryReportFormatter、JSONReportFormatter っていうイイやつがあります。

JSONReportFormatter は QueryReportFormatter の子クラスで、出力が JSON になるよう override したものですね。

先ほど作った EventAggregator のオブジェクトと、EXPLAIN を投げる先の DB Handler を渡すと、片っ端から投げまくってくれます。

my $config = {
    dsn => 'dbi:mysql:dbname=DATABASE_NAME;host=127.0.0.1',
    user => 'root',
    pass => 'pass',
};
my $dbh = DBI->connect(map { $config->{$_} } qw(dsn user pass));

my $qrf = QueryReportFormatter->new(
    dbh => $dbh,
    ...
);
$qrf->print_reports(
    ea => $ea,
    ...
);

コードを見ると分かるんですが、要は文字列結合で EXPLAIN $query としているだけです。サブクエリがある場合は安易に EXPLAIN すると死ぬ可能性があるのでスキップされます。なるほど賢い！

マズいクエリを見つけたらアラート発報

JSON が取れるので、もちろん Mackerel に投げて、アラートやグラフを作っていきたい、ですよねぇ。

ここまでで、クエリごとの実行回数や実行時間、一番遅いクエリ等をそれぞれ取得し、更に全クエリについて EXPLAIN 結果も取得することができました。実はこれが pt-query-digest でやってることです。

なんで自前でやってきたかと言うと、一番欲しかった全自動 EXPLAIN 結果が --output json だとなーんか動かなくてですね、この記事はデバッグしている途中ってヤツです。

ドキュメント には

json output was introduced in 2.2.1 and is still in development, so the data structure may change in future versions.

とあります。なので JSON 出力に含める実装がまだ無い気がしています。(たぶん)

著名な便利ツールも中身は普通の Perl なので、こうして読み解いて＆コントリビュートしていきたいね、というお話でした。

明日は id:Pasta-K さんです。