日々の覚書: 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 さんが

mysql5.6=>mysql5.7の mysql_upgradeが5時間経っても終わらない。。。
— masasuzu.lab (@masasuz) 2016年6月20日

@masasuz 5.7のmysql_upgradeは古いDATETIME型を小数点数対応済のDATETIME型に書き換える処理が走るので、mysqldumpからの戻しと同じくらいかかる場合も。。
— yoku0825 (@yoku0825) 2016年6月20日

@yoku0825 がりがり書き換えしてますね。。。。ログ見る限り。
— masasuzu.lab (@masasuz) 2016年6月20日

@masasuz ウチは5.6化する時に全部mysqldumpからの戻しでDATETIME型を変換しているので、罠と認識していませんでした。。
— yoku0825 (@yoku0825) 2016年6月20日

@yoku0825 めちゃくちゃデータ量多いのでmysqldumpは最初から選択肢に入ってなかったのでした。。。
5.5 => 5.6のmysql_updgradeがそんなに時間かからなかったので油断してました。
— masasuzu.lab (@masasuz) 2016年6月20日

@masasuz 時既に遅い気がしますが、 avoid_temporal_upgrade=1 でDATETIME型変換を無効にできたりします。。

https://t.co/A1XRVsJ33d
— yoku0825 (@yoku0825) 2016年6月20日

というわけで計ってみた。
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とかすると速くなるかも。

日々の覚書

GA

2016/06/21

MySQL 5.7のmysql_upgradeがやたら重い件

0 件のコメント :

コメントを投稿