'Client requested master to start replication from impossible position'の原因

たとえばこんなエラーログ。

140603 10:05:58 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000032' at position 61352894, relay log './mysql-relay.000787' position: 21485832
140603 10:05:58 [Note] Slave I/O thread: connected to master 'replicator@xxx.xxx.xxx.xxx:3306',  replication started in log 'mysql-bin.000032' at position 61352894
140603 10:05:58 [ERROR] Error reading packet from server: Client requested master to start replication from impossible position ( server_errno=1236)
140603 10:05:58 [ERROR] Got fatal error 1236: 'Client requested master to start replication from impossible position' from master when reading data from binary log
140603 10:05:58 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.000032', position 61352894

START SLAVEしたタイミングでこんなんが出ることがあります。
そしてI/Oスレッドのみが止まる。SHOW SLAVE STATUSで見るとSlave_IO_Running: No, Slave_SQL_Running: Yes な状態です。

ゆえあってMySQL 5.0なので(というか2014年にもなってTritonnです)、SHOW SLAVE STATUSには何も表示されてないですが、5.1 以降なら↑のログの内容がLast_IO_Errorに表示されるんじゃないかと。

上から読んでいくと、

1. SQLスレッドが初期化された。マスターのログファイルはmysql-bin.000032でログポジションは61352894、リレーログファイルはmysql-relay.000787でログポジションが21485832。
2. I/Oスレッドがマスターに接続して、mysql-bin.000032のポジション61352894のログを要求した。
3. サーバーからerrno= 1236 を受け取った。メッセージは「クライアントのリクエストしたレプリケーションの開始位置がアリエナイ！」
4. 大事なので(かどうかは知らんけど)2回言った
5. I/Oスレッドが動作を停止した。最後に読んだマスターのログファイルは..(略)

errno= 1236は「バイナリーログをもらおうとしたら致命的な(=リトライしても成功する見込みのない)エラーが発生した」というI/Oスレッドの(わりと)汎用エラーなので、大事なのはエラーメッセージの方。

$ perror 1236
MySQL error code 1236 (ER_MASTER_FATAL_ERROR_READING_BINLOG): Got fatal error %d from master when reading data from binary log: '%-.320s'

そしてマスター上のバイナリーログファイルはこんなんになっており、

$ ll mysql-bin.*
-rw-rw---- 1 mysql mysql 268436192 May 31 21:26 mysql-bin.000031
-rw-rw---- 1 mysql mysql  61341696 Jun  3 05:35 mysql-bin.000032
-rw-rw---- 1 mysql mysql        98 Jun  3 05:53 mysql-bin.000033
-rw-rw---- 1 mysql mysql       117 Jun  3 06:15 mysql-bin.000034
-rw-rw---- 1 mysql mysql   4630804 Jun  3 11:35 mysql-bin.000035
-rw-rw---- 1 mysql mysql        95 Jun  3 06:29 mysql-bin.index

確かにmysql-bin.000032に61352894バイト目は存在しない(master_log_posはバイナリーログファイルの先頭からのバイトオフセット)
だけど、スレーブは61352894バイト目までは終わってるから次をよこせと言っている状況。

マスターがsync-binlog= 0 でOSごとクラッシュした時にこんな状況が起こりがちで、

1. マスターがバイナリーログをwrite
2. Binlog dump threadがwriteされたバイナリーログを読み出してスレーブに送信
3. マスターのバイナリーログがフラッシュされる前にOSクラッシュ

とまあ、書き込みワークロードをかけながらOSをクラッシュさせるなり電源を落とすなりで比較的簡単に再現できる。

CHANGE MASTER TO master_log_file= 'mysql-bin.000033', master_log_pos= 1; で仮復旧はできるものの、その後マスター/スレーブのデータの整合性確認しないといけないのが面倒とか、バイナリーログの保全ができてない(log-slave-updatesしているならそっちから抽出すれば大丈夫だろうけど)ので、この時間近辺のPITRは危ないとか色々あるので、5.6のmysqlbinlog使ったリアルタイムバックアップももう一度考えようかなぁ。。

InfiniDB 4.5をざっくりインストール…する前に色々困ったこと

今ふっと2年くらい前にInfobright調べてたことを思い出しましたが気にしない。

