2013-12-06

tmpfs のファイルを zfs の log device に入れられる件 #zfs #solaris

solaris zfs

ちょっとしたメンテナンスで InnoDB のテーブル圧縮を並列でやっていたんだけど、 random i/o が多すぎて全然すすまない。悪いことにこのサーバは iSCSI ディスクしか無くて、どうしようかなと思っていたときにふと気づいたこと。

% dd if=/dev/zero of=/tmp/zero.dat bs=1048576 count=1024
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB) copied, 1.10092 s, 975 MB/s

% sudo zpool add tank cache /tmp/zero.dat
cannot add to 'tank': cache device must be a disk or disk slice

これはダメなんだけど、

% sudo zpool add tank log /tmp/zero.dat
% zpool status -v tank
  pool: tank
 state: ONLINE
  scan: none requested
config:

        NAME                                     STATE     READ WRITE CKSUM
        tank                                     ONLINE       0     0     0
          c0t600144F0A3B974070000529E2FEB0001d0  ONLINE       0     0     0
        logs
          /tmp/zero.dat                          ONLINE       0     0     0

errors: No known data errors

こっちは通るんですね。

DTT の iopattern で見た結果。中央のスパイクがあるところで add log した。 KW (kbytes of write) がちゃんと増えてくれてるようです。

iostat(1M) で iSCSI ディスクを調べてしまうと write iops は逆に減るのかも。 iopattern は io:genunix::done で調べて tick-1sec で表示してるので、これを信じるので良いのだと思う。

2013-06-02

Re: rsync で削除すると速い (?) 件

rsync coreutils zfs dtrace

こんなの頑張る意味あんの? って気もしなくもないけど、必要なことの小さいサンプルになったのでグラフまで書いてみた。

rsync --delete よりも rm -rf のほうが、 getdents (readdir) の累計時間が 30 秒多いから real も 30 秒多い、というのが前提のように書いてますが、実際に正しいのかは未確認。重要なのは methodology ってことで。

調査用 dtrace スクリプト

aggregation の key に wall からの経過時刻 (秒単位) を入れることで秒ごとに出した。 quantize したいけど @ を数えんのめんどいし、あんまり printf しまくると drop されちゃうし。

avg いるの? というのは excel の pivot table の都合。

#!/usr/sbin/dtrace -s

int start_wall;

dtrace:::BEGIN
{
    start_wall = timestamp;
}

syscall:::entry
/execname == "rm" || execname == "rsync"/
{
    self->start[pid, probefunc] = timestamp;
}

syscall:::return
/self->start[pid, probefunc] && (probefunc == "getdents64" || probefunc == "unlinkat")/
{
    @sum[pid, execname, probefunc, "sum", (timestamp - start_wall)/1000000000] = sum(timestamp - self->start[pid, probefunc]);
    @avg[pid, execname, probefunc, "avg", (timestamp - start_wall)/1000000000] = avg(timestamp - self->start[pid, probefunc]);
    @cnt[pid, execname, probefunc, "cnt", (timestamp - start_wall)/1000000000] = count();

    self->start[pid, probefunc] = 0;
}

getdents64 と unlinkat の流れ

なんとも分かりやすい結果で、以下がわかった。

rsync は最初に getdents (readdir) しまくってファイルリスト作り (~80sec)、その後いっきにファイルを消す (~120sec)
rm -rf は 5~10 秒ごとに readdir と unlink を繰り返す
ただし、どちらも最終的に syscall の回数は同じ *1

結果として rm のほうが遅くなる理由は、やはり 1回の readdir にかかる時間が長い様子。

直感的にはファイル数が少ないほうが readdir が速いのかと思ったが、そうでもなかった。ブレはあるものの、 rm で unlink が進んだ後の readdir でも分かりやすい速度変化はなかった。

まとめ

やっぱ一気にやったほうが速い。ただし最初にファイルリスト作る分メモリをたくさん必要とする。 prstat で眺めただけだけど、 rm は RSS が 24M で cap されてるような雰囲気。一方 rsync のほうはモリモリ増えていって 44M で止まった。

