2016年7月27日水曜日

SHOWステートメントをSHWOとタイポしてしまう

SHOWってshwoってタイポしませんか? わたしはします。

mysqlコマンドラインクライアントでの改変は、やった。


クエリーリライトプラグインも、やった。

Handlerさんコンニチワ (lsステートメントとかcatステートメントとかやった)

次はパーサーいじって改変せねばなるまい。

ということで書いた。
https://gist.github.com/yoku0825/68369433679392b2284e4eaf258b00c6

このパッチを適用したmysqldを起動すれば、


mysql57> shwo databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| mysql              |
| performance_schema |
| sys                |
+--------------------+
4 rows in set (0.00 sec)


_人人人人人人人人人_
> shwo databases <
 ̄Y^Y^Y^Y^Y^Y^Y^Y^Y^ ̄

もちろんGPLですので、typoが気になる方は導入してみると、仕事の効率が上がるかも知れません。


ところで、クエリーの強制書き換えを3つの場所でやってみた感想。

- 一番お手軽なのはなんと今回のSQLパーサー
  - 変なの書けばコンパイル時にエラーになるか、いじったところが動かないだけ
    - mysqlコマンドラインクライアントとクエリーリライトは容赦なくSEGV食らう
  - しかも全バージョン対応(だと思う)
  - やりたいことがエイリアス的な何か、って決まってるならアリだと思う(か?)
- なんか このとき はクエリーリライト用っぽい構造体の名前だったりしたけど、 今見ると 明らかにaudit_pluginを使うようになってる。。
  - pre-parseならなんとか似たように使えるけど、post-parseは全然書き方が変わってる。つらい。

というわけで、もしなんかやるとしたら、SQLパーサーがいいかなって思いました。

2016年7月25日月曜日

MySQL 5.7のngramパーサーはアルファベットを含む文章を上手くトークナイズできない

MySQL Bugs: #82330: Don't recursively-evaluate stopword after tokenize

ngramパーサー を使ってアルファベット混じりの日本語全文検索をしようとすると悲劇が起こる。デフォルトのストップワード一覧は このへん


MySQL 5.7.13で全文検索INDEXを使ってるんですけど半角英字でヒットする奴とヒットしないやつが居るんですけどこれって何ででしょう… ちなみに NGRAMを2文字 です。 例えばbabyって単語が含まれてる文章でbabyって単語がヒットしません。 stop wordsには含まれてないんですがなんでだろうと…

http://mysql-casual.slackarchive.io/general/-/1466580139/1469433820/1469174336000008/


mysql57> CREATE TABLE t1 (num serial, val varchar(32), FULLTEXT KEY (val) WITH PARSER ngram);
Query OK, 0 rows affected (0.40 sec)

mysql57> INSERT INTO t1 VALUES (1, 'baby');
Query OK, 1 row affected (0.04 sec)

mysql57> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | baby |
+-----+------+
1 row in set (0.01 sec)

mysql57> SELECT * FROM t1 WHERE MATCH(val) AGAINST ('baby' IN BOOLEAN MODE);
Empty set (0.02 sec)

mysql57> SET GLOBAL innodb_ft_aux_table = 'd1/t1';
Query OK, 0 rows affected (0.01 sec)

mysql57> SELECT * FROM i_s.INNODB_FT_INDEX_CACHE;
Empty set (0.05 sec)

確かに何も入らない。俺の知ってるBigramなら "ba", "ab", "by" の3つのトークンが入るはずなのに。


ソースコードをざっくり流してみたところ、

/*Ngram checks whether the token contains any words in stopwords.
We can't simply use CONTAIN to search in stopwords, because it's
built on COMPARE. So we need to tokenize the token into words
from unigram to f_n_char, and check them separately. */

https://github.com/mysql/mysql-server/blob/mysql-5.7.13/storage/innobase/fts/fts0fts.cc#L4790-L4845


( ゚д゚) ・・・

(つд⊂)ゴシゴシ

(;゚д゚) ・・・

(つд⊂)ゴシゴシゴシ
_, ._
(;゚ Д゚) …!?


トークナイズした後に、トークンにストップワードが含まれてないか、1gramからngramまで順番に評価する…だと…!?

よく見たらドキュメントにも書いてある。

ngram Parser Stopword Handling

The built-in MySQL full-text parser compares words to entries in the stopword list. If a word is equal to an entry in the stopword list, the word is excluded from the index. For the ngram parser, stopword handling is performed differently. Instead of excluding tokens that are equal to entries in the stopword list, the ngram parser excludes tokens that contain stopwords. For example, assuming ngram_token_size=2, a document that contains “a,b” is parsed to “a,” and “,b”. If a comma (“,”) is defined as a stopword, both “a,” and “,b” are excluded from the index because they contain a comma.