Infobrightが今どうなったのかは知りませんが、InfiniDBは去年くらい(4.0)から「商用版とオープンソース版のコードベースが統合され、機能制限がなくなった(同じ機能が使える)」と前々から聞いていたので、GPL版だと変にコア数の制限を受けたりするInfobright使うぐらいならInfiniDBかなと思って。

昔は www.calpont.com (Calpontって会社がInfiniDBを作ってた) だったものの、今はInfiniDB社になったっぽく、URLは http://infinidb.co/ にリダイレクトされる。

ダウンロードページにいってプラットフォームを選ぶと、「Access denied. You must log in to view this page.」と言われて、アカウントを登録しろと言われる。ちなみにここまで一切合切ライセンスの話(GPLv2だよ、という話)は無し。MySQLのように「No thanks」のリンクは無く、メールアドレスを差し出さない限りダウンロードはできない(2014/05/26現在) メールアドレスを差し出すと何が起こるのかも何の説明も無い。

2013/12/13時点の情報だけど、メールアドレス登録したら

<日本のお客様へ>
Calpont Corporation（以下：Calpont）は、日本におけるInfiniDBの販売及びサポートに関して株式会社アシスト（以下：アシスト社）と提携しており、
サイト上から登録頂いた情報はアシスト社と共有しています。
そのため、アシスト社から直接コンタクトをする場合がありますので、あらかじめご了承下さい。

とかいうメールが来た(今もそうなのかどうかはわからない) 今見返して気付くものの、当時はまだCalpont社だったのか。

これはなんだか非常に嫌だなぁ(´･ω･｀) < せめて同意とってー


で、登録後にダウンロードできるのはWindows, Linux(バイナリーの.tar.gz), .rpm, .deb の4種類。

ｿｰｽｺｰﾄﾞﾏﾀﾞｧ-? （･∀･ ）っ/凵⌒☆ﾁﾝﾁﾝ

バイナリーの.tar.gzの中にもライセンス書いてないし、ソースコード取得先も書いてないからちょっと不安になったものの、ソースコードはGithubから取ってくるらしい。

InfiniDB本体のリポジトリー と MySQLインターフェイスのリポジトリー があって、なんかmakeしようと色々がんばってみたりしたけどダメだったので、既にメールアドレスも登録しちゃってたので諦めてバイナリーをDLしてきた。


という訳で、今のところメールアドレスを登録しないとさっくり試すにはつらそうな気配がするものの、いっこだけ簡単にやる方法として、InfiniDBが提供しているEC2のAMIを使ってインスタンスを立ち上げると、インストールが終わった状態(かつ、/rootに.rpmが置いてあるままの状態)で上がってくるので、このrpmファイルをscpで持ってきて、好きなところにインストールする。

rpmファイルのライセンスがGPLv2でなくてちょっとあせったけれど、ただの間違いらしいのでそのうち直るだろうし、↑の方法ももちろん問題ない。

@yoku0825 Thanks for catching this, we are fixing rpm license line to reflect GPLv2. For now you can distribute the rpm you downloaded.
— InfiniDB (@InfiniDB) 2014, 5月 27

InfiniDBのデータノード的なプロセスのベースディレクトリが/usr/local/Calpont 、mysqldも /usr/local/Calpont/mysql にある想定で色々設定してあって、後者はまだmy.cnf書き換える気にならなくもないけど、前者は色々面倒そうなので、パッケージファイルで突っ込んじゃうか、.tar.gzバイナリーを配置するにしても/usr/local/Calpont 決め打ちでいった方が面倒はなさげ。

ざっくり使ってみた感想はまたいずれ。

Tritonnのsenna_log_levelの取りうる値

senna_log_levelでぐぐったけど、まさかの何も見つからなかったので。

const char *senna_log_level_type_names[] = { "NONE", "EMERG", "ALERT",
                                             "CRIT", "ERROR", "WARNING",
                                             "NOTICE", "INFO", "DEBUG",
                                             "DUMP", NullS };
TYPELIB senna_log_level_typelib=
{
  array_elements(senna_log_level_type_names)-1, "",
  senna_log_level_type_names, NULL
};

tritonn-1.0.12-mysql-5.0.87/sql/set_var.cc

それだけ。

MySQLのバイナリーログ、999999の次は？

1000000です。
↓は"log-bin= bin"を設定した状態。