...という以前に、これはファイルシステムで相当変わるはず (とくに zfs なら log device に ssd 突っ込んで xargs -P で rm とか) なので、 zfs においては余り差が出なかったようです。

個人的には zfs はディレクトリ中のファイルが多くても安定して動くよ、という結論で終えたいですが、そこまで言うにはこれじゃ厳しいな。

*1:追記: syscall の回数が同じなのは、 rm -rf がディレクトリ内のファイル数 N に対して O(N) であってほしいという要請から当然といえば当然ですね。

2013-06-01

rsync で削除すると速い (?) 件

rsync coreutils

https://twitter.com/matsuu/statuses/340655491917152257
http://linuxnote.net/jianingy/en/linux/a-fast-way-to-remove-huge-number-of-files.html

ちょっと気になったので試したけどそんな差がでなかった。もうちょい調べたいとこだが時間切れで途中までのメモ。
(追記: つづきを http://d.hatena.ne.jp/ichii386/20130602/1370112280 に書きました。)

環境

solaris11.1
zfs
rm: coreutils-8.21, ふつうに gcc-4.5 で ./configure && make しただけ
rsync: rsync-3.0.9, coreutils 同様
空の zfs で ``mkdir aho && cd aho && seq 1000000 | xargs -n100 touch'' した状態

だいたい以下のような感じで実行した。

% sudo dtrace -s ~/aho.d -c 'ptime -m /home/ichii386/opt/bin/rm -rf a' 2>&1 | tee ~/rm-rf.out

@aho[pid, tid, probefunc] = sum(timestamp - self->start[pid, tid, probefunc]);

なお rsync はローカル間の rsync であっても、親から送信元/送信先用に 2 つ子プロセスを作ることに注意。なので pid が必要。 tid は不要だが入れただけ。

syscall

rm -rf

real     2:01.505976414
user        2.769709176
sys        55.723185817
trap        0.001915214
tflt        0.000000000
dflt        0.000000000
kflt        0.000000000
lock        0.000000000
slp      1:00.229405966
lat         2.781001128
stop        0.000432667
(中略)
    23225        1  openat64                                                      67380
    23225        1  brk                                                        34923152
    23225        1  fstatat64                                               26603970151
    23225        1  unlinkat                                                27208982573
    23225        1  getdents64                                              54917440620

(カラムは順に pid, tid, probefunc, sum)

rsync --delete

real     1:36.321831952
user        2.637288864
sys      1:06.216847212
trap        0.000469720
tflt        0.000000000
dflt        0.000000000
kflt        0.000000000
lock        0.000000000
slp      3:39.204833186
lat         0.813593332
stop        0.000393367
(中略)
    23205        1  brk                                                         4543719
    23205        1  pollsys                                                    23666804
    23205        1  fstatat64                                               22882608802
    23205        1  getdents64                                              24778032557
    23205        1  unlinkat                                                35046337825
    23206        1  pollsys                                                 96253638085
    23204        1  pollsys                                                 96312023834

rm -rf に比べ 30sec ほど速いが、 getdents64 が 30sec ほどなので、それが原因ぽい。 (pid=23204, 23026 の pollsys はただ待ってるだけ)

getdents64 の分布

sum() を quantize() した結果:

rm -rf

           value  ------------- Distribution ------------- count
            4096 |                                         0
            8192 |                                         1
           16384 |                                         0
           32768 |                                         1
           65536 |                                         0
          131072 |                                         0
          262144 |                                         1
          524288 |                                         0
         1048576 |@@@@@@                                   568
         2097152 |@                                        111
         4194304 |@@@@@@@                                  689
         8388608 |@@@@@@@@@@@@@@@                          1463
        16777216 |@@@@@@@                                  699
        33554432 |@@                                       232
        67108864 |                                         39
       134217728 |                                         8
       268435456 |                                         4
       536870912 |                                         0
      1073741824 |                                         1
      2147483648 |                                         0

rsync --delete

           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |                                         1
            8192 |                                         0
           16384 |                                         1
           32768 |                                         0
           65536 |                                         0
          131072 |                                         0
          262144 |                                         0
          524288 |                                         2
         1048576 |@@@@@@@@@@@@@@@@@@@@@@@@                 2317
         2097152 |@@@@                                     364
         4194304 |@@@                                      270
         8388608 |@@@@@                                    463
        16777216 |@@@                                      265
        33554432 |@                                        121
        67108864 |                                         10
       134217728 |                                         1
       268435456 |                                         0
       536870912 |                                         1
      1073741824 |                                         0

感想

rsync は最初にファイルの一覧作ってから削除するだけだけど、 rm の場合は消しながら「ディレクトリが空になったか」を検査してるのかな?

...と思ったけど、だとすれば getdents の回数が変わるはずなんだけど、同じなんだよね。 rm のほうがバラついてるし、とすると消してる間にディレクトリの中身が変わるから readdir にかかるコストが安定しないとか?

2013-05-25

mysql-5.6.11 で secure-auth が厳しくなった件

mysql

@yoku0825 さんが http://yoku0825.blogspot.jp/2013/05/mysql56mysql50ioerror-2049.html に書かれている通り

mysql-5.6.11 で secure-auth が厳しくなった (Bug#15977433 だが非公開?)
slave io thread とか federated が secure-auth=off でもそれを参照してない

ために、 master が old password 使っているとどうやっても replication が繋がらなくなってしまいました。やりたいことはわかるので、まあ仕様ってことで理解したいものの、いくつか試行錯誤した結果、現実的には厳しい。

mysqld の secure-auth が client としての挙動に影響するのはなんかおかしい気もするし、まじめにやるなら別の変数用意して参照するとか、もうそれ用に auth plugin 作っちゃえばいいんですけれど、今の流れではそこまで気合を入れる気も起きない。

@yoku0825 さんパッチ (上のリンク参照)
- mysql_init() のデフォルト書き換える方針
- 一緒にビルドされるクライアントプログラムも変わって、副作用が追いきれなくて怖いです...

old_password_auth_client でエラーにしない (5.6.10 に戻す)
- どういうバグが報告されてるのか分からないし、他のハマリポイントを隠蔽しちゃうのがイヤ
- http://bazaar.launchpad.net/~mysql/mysql-server/5.6/revision/4755

slave io thread のとこだけ secure-auth 見ない
- クソ1行パッチ。影響範囲は少ない (と信じたい)

--- ./sql/rpl_slave.cc.orig     2013-04-05 21:27:18.000000000 +0900
+++ ./sql/rpl_slave.cc  2013-05-25 06:11:44.615072089 +0900
@@ -6669,6 +6669,8 @@
   /* This one is not strictly needed but we have it here for completeness */
   mysql_options(mysql, MYSQL_SET_CHARSET_DIR, (char *) charsets_dir);

+  mysql->options.secure_auth= FALSE;
+
   if (mi->is_start_plugin_auth_configured())
   {
     DBUG_PRINT("info", ("Slaving is using MYSQL_DEFAULT_AUTH %s",

追記: さいしょ ``mysql_options(mysql, MYSQL_SECURE_AUTH, "off");'' と書いてたのはウソですすいません

どうなんですかね、やっぱ auth plugin 書いたほうがいろいろ応用は効くんじゃないかと思いますけど、みんなどうしてんだろ。

2013-03-03

0時ちょうどに MySQL の snapshot をとりたい (注: MyISAM 限定)

mysql myisam zfs solaris

今日書いてたスクリプトの結果待ちで、ひさしぶりにメモ。

やりたいこと

毎日0時ちょうどに mysql のデータの snapshot を取りたい
snapshot はバックアップのためではなく、アクセスできる状態のものにしたい

環境

MySQL-5.6.10
- サービスで使っている master は別にいて、 snapshot 取る用に slave を用意します
- あとで出てきますが mysqlbinlog の出力フォーマットとかで他のバージョンは未確認
Solaris11u1, ZFS
- 11 以上ならたぶん大丈夫かと

0時ちょうど

「毎日0時ちょうど」という要件を満たすために、0 時よりちょっと前 (23:55とか) に slave の sql_thread を止め、 relaylog が十分溜まってから mysqlbinlog で必要な pos を調べ、そこまで sql_thread を走らせることにします。

たとえば master から 0 時ちょうどを判定できる event が流れてくればいいんですけれど、そうでない場合、 0 時前後の event たちを眺めて「ここまで実行したら 0 時ちょうど」を (sql thread を止めたまま) 確認しないといけません。 master が binlog 書いた時間を調べる方針もあるかもしれませんが、 master には負荷を掛けたくないです。

mysqlbinlog の出力

たとえば以下のような出力があるとします。

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#130302  0:00:09 server id 100  end_log_pos 120   Start: binlog v 4, server v 5.6.10-log created 130302  0:00:09
# at 120
#130302  0:00:09 server id 200  end_log_pos 167     Rotate to master.004175  pos: 4
# at 167
#130302 21:03:32 server id 200  end_log_pos 98      Start: binlog v 4, server v 5.5.2-log created 130302 21:03:32
# at 261
#130302 21:03:32 server id 200  end_log_pos 306     Query   thread_id=2718205182    exec_time=0     error_code=0
use `hoge`/*!*/;
SET TIMESTAMP=1362063599/*!*/;
INSERT INTO foo .../*!*/;
# at 469
#130302 21:03:32 server id 200  end_log_pos 555     Query   thread_id=2718205180    exec_time=0     error_code=0
SET TIMESTAMP=1362063600/*!*/;
UPDATE foo ..

ちなみに SHOW RELAYLOG EVENTS で似たようなものを出せますが、 timestamp を知ることはできないようです。 mysqlbinlog が OS のプロセス実行でキモい気もしますが、 snapshot 作成のとこでも必要だし、まあ気にしない。

SET TIMESTAMP 文が 0 時を越えた直前の pos が「0時ちょうど」になるはずです。この例だと pos=469 が 0 時ちょうど、ということになりますね。

範囲を絞る

この出力を地味に理解するのはアホっぽいので

% mysqlbinlog --start-datetime="2013-03-01 00:00:00" --end-datetime="2013-03-01 00:00:01" relaylog.000123

でもうちょい範囲を絞ることにします。こうすると、 pos=469 以降が出力されます。(逆に pos=261~469 が出力されません。)

いらないのを削る

絞った結果の head -n1 が pos=469 だったらいいんですが、最初の pos=4 とか 107 とかは mysqlbinlog の出力にどうしても入ってきてしまいます。しかも 107 なんてバージョンで微妙に変わりそうですよね。

そこで、 # at [pos] の次のコメント行で Start binlog とか Rotate ではなく Query になってるものを出すようにします。

% mysqlbinlog --start-datetime="2013-03-01 00:00:00" --stop-datetime="2013-03-01 00:00:01" relaylog.000123 \
    | sed -n '/^# at [0-9]\+/{N; /#[0-9].*Query/{P; q}}'
# at 469

見つからなかったら?

replication がすごい遅れてると、 0 時ちょうどの event がまだ届いてないかもしれません。その場合は適当に sleep して、存在する relaylog ファイルを順に調べることにします。

23:55 に sql thread 止めるところから始めているので、むしろ最初は見つからないはずです。

その pos まで replication を進める

あとはそのまま。

mysql> START SLAVE SQL_THREAD UNTIL RELAY_LOG_FILE="relaylog.000123", RELAY_LOG_POS=469

snapshot 作成

バックアップだったら mysqld 落として datadir をそのまま tar すればいいですけれど、たとえばデータベース名 hoge だったら hoge_20130301 で 2013/03/01 時点の snapshot にアクセスできると便利ですよね。

そこで、ディレクトリをそのままコピればオッケーな MyISAM の登場です。仮に master が InnoDB でも、この slave だけえいやっと alter table ... engine=myisam しておきましょう。

コピーする

% mysql -e 'FLUSH TABLES WITH READ LOCK; SELECT sleep(3600)' &
% cp -p /srv/mysql/hoge /srv/mysql/hoge_20130301
% kill %1

いや、しかし日数分だけコピーして容量増えるとか無理そうな気がしますね。というか 3600 秒以内にコピーが終わらないとひどいことに...。

zfs clone

そこで zfs の登場です。

zfs snapshot は差分だけしか容量を食わないので、たとえば 100GB のデータベースだが更新されるのは毎日 10MB くらいだとすれば、1日の snapshot に必要な容量は 10MB くらいで済みます。

さらには snapshot, clone はほぼ一瞬なので 3600 秒を超える不安もありません。(たぶん。)

% mysql -e 'FLUSH TABLES WITH READ LOCK; SELECT sleep(3600)' &
% sudo zfs snapshot tank/mysql/hoge@20130301
% sudo zfs clone -o mountpoint=/srv/mysql/hoge_20130301 -o readonly=on tank/mysql/hoge@20130301 \
> tank/mysql/hoge/snap/20130301
% kill %1

ついでに readonly=on もつけときましょうか。まあ rollback できるしいいんですけど。

まとめ

以上をまとたものが https://github.com/ichii386/misc/blob/master/myisam_snapshot.bash これ。

これの前バージョンはどっかの業務ですでに使ってるんですけど、まあ動いてそうだしこれもいけるかな。あ、実際に使うときはもっといろんなことをチェックしないといけないので注意。

なお zfs は以下の様な配置になります。

% zfs list -tall -oname,type,mountpoint -r tank
NAME                       TYPE        MOUNTPOINT
tank                       filesystem  none
tank/origin                filesystem  /srv/mysql
tank/origin@20130301       snapshot    -
tank/origin@20130302       snapshot    -
tank/origin/hoge           filesystem  /srv/mysql/hoge
tank/origin/hoge@20130301  snapshot    -
tank/origin/hoge@20130302  snapshot    -
tank/snap                  filesystem  none
tank/snap/hoge             filesystem  none
tank/snap/hoge/20130301    filesystem  /srv/mysql/hoge_20130301
tank/snap/hoge/20130302    filesystem  /srv/mysql/hoge_20130302

mysql から見るとこんなかんじ。

mysql> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| hoge               |
| hoge_20130301      |
| hoge_20130302      |
| mysql              |
| performance_schema |
+--------------------+
3 rows in set (0.01 sec)

課題

やっぱ innodb でもやりたいですよね。 tablespace の export/import まだ試してないし。

というか Joyent が Percona Server 使ってこういうのやってるぽいし。調べてないんでわかんないけど同じような目的なのかな?

2012-03-12

InnoDB Deep Talk #1 をやりました

mysql いろいろ

先日の 3/10 に無事 InnoDB Deep Talk #1 を開催出来ました。

発表していただいた木下さん、平塚さん、瀬島さん、LT をしていただいた皆さま、そして参加者の皆さま、ありがとうございました！内容は公開できない内容も含まれるということで、申し訳ありませんが ust や録画はありませんでした。平塚さんの資料は http://d.hatena.ne.jp/sh2/20120310 をご参照下さい。

感想、反省など

参加者について
- 多くの方は InnoDB ユーザでしたが、 MySQL に限らず Oracle や PostgreSQL の方も参加されていました。ビル提出用の名簿をチラ見するに、ほんといろんな会社の方が参加されていたようです。

タイトルについて
- "InnoDB Deep Talk #1" のどこが釣りなのかというと、 MySQL Casual Talk に対抗したかったからです。なぜ対抗したいかは察して下さい。

QR コードによる入館について
- すごい厳密な入館管理が必要だと思われてしまうようでした。意図は前のエントリにちょっと書いたとおりではありますが、 QR 取得ページにちゃんと説明を書かないといけないことがわかりました。
- 一方で、受付はたいへんスムーズに進めることができました。これまでのイベントとかでやってた受付業務がアホのようです...。

Percona の話
- 詳しくは木下さんの非公開資料参照なので申し訳ありませんが、これを機に Percona という会社があって、いろんな人や contribute のやりとりがあるということが日本の MySQL コミュニティに少しでも伝わればいいなと思います。去年の秋にロンドンまで行って Percona Live 2011 に参加した時の違和感が少しでも無くなれば...。

オプティマイザの話
- Deep すぎてよかった。オプティマイザの具体的な実装を見たのは初めてでした。
- Histogram はある意味中間 index を作るようなもんだよなーと思った。ぜんぶで頑張るわけにもいかないので、 "create index foo (foo) using histogram" とかあってもいいのかも。

瀬島さんの話
- きっと発表内容が某すべらない話のブログに上がってくれるはずです。ジャストなうお願いしました

ネタ by @moriyoshit
- http://d.hatena.ne.jp/moriyoshi/20120311/1331488092 さすがです

開催側だと自分が聞きたい話が聞けるのでありがたいですが、運営の都合ぜんぶの話を聞けないことがほとんどなんですよね。でも懲りずにまたなんかやりたいです！

2012-03-07

[mysql][いろいろ] InnoDB Deep Talk #1 をやります、のつづき

http://n-gram.jp/inno/ に入館に関するメモページを作りました。

入館に関して

森ビル (六本木ヒルズ) では、たくさんのお客さんがいっぺんに来たり、土日で受付のお姉さんがいないとき、会場側となるテナントに入館シールを事前に渡しておくことで、受付の負荷をテナント側に委譲する仕組みがあります。

これはあくまで委譲であって、平日の昼に往訪で入るときと同様のセキュリティレベルは維持されます。平日の昼の場合は、以下のようにして入ることになります。 (これは一般論で、テナントごとにビルとの調整もあるでしょうし、ビルには入れたとしてもその先でテナント個別のセキュリティチェックをしている場合もあります。)

お客さんの名前と所属を確認し、紙の入館カードを渡して入ってもらう
テナントの人がカードにサインをし、お客さんが出るときにカードを回収する

ビルとしては、入った人の名前と所属と、ちゃんと出ていったことを確認したいわけです。これが入館シールによる委譲では以下のようになります。

お客さんの名前と所属はテナントの人に事前に名簿化しておいてもらう
入館カードにサインするのは、事前に入館シールを発行してもらうときの申請でまとめて済んでいることにする
入った人が全員ちゃんと出ていったかどうかはシールを回収し枚数を数えることで担保
事後に改めて、実際にきた人の名簿を提出し、ドタキャン・ドタ参加も対応

ここで問題になるのが、受付で入館シールを渡すかわりに事前名簿との突き合わせをしなければいけません。これがすごい手間取る。

QR コードの登場

そこで、今回は事前にアカウント名を QR コード化し、名簿との突き合わせを QR コードリーダでさくさくやろうと思っています。

QR コードリーダは http://www.denso-wave.com/ja/adcd/product/iccard/qk20_ic/ です。これは USB 接続でキーボードデバイスとして認識されるので、 STDIN から入力を待って付き合わせるプログラムをターミナルで実行しっぱなしにし、来た人に QR コードをかざしてもらえばいいわけですね!

もちろん、よく分かんないライブラリから叩いてなんかするモードというのもあるようです。まだ使ってないけど。

いや?

ほんとはもっと色々やりたかったんですが、今回はそこまでやれなそうです。実際だれが来たかが分かればいいなら、その場で入力フォームに入力してもらえばいいわけで...。

直前に余裕あったらいろいろ追加するかもしれないんで、生暖かく見守って下さいませ。よろしくお願いします。