By default, the ngram parser uses the default stopword list, which contains a list of English stopwords. For a stopword list applicable to Chinese, Japanese, or Korean, you must create your own. For information about creating a stopword list, see Section 13.9.4, “Full-Text Stopwords”.

Stopwords greater in length than ngram_token_size are ignored.

http://dev.mysql.com/doc/refman/5.7/en/fulltext-search-ngram.html


というわけで、MySQL 5.7.13現在のngramパーサーは

1. "baby" を "ba", "ab", "by"にトークナイズする
2. "ba" を "b", "a" に再分割してストップワード評価。"a" がストップワードなのでこの "ba" のトークンは登録されない。
3. "ab" を "a", "b" に再分割してストップワード評価。"a" がストップワードなのでこの "ab" のトークンも登録されない
4. "by" は再分割する前からストップワードなので "by" のトークンも登録されない

たまたま、"baby"は完全にトークナイズされないワードだった…:(;゙゚'ω゚'):

他にデフォルトのストップワードである "to" を含む "TOKYO" なんかは、

mysql57> truncate t1;
Query OK, 0 rows affected (0.41 sec)

mysql57> INSERT INTO t1 VALUES (1, 'tokyo');
Query OK, 1 row affected (0.04 sec)

mysql57> SELECT * FROM t1;
+-----+-------+
| num | val   |
+-----+-------+
|   1 | tokyo |
+-----+-------+
1 row in set (0.03 sec)

mysql57> SELECT * FROM t1 WHERE MATCH(val) AGAINST ('tokyo' IN BOOLEAN MODE);
+-----+-------+
| num | val   |
+-----+-------+
|   1 | tokyo |
+-----+-------+
1 row in set (0.04 sec)

mysql57> SET GLOBAL innodb_ft_aux_table = 'd1/t1';
Query OK, 0 rows affected (0.00 sec)

mysql57> SELECT * FROM i_s.INNODB_FT_INDEX_CACHE ORDER BY position;
+------+--------------+-------------+-----------+--------+----------+
| WORD | FIRST_DOC_ID | LAST_DOC_ID | DOC_COUNT | DOC_ID | POSITION |
+------+--------------+-------------+-----------+--------+----------+
| ok   |            2 |           2 |         1 |      2 |        1 |
| ky   |            2 |           2 |         1 |      2 |        2 |
| yo   |            2 |           2 |         1 |      2 |        3 |
+------+--------------+-------------+-----------+--------+----------+
3 rows in set (0.00 sec)

"to"の部分以外はトークナイズされるので、一見検索できてそうに見えるけど、やっぱり "to" のトークンが握りつぶされているので


mysql57> INSERT INTO t1 VALUES (2, 'okyo');
Query OK, 1 row affected (0.03 sec)

mysql57> SELECT * FROM t1;
+-----+-------+
| num | val   |
+-----+-------+
|   1 | tokyo |
|   2 | okyo  |
+-----+-------+
2 rows in set (0.01 sec)

mysql57> SELECT * FROM t1 WHERE MATCH(val) AGAINST ('tokyo' IN BOOLEAN MODE);
+-----+-------+
| num | val   |
+-----+-------+
|   1 | tokyo |
|   2 | okyo  |
+-----+-------+
2 rows in set (0.01 sec)