# ll
total 537160
-rw-rw---- 1 mysql mysql        56 May 20 14:32 auto.cnf
-rw-rw---- 1 mysql mysql       139 May 20 15:42 bin.000001
-rw-rw---- 1 mysql mysql        13 May 20 15:42 bin.index
-rw-r----- 1 mysql root      11916 May 20 15:42 error.log
-rw-rw---- 1 mysql mysql       884 May 20 15:42 ib_buffer_pool
-rw-rw---- 1 mysql mysql 268435456 May 20 15:42 ib_logfile0
-rw-rw---- 1 mysql mysql 268435456 May 20 15:42 ib_logfile1
-rw-rw---- 1 mysql mysql  12582912 May 20 15:42 ibdata1
-rw-rw---- 1 mysql mysql         6 May 20 15:42 mysql.pid
drwx------ 2 mysql mysql      4096 May 20 14:32 mysql
drwx------ 2 mysql mysql      4096 May 20 14:32 performance_schema
-rw-rw---- 1 mysql mysql       322 May 20 15:42 slow.log
drwx------ 2 mysql mysql      4096 May 20 14:32 test

# mv -i bin.000001 bin.999999
# echo bin.999999 > bin.index

# /etc/init.d/mysql restart

# ll
total 537172
-rw-rw---- 1 mysql mysql        56 May 20 14:32 auto.cnf
-rw-rw---- 1 mysql mysql       120 May 20 15:42 bin.1000000
-rw-rw---- 1 mysql mysql       139 May 20 15:42 bin.999999
-rw-rw---- 1 mysql mysql        27 May 20 15:42 bin.index
-rw-r----- 1 mysql root      13820 May 20 15:42 error.log
-rw-rw---- 1 mysql mysql       884 May 20 15:42 ib_buffer_pool
-rw-rw---- 1 mysql mysql 268435456 May 20 15:42 ib_logfile0
-rw-rw---- 1 mysql mysql 268435456 May 20 15:42 ib_logfile1
-rw-rw---- 1 mysql mysql  12582912 May 20 15:42 ibdata1
-rw-rw---- 1 mysql mysql         6 May 20 15:42 mysql.pid
drwx------ 2 mysql mysql      4096 May 20 14:32 mysql
srwxrwxrwx 1 mysql mysql         0 May 20 15:42 mysql.sock
drwx------ 2 mysql mysql      4096 May 20 14:32 performance_schema
-rw-rw---- 1 mysql mysql       483 May 20 15:42 slow.log
drwx------ 2 mysql mysql      4096 May 20 14:32 test

どこまでいけるのか試してみましたが、2^ 63までのようです。

# mv -i bin.1000000 bin.9223372036854775808
# echo bin.9223372036854775808> bin.index

# /etc/init.d/mysql restart

# ll
total 537192
-rw-rw---- 1 mysql mysql        56 May 20 14:32 auto.cnf
-rw-rw---- 1 mysql mysql       170 May 20 16:21 bin.9223372036854775808
-rw-rw---- 1 mysql mysql        50 May 20 16:21 bin.index
-rw-r----- 1 mysql root      39612 May 20 16:21 error.log
-rw-rw---- 1 mysql mysql       884 May 20 16:21 ib_buffer_pool
-rw-rw---- 1 mysql mysql 268435456 May 20 16:21 ib_logfile0
-rw-rw---- 1 mysql mysql 268435456 May 20 15:42 ib_logfile1
-rw-rw---- 1 mysql mysql  12582912 May 20 16:21 ibdata1
-rw-rw---- 1 mysql mysql         6 May 20 16:21 mysql.pid
drwx------ 2 mysql mysql      4096 May 20 14:32 mysql
srwxrwxrwx 1 mysql mysql         0 May 20 16:21 mysql.sock
drwx------ 2 mysql mysql      4096 May 20 14:32 performance_schema
-rw-rw---- 1 mysql mysql      1127 May 20 16:21 slow.log
drwx------ 2 mysql mysql      4096 May 20 14:32 test

# less error.log
..
2014-05-20 16:19:01 9560 [Warning] Next log extension: 9223372036854775808. Remaining log filename extensions: 9223372039002259455. Please consider archiving some logs.
2014-05-20 16:19:01 9560 [Warning] Next log extension: 9223372036854775808. Remaining log filename extensions: 9223372039002259455. Please consider archiving some logs.
..

mysql> FLUSH BINARY LOGS;
Query OK, 0 rows affected (0.00 sec)

