読者です 読者をやめる 読者になる 読者になる

Studio3104::BLOG.new

uninitialized constant Studio3104 (NameError)

fluent-plugin-mysqlslowquery + out_exec_filter でスロークエリを自動EXPLAIN



はじめに

管理するMySQLサーバが増えてくると、クエリの品質管理が大変になってきますよね。
スロークエリログを、EXPALINの結果も含めたデータで一箇所に集められたら幾ばくかの手間が省けるかなーとか考えてました。
ので、fluent-plugin-mysqlslowquery + out_exec_filteでやってみました。

検証環境

log_queries_not_using_indexesが有効な環境で、以下のクエリを投げてみて検証します。

mysql> SELECT * FROM user a, user b WHERE a.User=b.User;

mysql> EXPLAIN SELECT * FROM user a, user b WHERE a.User=b.User;
+----+-------------+-------+------+---------------+------+---------+------+------+--------------------------------+
| id | select_type | table | type | possible_keys | key  | key_len | ref  | rows | Extra                          |
+----+-------------+-------+------+---------------+------+---------+------+------+--------------------------------+
|  1 | SIMPLE      | a     | ALL  | NULL          | NULL | NULL    | NULL |   11 |                                |
|  1 | SIMPLE      | b     | ALL  | NULL          | NULL | NULL    | NULL |   11 | Using where; Using join buffer |
+----+-------------+-------+------+---------------+------+---------+------+------+--------------------------------+
2 rows in set (0.00 sec)

fluent-plugin-mysqlslowquery単体で使う場合

送信側の設定

超シンプル!

<source>
  type mysql_slow_query
  path /path/to/slow_query.log
  tag  mysql.slow
</source>
出力

こんな感じ。(わかりやすいように改行を入れてますが実際は1行です)

2012-07-04T11:17:24+09:00	mysql.slow
{
  "user":"studio3104[studio3104]",
  "host":"localhost",
  "host_ip":"",
  "query_time":0.000947,
  "lock_time":0.000128,
  "rows_sent":27,
  "rows_examined":11,
  "sql":"SET timestamp=1341368244; SELECT * FROM user a, user b WHERE a.User=b.User;"
}

fluent-plugin-mysqlslowquery + out_exec_filte

送信側設定
<source>
  type mysql_slow_query
  path /path/to/slow_query.log
  tag  mysql.slow
</source>
<match mysql.slow>
  type exec_filter
  command /path/to/out-exec-mysql-slowquery/explain.pl
  in_format json
  out_format msgpack
  tag slowfilter.host
  flush_interval 1s
</match>
<match slowfilter.**>
  type forward
  host reciever
  flush_interval 1s
</match>
explain.pl

こんな感じです。ソースさらすのに超勇気いるくらいのビギナーっす。
https://gist.github.com/3057557

#!/usr/bin/env perl

use strict;
use warnings;
use Data::Dumper;
$|=1;
use DBIx::Handler;
use JSON::XS;
use Data::MessagePack;

my $mp = Data::MessagePack->new();

my $db_user     = "td-agent";
my $db_passwd   = "td-agent";
my $db_opt      = { RaiseError => 0, PrintError => 1 };
my $handler     = DBIx::Handler->new("DBI:mysql:database=information_schema:127.0.0.1", $db_user, $db_passwd, $db_opt);

my $db;
my $long_query_time = $handler->dbh->selectrow_array("select VARIABLE_VALUE from GLOBAL_VARIABLES where VARIABLE_NAME = 'LONG_QUERY_TIME'");
$handler->dbh->do("SELECT SLEEP($long_query_time)");

while(my $json = <STDIN>){
  my $decode = eval { decode_json($json); };
  next if ($@);

  my $select;
  if (defined $decode->{sql} && $decode->{sql} =~ /(select[^\;]+)/i){
    $select = $1;
  }else{
    print $mp->pack($decode);
    next;
  }

  if ($decode->{sql} =~ /^use ([^\;]+)/i){
    $db = $1;
    $handler->dbh->do("use $db");
  }

  unless (defined $db){
    print $mp->pack($decode);
    next;
  }

  my $data   = $decode;
  my $result = eval { $handler->dbh->selectall_arrayref( "explain $select", +{Slice => {}});};

  if (defined $result){
    for (my $i=0;$i < (@$result);$i++){
      $data->{"explain$i"} = $result->[$i];
    }
    $data->{database} = $db;
  }

  print $mp->pack($data);
}
出力

こんな感じ。(わかりやすいように改行を入れてますが実際は1行です)

2012-07-04T11:17:24+09:00	slowfilter.host
{
  "lock_time":0.000128,
  "explain1":{
    "key_len":null,
    "Extra":"Using where; Using join buffer",
    "ref":null,
    "table":"b",
    "rows":"11",
    "key":null,
    "select_type":"SIMPLE",
    "possible_keys":null,
    "type":"ALL",
    "id":"1"
  },
  "sql":"SET timestamp=1341368244; SELECT * FROM user a, user b WHERE a.User=b.User;",
  "host":"localhost",
  "database":"mysql",
  "explain0":{
    "key_len":null,
    "Extra":"",
    "ref":null,
    "table":"a",
    "rows":"11",
    "key":null,
    "select_type":"SIMPLE",
    "possible_keys":null,
    "type":"ALL",
    "id":"1"
  },
  "user":"studio3104[studio3104]",
  "rows_sent":27,
  "host_ip":"",
  "query_time":0.0009469999999999999,
  "rows_examined":11
}

まとめ

可視化したい

こんな感じで可視化できたらいいなと思ってます。誰かに作ってもらおうと思ってます|_・)チラッ

ちゃんと動いてます

データ解析的な用途のMySQLサーバで実際に3日くらい動かしてますがエラーもなくきちんと動いております。
そのサーバはクソクエリの温床なのでスロークエリログ吐きまくりでいいサンプルになった。
可視化出来たらクエリ直してもらうんだ・・・ヽ(°▽、°)ノエヘヘヘヘ

こんなことしなくても

アプリケーション側の変更が出来るなら、DBIx::QueryLog - search.cpan.orgを使うほうがよさそうな予感がしてます。
ここまでやるならpluginにしたら?と自分でも思いますがアレがアレなのでアレですねぇ。(つまりrubyわかんない)


最後に

マッチョな皆さんからのdis、ツッコミ待ってます。enjoy!!