こうなる(´・ω・`)

取り敢えずの回避策は、 デフォルトのストップワードリスト を使わせなければいいので、 innodb_ft_server_stopword_table を指定してやればいいはず。


mysql57> CREATE TABLE stopwords (value varchar(255) NOT NULL PRIMARY KEY);
Query OK, 0 rows affected (0.16 sec)

mysql57> SET GLOBAL innodb_ft_server_stopword_table = 'd1/stopwords';
Query OK, 0 rows affected (0.02 sec)

mysql57> OPTIMIZE TABLE t1;
+-------+----------+----------+-------------------------------------------------------------------+
| Table | Op       | Msg_type | Msg_text                                                          |
+-------+----------+----------+-------------------------------------------------------------------+
| d1.t1 | optimize | note     | Table does not support optimize, doing recreate + analyze instead |
| d1.t1 | optimize | status   | OK                                                                |
+-------+----------+----------+-------------------------------------------------------------------+
2 rows in set (0.68 sec)

mysql57> SELECT * FROM t1;
+-----+-------+
| num | val   |
+-----+-------+
|   1 | tokyo |
|   2 | okyo  |
+-----+-------+
2 rows in set (0.01 sec)

mysql57> SELECT * FROM t1 WHERE MATCH(val) AGAINST ('tokyo' IN BOOLEAN MODE);
+-----+-------+
| num | val   |
+-----+-------+
|   1 | tokyo |
+-----+-------+
1 row in set (0.07 sec)

mysql57> SELECT * FROM i_s.INNODB_FT_INDEX_CACHE ORDER BY position;
+------+--------------+-------------+-----------+--------+----------+
| WORD | FIRST_DOC_ID | LAST_DOC_ID | DOC_COUNT | DOC_ID | POSITION |
+------+--------------+-------------+-----------+--------+----------+
| ok   |            2 |           3 |         2 |      3 |        0 |
| to   |            2 |           2 |         1 |      2 |        0 |
| ky   |            2 |           3 |         2 |      3 |        1 |
| ok   |            2 |           3 |         2 |      2 |        1 |
| ky   |            2 |           3 |         2 |      2 |        2 |
| yo   |            2 |           3 |         2 |      3 |        2 |
| yo   |            2 |           3 |         2 |      2 |        3 |
+------+--------------+-------------+-----------+--------+----------+
7 rows in set (0.02 sec)

回避できた。
しかしこれ、どうしてこんな仕様にした。。

2016年7月5日火曜日

MySQL Fabricの様子を監視するための何か

MySQL Fabricでぼっこぼこにされたはなし で考えていた、MySQL FabricのMySQLプロトコルの口でAPIを叩いて監視しようと思っているはなし。

MySQLプロトコルの口では "CALL" ステートメントをフックして(というか単にクエリーを正規表現でマッチさせて) MySQL Fabricの各種APIを呼べるようになっている。
  => 日々の覚書: MySQL Fabricつらい(Fabricサーバー上のMySQLプロトコルの口でFabricのAPIが呼べる編)

ので、これを使うことにする。叩くAPIはたぶんこの辺。


mysqlfabric mysql 用途
mysqlfabric manage ping CALL manage.ping() mysqlfabricデーモンが生きてるかどうか
mysqlfabric statistics node CALL statistics.node() node_uptime, node_startupを見たいとき
mysqlfabric group lookup_groups CALL group.lookup_groups() group_idをここで取る
mysqlfabric group health ‘group_id’ CALL group.health(‘group_id’) is_alive, status, is_not_runningとか見どころがいっぱい
statisticsまでは拘らなくてもいいかなと思って、書いたのがこんな。


my $conn= DBI->connect("dbi:mysql:;host=fabric_ipaddr;port=32275", "fabric_usser", "fabric_password",
                       {RaiseError => 1, PrintError => 0,
                        mysql_connect_timeout => 1, mysql_read_timeout => 1, mysql_write_timeout => 1});

my $manage_ping= $conn->prepare("CALL manage.ping()");
$manage_ping->execute;

my $lookup_groups= $conn->prepare("CALL group.lookup_groups()");
$lookup_groups->execute;
$lookup_groups->fetchall_arrayref(); ### Skip because 1st Result set is fabric's uuid.
$lookup_groups->more_results;        ### Go ahead to next Result set.
foreach my $group (@{$lookup_groups->fetchall_arrayref({})})
{
  my $group_id= $group->{group_id};

  my $group_health= $conn->prepare("CALL group.health(?)");
  $group_health->execute($group_id);
  $group_health->fetchall_arrayref(); ### Skip because 1st Result set is fabric's uuid.
  $group_health->more_results;        ### Go ahead to next Result set.

  my $primary_server= "";
  foreach my $server (@{$group_health->fetchall_arrayref({})})
  {
    if ($server->{io_not_running} || $server->{sql_not_running})
    {
      critf("group_health is something wrong: %s", $server);
    }
    else
    {
      $primary_server= $server->{uuid} if $server->{status} eq "PRIMARY";
    }
  }
  critf("There's no PRIMARY state server in %s", $group_id) unless $primary_server;
}

CALL group.lookup_groups(); (をはじめとする色々なストアドプロシージャもどきの)戻りが複数の結果セットをカジュアルに返すので、生まれて初めて more_results なんてメソッド を呼んだ。manage pingなんかは1つしか返さないので、本当はちゃんとループさせて "TTL" が入ってたら多分応答ヘッダーの方だとか判定した方がいいんだろう(たぶん、する)
1つ目の結果セットが "mysqlfabricのUUID" と "Time-To-Live" を返し、2つ目の結果セットにコマンドの結果が詰まっている。

$ mysqlfabric group lookup_groups
Fabric UUID:  5ca1ab1e-a007-feed-f00d-cab3fe13249e
Time-To-Live: 1

    group_id description failure_detector                          master_uuid
------------ ----------- ---------------- ------------------------------------
    fabric_A        None                0 8658f0e6-fb9e-11e5-8c6f-001a4a571800
    fabric_B        None                1 a1ffe373-3e73-11e6-87b3-001a4a5718ee


MySQL [(none)]> CALL group.lookup_groups();
+--------------------------------------+-----+---------+
| fabric_uuid                          | ttl | message |
+--------------------------------------+-----+---------+
| 5ca1ab1e-a007-feed-f00d-cab3fe13249e |   1 | NULL    |
+--------------------------------------+-----+---------+
1 row in set (0.01 sec)

+--------------+-------------+------------------+--------------------------------------+
| group_id     | description | failure_detector | master_uuid                          |
+--------------+-------------+------------------+--------------------------------------+
| fabric_A     | NULL        |                0 | 8658f0e6-fb9e-11e5-8c6f-001a4a571800 |
| fabric_B     | NULL        |                1 | a1ffe373-3e73-11e6-87b3-001a4a5718ee |
+--------------+-------------+------------------+--------------------------------------+
2 rows in set (0.01 sec)

さて…切り替わりをフックするのはどうしようかな。。threat.report_failureあたりは何のマシな情報も吐いてくれなかった。。


mysql> CALL threat.report_failure('a1ffe373-3e73-11e6-87b3-001a4a5718ee');
+--------------------------------------+-----+---------+
| fabric_uuid                          | ttl | message |
+--------------------------------------+-----+---------+
| 5ca1ab1e-a007-feed-f00d-cab3fe13249e |   1 | NULL    |
+--------------------------------------+-----+---------+
1 row in set (0.58 sec)

+--------------------------------------+----------+---------+--------+
| uuid                                 | finished | success | result |
+--------------------------------------+----------+---------+--------+
| 90517342-6a1f-424f-bed3-7a65f6140167 |        1 |       1 |      1 |
+--------------------------------------+----------+---------+--------+
1 row in set (0.58 sec)

+-------+---------+---------------+---------------------------------------------------------------+
| state | success | when          | description                                                   |
+-------+---------+---------------+---------------------------------------------------------------+
|     3 |       2 | 1467708190.44 | Triggered by <mysql.fabric.events.Event object at 0x239f350>. |
|     4 |       2 | 1467708190.47 | Executing action (_report_failure).                           |
|     5 |       2 |  1467708190.5 | Executed action (_report_failure).                            |
|     3 |       2 | 1467708190.48 | Triggered by <mysql.fabric.events.Event object at 0x22777d0>. |
|     4 |       2 |  1467708190.5 | Executing action (_find_candidate_fail).                      |
|     5 |       2 | 1467708190.59 | Executed action (_find_candidate_fail).                       |
|     3 |       2 | 1467708190.58 | Triggered by <mysql.fabric.events.Event object at 0x239f8d0>. |
|     4 |       2 | 1467708190.59 | Executing action (_check_candidate_fail).                     |
|     5 |       2 | 1467708190.65 | Executed action (_check_candidate_fail).                      |
|     3 |       2 | 1467708190.64 | Triggered by <mysql.fabric.events.Event object at 0x239f950>. |
|     4 |       2 | 1467708190.65 | Executing action (_wait_slave_fail).                          |
|     5 |       2 | 1467708190.87 | Executed action (_wait_slave_fail).                           |
|     3 |       2 | 1467708190.86 | Triggered by <mysql.fabric.events.Event object at 0x239fa90>. |
|     4 |       2 | 1467708190.87 | Executing action (_change_to_candidate).                      |
|     5 |       2 | 1467708191.02 | Executed action (_change_to_candidate).                       |
+-------+---------+---------------+---------------------------------------------------------------+
15 rows in set (0.58 sec)

2016年6月24日金曜日

そのALTER TABLEがオンラインALTER TABLEかどうかを確かめる方法

MySQL 5.6以降の InnoDB オンラインDDL について、「これってオンラインでできたっけ?」とここ最近だけで何度か聞かれたので。
ちなみにここを見てもわかる。
何故か概要ページにできるかできないかの表があることと、 ALTER TABLE のページから概要ページに直接リンクがないので見つけにくいらしい。
で、このページを思い出せなくてもできるかどうか確認する方法。
  • 同じ構造を持った空のテーブルを作ります
mysql57> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

mysql57> CREATE TEMPORARY TABLE tt1 LIKE t1;
Query OK, 0 rows affected (0.00 sec)

  • 試したいALTER TABLEに LOCK=NONE を明示して実行するます
mysql57> ALTER TABLE tt1 ADD KEY (val), LOCK=NONE; -- インデックスの追加はできる
Query OK, 0 rows affected (0.02 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql57> ALTER TABLE tt1 ADD FULLTEXT KEY (val), LOCK=NONE; -- FTインデックスの追加はできない
ERROR 1846 (0A000): LOCK=NONE is not supported. Reason: Fulltext index creation requires a lock. Try LOCK=SHARED.

mysql57> ALTER TABLE tt1 MODIFY val varchar(63), LOCK=NONE; -- 255バイトをまたがないvarcharのサイズ変更はできる
Query OK, 0 rows affected (0.02 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql57> ALTER TABLE tt1 MODIFY val varchar(64), LOCK=NONE; -- 255バイトをまたぐやつはできない
ERROR 1846 (0A000): LOCK=NONE is not supported. Reason: Cannot change column type INPLACE. Try LOCK=SHARED.

mysql57> ALTER TABLE tt1 MODIFY val varchar(63) CHARACTER SET latin1, LOCK=NONE; -- 文字コードの変換もできない
ERROR 1846 (0A000): LOCK=NONE is not supported. Reason: Cannot change column type INPLACE. Try LOCK=SHARED.
ね、簡単でしょ?

2016年6月21日火曜日

MySQL 5.7のmysql_upgradeがやたら重い件

日々の覚書: MySQL 5.7のmysql_upgradeは本当にDATETIME型を新しいフォーマットに直してくれるけれど でちょっと触れてるんだけど、DATETIME型(TIME型とTIMESTAMP型もあるけど)には現在2つのフォーマットが合って、

- 5.5とそれ以前のDATETIME型(秒部の小数点数非対応、8バイト、以下 旧DATETIME型)
- 5.6とそれ以降のDATETIME型(秒部の小数点数対応、小数部無しの場合は5バイト、以下DATETIME2型)

で、MySQL 5.7のmysql_upgradeは旧DATETIME型をDATETIME2型にアップグレードしてくれるよ、こいつらはレプリケーションで混ぜるとよろしくないから、これで安心だね、みたいなのが 前に書いた記事 のあらすじ。


と、MySQL 5.6 => 5.7のmysql_upgradeが特に問題にはなっていなかったので気付かなかったんだけれど、ふと気付いたら我らが Chiba.pm@masasuz さんが













というわけで計ってみた。
d2.xlargeインスタンスをスポットで借りてゴニョゴニョ。

テストデータはこんな感じ。

$ perl -MDigest::MD5 -e 'for (my $n= 1; $n <= 100000000; $n++) {printf("%d\t%s\n", $n, Digest::MD5::md5_hex($n));}' > /data/md5
mysql> CREATE TABLE t1 (num serial, val varchar(32) not null, dt datetime not null);
mysql> LOAD DATA INFILE '/data/md5' INTO TABLE t1 (num, val) SET dt = NOW();
$ ll d1/t1.ibd -h
-rw-rw---- 1 mysql mysql 6.9G Jun 21 02:16 d1/t1.ibd


結果はこんな感じ。1回ずつしか計ってないから誤差はあると思う。

from to time メモ
5.5(旧DATETIME) 5.7(DATETIME2) 31:16 5.5のmysqldで作ったデータをそのまま5.7のmysqldで起動してmysql_upgrade
5.5(旧DATETIME) 5.6(旧DATETIME) 00:06 5.5のmysqldで作ったデータをそのまま5.6のmysqldで起動してmysql_upgrade
5.6(旧DATETIME) 5.7(旧DATETIME) 00:16 ↑のデータを5.7のmysqld —avoid-temporal-upgradeで起動してmysql_upgrade
5.6(旧DATETIME) 5.7(DATETIME2) 36:53 ↑↑のデータを5.7のmysql_upgrade
5.6(旧DATETIME) 5.6(DATETIME2) 23:01 ↑↑↑のデータを5.6でALTER TABLE t1 FORCE
5.5(旧DATETIME) 5.6(DATETIME2) 22:37 5.5からmysqldumpして5.6にリストア(ダンプに別途1:31かかってる)
5.6(DATETIME2) 5.7(DATETIME2) 00:11 ↑のデータを5.7へmysql_upgrade



5.5のmysqldで作ったデータをそのまま5.7のmysqldで起動してmysql_upgradeした時のリソースの様子。

$ dstat -tamr 10
  date/time   |usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw | used  buff  cach  free| read  writ
21-06 02:23:44|  5   0  64  30   0   0|   0    19M|   6B    4B|   0     0 |1288  1142 |4895M  109M 24.9G  155M|   0   518
21-06 02:23:54|  6   1  65  29   0   0|   0    21M|   0     0 |   0     0 |1385  1176 |4969M  109M 24.8G  152M|   0   563
21-06 02:25:54|  6   0  64  30   0   0|   0    22M|   0     0 |   0     0 |1402  1194 |5822M  115M 24.0G  157M|   0   580


単にdatadirをコピーしてるだけの間は↓これくらい出ていたので、MySQL側の限界ではある様子。

$ dstat -tamr 10
21-06 03:00:14|  0   0  48  52   0   0| 410B  143M|  81B  606B|   0     0 |3491   594 | 889M 75.6M 24.1G 4991M|0.10  3434
21-06 03:00:24|  0   0  50  49   0   0| 410B  137M|  60B  570B|   0     0 |3366   544 | 926M 75.7M 25.4G 3632M|0.10  3295
21-06 03:00:34|  0   0  52  47   0   0|   0   149M|  79B  607B|   0     0 |3616   579 | 964M 75.7M 26.7G 2239M|   0  3576


30秒だけ pt-ioprofile でI/O状況を見てみたらこんな感じ。

# pt-ioprofile --cell sizes
Tue Jun 21 02:22:59 UTC 2016
Tracing process ID 4076
     total     pwrite      fsync      lseek filename
48041558016   96468992          0 47945089024 /data/mysql/d1/#sql-fec_2.ibd
 136257004  136252928       4076          0 /data/mysql/ib_logfile1
 115982336  115982336          0          0 /data/mysql/ibdata1
         0          0          0          0 /data/mysql/ib_logfile0

テンポラリーな.ibdファイルを作ってるので、テーブルコピーのALTER TABLEがまさに走っているはず。
pt-ioprofileを見るに、ibdファイルそのものよりもInnoDBログファイルに書き込んでいる(そう、テーブルコピーのALTER TABLEは1000行ずつコミットするらしい)ので、innodb_flush_log_at_trx_commit= 0とかすると速くなるかも。

2016年6月14日火曜日

innotopのその後 2016年6月

日々の覚書: innotopが最近息してないなーと思ったんだ から 1か月。innotop v1.11 がリリースされました。

v1.10からのアップデート内容はざっくりと

- MariaDB 10.1のサポート #124
- MySQL 5.7のマルチソースレプリケーションに対応 #129
- 壊れたテストの修正 #135
- perl 5.22でエラーになる問題の修正 #136
- MySQL 5.7で "L", "K"画面が表示できない不具合の修正 #137

あたりでしょうか。 @ryochin さん++。


MySQL 5.7に本格対応ということで晴れて v1.11 としてリリースされました(が、 コードの中のバージョンがv1.10のままというIssue が。。)

どうせならepelリポジトリーに入ってくれると楽でいいので、Red HatのBugzillaに上げてみました。
(本当にこれで良いのかどうかわからないけど、伝わるといいなあ…と思っていたらさっきの #139 が上がってきてアレなんですが)



innotopのリポジトリーで色々やってくれる lefred って先月Oracle(2016/06/14現在でMySQL Community Managerって書いてある)に入ったんですね。



入社後も バージョンageてよっていうIssue に反応してくれてるので、IssueやPRがあれば反応するっていうスタンスなんですかね(Percona時代からinnotop自体そんな感じだったけれど)

innotopの近況報告でした。

2016年5月16日月曜日

MySQL Routerの接続でMySQL Fabricのlogテーブルがあふれた(event_schedulerをOFFにするとあぶない)

MySQL Fabricには /etc/mysql/fabric.cfg の [logging]セクションの他にもログを取る部分が仕込まれていて、


mysql> SELECT * FROM fabric.log;
+---------------------------+----------------------------+------------------------------+-----------------------------------------------------------------------+----------+------+
| subject                   | reported                   | reporter                     | message                                                               | category | type |
+---------------------------+----------------------------+------------------------------+-----------------------------------------------------------------------+----------+------+
| 0                         | 2016-05-16 06:48:47.000000 | mysql.fabric.services.manage | Fabric node version (1.5.6) started.                                  |        0 |    0 |
| manage.ping               | 2016-05-16 06:48:52.000000 | mysql.fabric.command         | Started command (manage, ping).                                       |        1 |    0 |
| manage.ping               | 2016-05-16 06:48:52.000000 | mysql.fabric.command         | Finished command (manage, ping).                                      |        1 |    1 |
..
| dump.servers              | 2016-05-16 06:55:53.000000 | mysql.fabric.command         | Finished command (dump, servers).                                     |        1 |    1 |
| dump.sharding_information | 2016-05-16 06:55:53.000000 | mysql.fabric.command         | Started command (dump, sharding_information).                         |        1 |    0 |
| dump.sharding_information | 2016-05-16 06:55:53.000000 | mysql.fabric.command         | Finished command (dump, sharding_information).                        |        1 |    1 |
+---------------------------+----------------------------+------------------------------+-----------------------------------------------------------------------+----------+------+
1297 rows in set (0.02 sec)

なんというか、どぱーと吐いている。

( ´-`).oO(こんなトランザクションで保護される必要もなさそうな間っ平なログをMySQLに突っ込むとか、何考えてるのか小一時間問い詰めたい。


そしてなんか周辺の流れを見ても、何のフィルターもなく毎回INSERTされてるように見える。マジか(Python詳しい人誰か)

https://github.com/mysql/mysql-fabric/blob/release/1.5.5/lib/mysql/fabric/handler.py#L305-L307



$ mysqlbinlog -R -uroot -h 172.17.0.4 --stop-never -vv --start-position=182893 bin.000001 | grep "^#"
..

# at 285377
#160516 15:55:53 server id 1  end_log_pos 285408 CRC32 0x7f70413b       Xid = 5500
# at 285408
#160516 15:55:53 server id 1  end_log_pos 285473 CRC32 0xb35843f4       Anonymous_GTID  last_committed=772      sequence_number=773
# at 285473
#160516 15:55:53 server id 1  end_log_pos 285555 CRC32 0xd3de3d80       Query   thread_id=4     exec_time=0     error_code=0
# at 285555
#160516 15:55:53 server id 1  end_log_pos 285614 CRC32 0x12ff61e4       Table_map: `fabric`.`log` mapped to number 110
# at 285614
#160516 15:55:53 server id 1  end_log_pos 285734 CRC32 0x3c061fb3       Write_rows: table id 110 flags: STMT_END_F
### INSERT INTO `fabric`.`log`
### SET
###   @1='dump.servers' /* VARSTRING(120) meta=120 nullable=0 is_null=0 */
###   @2=1463349353.000000 /* TIMESTAMP(6) meta=6 nullable=0 is_null=0 */
###   @3='mysql.fabric.command' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @4='Finished command (dump, servers).' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
###   @5=1 /* INT meta=0 nullable=0 is_null=0 */
###   @6=1 /* INT meta=0 nullable=0 is_null=0 */
# at 285734
#160516 15:55:53 server id 1  end_log_pos 285765 CRC32 0x39af684e       Xid = 5508
# at 285765
#160516 15:55:53 server id 1  end_log_pos 285830 CRC32 0xe449e1fe       Anonymous_GTID  last_committed=773      sequence_number=774
# at 285830
#160516 15:55:53 server id 1  end_log_pos 285912 CRC32 0x239e9184       Query   thread_id=4     exec_time=0     error_code=0
# at 285912
#160516 15:55:53 server id 1  end_log_pos 285971 CRC32 0xe2235101       Table_map: `fabric`.`log` mapped to number 110
# at 285971
#160516 15:55:53 server id 1  end_log_pos 286116 CRC32 0xf5cc5f55       Write_rows: table id 110 flags: STMT_END_F
### INSERT INTO `fabric`.`log`
### SET
###   @1='dump.sharding_information' /* VARSTRING(120) meta=120 nullable=0 is_null=0 */
###   @2=1463349353.000000 /* TIMESTAMP(6) meta=6 nullable=0 is_null=0 */
###   @3='mysql.fabric.command' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @4='Started command (dump, sharding_information).' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
###   @5=1 /* INT meta=0 nullable=0 is_null=0 */
###   @6=0 /* INT meta=0 nullable=0 is_null=0 */

MySQL Routerを起動している間中、ずっとこれが来る。
それぞれのmysqlrouterから1秒に3リクエストずつ来ているらしく、そんな感じで倍々ゲームになっている:(;゙゚'ω゚'):

さてどうしようか。


【2016/05/17 13:46】

event_schedulerをOFFにしてたのがいけなかったのか!!!!

mysql> SELECT * FROM events\G
*************************** 1. row ***************************
       EVENT_CATALOG: def
        EVENT_SCHEMA: fabric
          EVENT_NAME: prune_log
             DEFINER: mikasa_fabric@127.0.0.1
           TIME_ZONE: SYSTEM
          EVENT_BODY: SQL
    EVENT_DEFINITION: DELETE FROM log WHERE TIMEDIFF(UTC_TIMESTAMP(), reported) > MAKETIME(3600,0,0)
          EVENT_TYPE: RECURRING
          EXECUTE_AT: NULL
      INTERVAL_VALUE: 3600
      INTERVAL_FIELD: SECOND
            SQL_MODE: NO_ENGINE_SUBSTITUTION
              STARTS: 2016-04-04 15:49:10
                ENDS: NULL
              STATUS: ENABLED
       ON_COMPLETION: NOT PRESERVE
             CREATED: 2016-04-04 15:49:10
        LAST_ALTERED: 2016-04-04 15:49:10
       LAST_EXECUTED: NULL
       EVENT_COMMENT:
          ORIGINATOR: 33893
CHARACTER_SET_CLIENT: utf8
COLLATION_CONNECTION: utf8_general_ci
  DATABASE_COLLATION: utf8_general_ci
*************************** 2. row ***************************
       EVENT_CATALOG: def
        EVENT_SCHEMA: fabric
          EVENT_NAME: prune_error_log
             DEFINER: mikasa_fabric@127.0.0.1
           TIME_ZONE: SYSTEM
          EVENT_BODY: SQL
    EVENT_DEFINITION: DELETE FROM error_log WHERE TIMEDIFF(UTC_TIMESTAMP(), reported) > MAKETIME(3600,0,0)
          EVENT_TYPE: RECURRING
          EXECUTE_AT: NULL
      INTERVAL_VALUE: 3600
      INTERVAL_FIELD: SECOND
            SQL_MODE: NO_ENGINE_SUBSTITUTION
              STARTS: 2016-04-04 15:49:11
                ENDS: NULL
              STATUS: ENABLED
       ON_COMPLETION: NOT PRESERVE
             CREATED: 2016-04-04 15:49:11
        LAST_ALTERED: 2016-04-04 15:49:11
       LAST_EXECUTED: NULL
       EVENT_COMMENT:
          ORIGINATOR: 33893
CHARACTER_SET_CLIENT: utf8
COLLATION_CONNECTION: utf8_general_ci
  DATABASE_COLLATION: utf8_general_ci
2 rows in set (0.00 sec)

mysql> SELECT @@event_scheduler;
+-------------------+
| @@event_scheduler |
+-------------------+
| OFF               |
+-------------------+
1 row in set (0.00 sec)


MySQL Bugs: #73206: MySQL Fabric should report a warning when MySQL Event Scheduler is disabled




1. logテーブルをBlackhole化する

mysql> use fabric
mysql> ALTER TABLE log Engine= Blackhole;

一番最初にこれが出てくるのもなんだかななんだけど、なんとこれ無事に動く。
mysqlfabricデーモンを再起動してもフツーに動いた。マジか。


2. ロギングをすっ飛ばすようにMySQL Fabric側をゴニョる

$ diff -C1 /usr/lib/python2.6/site-packages/mysql/fabric/handler.py handler.py
*** /usr/lib/python2.6/site-packages/mysql/fabric/handler.py    2015-09-11 14:31:50.000000000 +0900
--- handler.py  2016-05-16 16:51:12.000000000 +0900
***************
*** 209,214 ****
          """
-         persister.exec_stmt(_INSERT_FABRIC_LOG,
-             {"params": (subject, reported, reporter, info, info_category,
-             info_type)}
-         )

--- 209,210 ----

これでももちろんMySQL Routerはちゃんと動く。


3. 定期的にlogテーブルからレコードをパージする

至極当たり前すぎる。
何故かすごくごちゃごちゃとインデックスが張ってあるので、reportedで期間を切って定期的に消すのはそんなに難しくないはずだ。
(最近のMySQLはOPTIMIZE TABLEもオンラインでできるのでー。。)

mysql> SHOW CREATE TABLE log\G
*************************** 1. row ***************************
       Table: log
Create Table: CREATE TABLE `log` (
  `subject` varchar(40) NOT NULL,
  `reported` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
  `reporter` varchar(64) NOT NULL,
  `message` text,
  `category` int(11) NOT NULL,
  `type` int(11) NOT NULL,
  KEY `key_subject_reported` (`subject`,`reported`),
  KEY `key_reporter` (`reporter`),
  KEY `key_reported` (`reported`),
  KEY `key_category` (`category`),
  KEY `key_type` (`type`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)


これ、実際に運用してる人はどうしてるんでしょうか。
お客様の中にMySQL Fabricを運用している方はいらっしゃいませんか?


…いらっしゃいませんね。