# ll
total 537192
-rw-rw---- 1 mysql mysql        56 May 20 14:32 auto.cnf
-rw-rw---- 1 mysql mysql       170 May 20 16:22 bin.9223372036854775808
-rw-rw---- 1 mysql mysql        76 May 20 16:22 bin.index
-rw-r----- 1 mysql root      39782 May 20 16:22 error.log
-rw-rw---- 1 mysql mysql       884 May 20 16:21 ib_buffer_pool
-rw-rw---- 1 mysql mysql 268435456 May 20 16:21 ib_logfile0
-rw-rw---- 1 mysql mysql 268435456 May 20 15:42 ib_logfile1
-rw-rw---- 1 mysql mysql  12582912 May 20 16:21 ibdata1
-rw-rw---- 1 mysql mysql         6 May 20 16:21 mysql.pid
drwx------ 2 mysql mysql      4096 May 20 14:32 mysql
srwxrwxrwx 1 mysql mysql         0 May 20 16:21 mysql.sock
drwx------ 2 mysql mysql      4096 May 20 14:32 performance_schema
-rw-rw---- 1 mysql mysql      1127 May 20 16:21 slow.log
drwx------ 2 mysql mysql      4096 May 20 14:32 test

# less error.log
..
2014-05-20 16:22:08 11194 [Warning] Next log extension: 9223372036854775808. Remaining log filename extensions: 9223372039002259455. Please consider archiving some logs.

おい、Query OK, じゃないだろ。。

InnoDBオンラインALTER TABLEではIndex_lengthが更新されない

そのままなんですが。


インデックス張ってからロードしたとき。

mysql> CREATE TABLE t1 (num int unsigned, val varchar(32), upd datetime default current_timestamp);
mysql> ALTER TABLE t1 ADD KEY (val, upd), ADD KEY (upd);
mysql> LOAD DATA INFILE '/data/tmp/md5.tsv' INTO TABLE t1(num, val);

$ ls -ls /data/tmp/mysql/d1/t1.ibd
1754804 -rw-rw---- 1 mysql mysql 1795162112 May 20 14:41 /data/tmp/mysql/d1/t1.ibd

mysql> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 9705549
 Avg_row_length: 74
    Data_length: 727711744
Max_data_length: 0
   Index_length: 1027342336
      Data_free: 6291456
 Auto_increment: NULL
    Create_time: 2014-05-20 14:38:32
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)

ALTER TABLE .. ALGORITHM= COPY

mysql> CREATE TABLE t1 (num int unsigned, val varchar(32), upd datetime default current_timestamp);
mysql> LOAD DATA INFILE '/data/tmp/md5.tsv' INTO TABLE t1(num, val);
mysql> ALTER TABLE t1 ADD KEY (val, upd), ADD KEY (upd), ALGORITHM= COPY;

$ ll -s /data/tmp/mysql/d1/t1.ibd
1754804 -rw-rw---- 1 mysql mysql 1795162112 May 20 15:37 /data/tmp/mysql/d1/t1.ibd

mysql> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 9188260
 Avg_row_length: 75
    Data_length: 691011584
Max_data_length: 0
   Index_length: 965476352
      Data_free: 6291456
 Auto_increment: NULL
    Create_time: 2014-05-20 15:37:16
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)

ALTER TABLE .. ALGORITHM= INPLACE 暗黙のデフォルト、いわゆるオンラインALTER TABLE

mysql> CREATE TABLE t1 (num int unsigned, val varchar(32), upd datetime default current_timestamp);
mysql> LOAD DATA INFILE '/data/tmp/md5.tsv' INTO TABLE t1(num, val);
mysql> ALTER TABLE t1 ADD KEY (val, upd), ADD KEY (upd);

$ ll -s /data/tmp/mysql/d1/t1.ibd
1394004 -rw-rw---- 1 mysql mysql 1426063360 May 20 14:45 /data/tmp/mysql/d1/t1.ibd

mysql> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 9704565
 Avg_row_length: 75
    Data_length: 729808896
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2014-05-20 14:45:40
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)

mysql> ANALYZE TABLE t1;
+-------+---------+----------+----------+
| Table | Op      | Msg_type | Msg_text |
+-------+---------+----------+----------+
| d1.t1 | analyze | status   | OK       |
+-------+---------+----------+----------+
1 row in set (0.01 sec)

mysql> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 9704565
 Avg_row_length: 75
    Data_length: 729808896
Max_data_length: 0
   Index_length: 690749440
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2014-05-20 15:42:26
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)

information_schema.tablesやSHOW TABLE STATUSを見張っている場合は要注意…:(；ﾞﾟ'ωﾟ'):

MySQL 5.6.4で実装されたinnodb-sort-buffer-sizeの値

InnoDBのオンラインALTER TABLEの時に使われるパラメーター。
セッション変数のsort_buffer_sizeのように使われて、これをあふれたぶんだけsort_merge_passes相当の処理が走るので重くなる。

http://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_sort_buffer_size

最大値が6.7GBに見えたけど全くの空目で、最大値は64Mと小さめ。暗黙のデフォルトは1M。

実際どれくらい違うのか。ざっくりテスト。

$ perl -e 'use Digest::MD5 qw/md5_hex/; open($fh, ">/data/tmp/md5.tsv"); for ($n= 1; $n<= 10000000; $n++) {printf($fh "%d\t%s\n", $n, md5_hex($n));}'

$ cat /data/tmp/md5.sql
SELECT @@innodb_sort_buffer_size;

use d1

DROP TABLE IF EXISTS t1;

CREATE TABLE t1 (num int unsigned, val varchar(32), upd datetime default current_timestamp);

LOAD DATA INFILE '/data/tmp/md5.tsv' INTO TABLE t1(num, val);

ALTER TABLE t1 ADD KEY (val, upd), ADD KEY (upd);

DROP TABLE t1;


mysql> source /data/tmp/md5.sql
+---------------------------+
| @@innodb_sort_buffer_size |
+---------------------------+
|                   1048576 |
+---------------------------+
1 row in set (0.00 sec)

Database changed
Query OK, 0 rows affected (0.03 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 10000000 rows affected (1 min 3.48 sec)
Records: 10000000  Deleted: 0  Skipped: 0  Warnings: 0

Query OK, 0 rows affected (2 min 8.53 sec)
Records: 0  Duplicates: 0  Warnings: 0

Query OK, 0 rows affected (0.70 sec)


mysql> source /data/tmp/md5.sql
+---------------------------+
| @@innodb_sort_buffer_size |
+---------------------------+
|                  16777216 |
+---------------------------+
1 row in set (0.00 sec)

Database changed
Query OK, 0 rows affected, 1 warning (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 10000000 rows affected (59.01 sec)
Records: 10000000  Deleted: 0  Skipped: 0  Warnings: 0

Query OK, 0 rows affected (2 min 8.33 sec)
Records: 0  Duplicates: 0  Warnings: 0

Query OK, 0 rows affected (0.62 sec)


mysql> source /data/tmp/md5.sql
+---------------------------+
| @@innodb_sort_buffer_size |
+---------------------------+
|                  67108864 |
+---------------------------+
1 row in set (0.00 sec)

Database changed
Query OK, 0 rows affected, 1 warning (0.00 sec)

Query OK, 0 rows affected (0.01 sec)

Query OK, 10000000 rows affected (1 min 0.29 sec)
Records: 10000000  Deleted: 0  Skipped: 0  Warnings: 0

Query OK, 0 rows affected (1 min 48.68 sec)
Records: 0  Duplicates: 0  Warnings: 0

Query OK, 0 rows affected (0.71 sec)

オンラインALTER TABLE用のパラメーターなので、ALTER TABLE .., ALGORITHM= COPYの場合はもちろん効かなかった。これを約10秒/GBの減少とみるか(ロード後で.ibdファイルは1.7GBくらい)、15%の減少とみるか。

グローバルで64Mなら、最初から最大値にしておいてもいいかな。


【2014/07/03 12:15】
実際には1つのADD KEYに対してinnodb-sort-buffer-sizeの4倍のメモリーを使うので注意。。

日々の覚書: MySQL 5.6のオンラインALTER TABLEとinnodb-sort-buffer-sizeに関する考察 

Percona XtraBackupの圧縮メモ

innobackupexのオプションごとにどれくらいかメモ。
主にファイルサイズと処理時間を比べたいだけなので、MySQLは起動しておれどトラフィックはなし。tpcc-mysqlのWH= 100をロードしただけ。

$ du -sh /data/mysql
14G     /data/mysql

データファイル意外と小さかった。。RESET MASTERしたのでバイナリーログは当然含まず。


tarボールストリーム圧縮なし

$ time innobackupex /data/mysql --stream=tar | ssh mysql@backup-server "cat - > /data/tmp/xtrabackup.tar"
..
real    4m53.213s
user    4m13.456s
sys     0m37.721s

$ ls -lh xtrabackup*
-rw-rw-r--  1 mysql mysql 8.5G May 19 16:35 xtrabackup.tar

$ mkdir xtrabackup

$ time tar ixf xtrabackup.tar -C xtrabackup

real    0m16.243s
user    0m0.163s
sys     0m16.073s

$ time innobackupex --apply-log xtrabackup
..
real    0m45.953s
user    0m0.297s
sys     0m5.908s

tarボールgzip圧縮

$ time innobackupex /data/mysql --stream=tar | gzip -c | ssh mysql@backup-server "cat - > /data/tmp/xtrabackup.tar.gz"
..
real    13m2.701s
user    15m19.741s
sys     0m28.345s

$ ls -lh xtrabackup*
-rw-rw-r-- 1 mysql mysql 4.8G May 19 16:58 xtrabackup.tar.gz

$ mkdir xtrabackup

$ time tar ixf xtrabackup.tar.gz -C xtrabackup

real    1m37.648s
user    1m31.823s
sys     0m21.962s

$ time innobackupex --apply-log xtrabackup
..
real    0m44.944s
user    0m0.277s
sys     0m6.055s

tarボールpbzip2圧縮(8並列)

$ time innobackupex /data/mysql --stream=tar | pbzip2 -p8 -c | ssh backup-server "cat - > /data/tmp/xtrabackup.tar.bz2"
..
real    3m11.137s
user    27m21.804s
sys     0m30.629s

$ ls -lh xtrabackup*
-rw-rw-r-- 1 mysql mysql 4.3G May 19 17:09 xtrabackup.tar.bz2

$ mkdir xtrabackup

$ time pbzip2 -p8 -dc xtrabackup.tar.bz2 | tar ix -C xtrabackup
tar: Read 2560 bytes from -

real    1m24.567s
user    11m18.711s
sys     0m30.188s

$ time innobackupex --apply-log xtrabackup
..
real    0m43.918s
user    0m0.291s
sys     0m6.073s

xbstream圧縮なし(1並列)

$ time innobackupex /data/mysql --stream=xbstream | ssh backup-server "cat - > /data/tmp/xtrabackup.xb"
..
real    5m17.412s
user    4m36.084s
sys     0m38.236s

$ ll -h xtrabackup.*
-rw-rw-r-- 1 mysql mysql 8.5G May 19 17:54 xtrabackup.xb

$ mkdir xtrabackup

$ time xbstream -x -C xtrabackup < xtrabackup.xb

real    1m32.016s
user    0m18.126s
sys     0m27.725s

$ time innobackupex --apply-log xtrabackup
..
real    0m47.103s
user    0m0.297s
sys     0m6.376s

xbstream圧縮あり(1並列)

$ time innobackupex /data/mysql --stream=xbstream --compress | ssh backup-server "cat - > /data/tmp/xtrabackup.xb"
..
real    5m44.481s
user    4m59.169s
sys     0m29.153s

$ ll -h xtrabackup.*
-rw-rw-r-- 1 mysql mysql 6.7G May 19 18:13 xtrabackup.xb

$ mkdir xtrabackup

$ time xbstream -x -C xtrabackup < xtrabackup.xb

real    1m11.434s
user    0m14.041s
sys     0m21.624s

$ time innobackupex --decompress xtrabackup/
..
real    1m54.178s
user    1m31.540s
sys     0m24.585s

$ time innobackupex --apply-log xtrabackup
..
real    0m45.782s
user    0m0.263s
sys     0m5.995s

xbstream圧縮あり(8並列)

$ time innobackupex /data/mysql --stream=xbstream --compress --compress-thread=8 --parallel=8 | ssh backup-server "cat - > /data/tmp/xtrabackup.xb"
..
real    3m40.315s
user    5m0.383s
sys     0m26.421s

$ ll -h xtrabackup.*

$ time xbstream -x -C xtrabackup < xtrabackup.xb
real    1m12.859s
user    0m13.734s
sys     0m20.157s

$ time innobackupex --decompress --parallel=8 xtrabackup/
..
real    2m16.178s
user    1m30.866s
sys     0m24.585s

$ time innobackupex --apply-log xtrabackup
..
real    0m45.722s
user    0m0.289s
sys     0m5.997s

decompress、多重化したらむしろ遅くなっててしょぼん。 tarボール無圧縮、--compact

$ time innobackupex /data/mysql --stream=tar --compact | ssh mysql@backup-server "cat - > /data/tmp/xtrabackup.tar"
..
real    4m50.256s
user    4m5.120s
sys     0m38.300s

$ ll -h xtrabackup.*
-rw-rw-r-- 1 mysql mysql 8.5G May 19 18:53 xtrabackup.tar

$ time tar ixf xtrabackup.tar -C xtrabackup

real    0m14.358s
user    0m0.209s
sys     0m13.879s

$ time innobackupex --apply-log xtrabackup
..
real    3m54.054s
user    0m24.002s
sys     0m41.084s

--stream=tarでは--parallelが効かないので、ごりごりやって良いなら--stream=xbstreamでいきたいところ。 容量面でcompactが全然効いた気配がないのに、--apply-logではちゃんとExpandingになって時間がかかってなんだかなぁ。 --rebuild-threads=8とかすれば多少速くなるのかも知れないけどそこまで試すアレなし。 ところでこの--compact(セカンダリーインデックスのそぎ落とし)が効かないのって、 tpcc_loadかましたあとにALTER TABLEでインデックスつけてるのがいけないような気がしてきた。

mysql> SHOW CREATE TABLE stock\G
*************************** 1. row ***************************
       Table: stock
Create Table: CREATE TABLE `stock` (
  `s_i_id` int(11) NOT NULL,
  `s_w_id` smallint(6) NOT NULL,
  `s_quantity` smallint(6) DEFAULT NULL,
  `s_dist_01` char(24) DEFAULT NULL,
  `s_dist_02` char(24) DEFAULT NULL,
  `s_dist_03` char(24) DEFAULT NULL,
  `s_dist_04` char(24) DEFAULT NULL,
  `s_dist_05` char(24) DEFAULT NULL,
  `s_dist_06` char(24) DEFAULT NULL,
  `s_dist_07` char(24) DEFAULT NULL,
  `s_dist_08` char(24) DEFAULT NULL,
  `s_dist_09` char(24) DEFAULT NULL,
  `s_dist_10` char(24) DEFAULT NULL,
  `s_ytd` decimal(8,0) DEFAULT NULL,
  `s_order_cnt` smallint(6) DEFAULT NULL,
  `s_remote_cnt` smallint(6) DEFAULT NULL,
  `s_data` varchar(50) DEFAULT NULL,
  PRIMARY KEY (`s_w_id`,`s_i_id`),
  KEY `fkey_stock_2` (`s_i_id`),
  CONSTRAINT `fkey_stock_1` FOREIGN KEY (`s_w_id`) REFERENCES `warehouse` (`w_id`),
  CONSTRAINT `fkey_stock_2` FOREIGN KEY (`s_i_id`) REFERENCES `item` (`i_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

mysql> SHOW TABLE STATUS LIKE 'stock'\G
*************************** 1. row ***************************
           Name: stock
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 9793316
 Avg_row_length: 354
    Data_length: 3469737984
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2014-05-19 15:51:37
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)

$ mysql-5.7.4-m14-linux-glibc2.5-x86_64/bin/innochecksum -S /data/tmp/mysql/tpcc/stock.ibd
File::/data/tmp/mysql/tpcc/stock.ibd
================PAGE TYPE SUMMARY==============
#PAGE_COUNT     PAGE_TYPE
===============================================
  224349        Index page
       0        Undo log page
       1        Inode page
       0        Insert buffer free list page
    1158        Freshly allocated page
      14        Insert buffer bitmap
       0        System page
       0        Transaction system page
       1        File Space Header
      13        Extent descriptor page
       0        BLOB page
       0        Compressed BLOB page
       0        Other type of page
===============================================
Additional information:
Undo page type: 0 insert, 0 update, 0 other
Undo page state: 0 active, 0 cached, 0 to_free, 0 to_purge, 0 prepared, 0 other

なぜかindex_lengthに計上されない謎。このあたりなのかなぁ？
【2014/05/20 15:59】 計上されないのはたぶん関係ない ⇒ 日々の覚書: InnoDBオンラインALTER TABLEではIndex_lengthが更新されない

5.7.4のinnochecksumでも、セカンダリーインデックスなのかクラスターインデックス(=データページ)なのかは分けられないのかー。

取り敢えずマシンパワーがあるのあらxbstream+ pbzip2, ほそぼそやるならxbstream+ compressでいいかな。