MySQLに対して、カジュアルにやってはいけない事をやってみよう[追記アリ]
※ブクマコメントで指摘頂いた箇所を追記しました><
MySQL Casual Advent Calendar 2011 21日目の記事です。
前日は@sohgohさんの
「MySQLのUDFでカジュアルにファイル操作【MySQL Casual Advent Calendar 2011 20日目】」
でした。図や動画もあって見やすいですね!
改めて自己紹介です。21日目を担当する、今回のカレンダーでNo.1カジュアルの座を狙っているid:oranie(オラニエ)です。
今回はMySQLもそこそこで、僕の名前の正しい読み方だけを覚えてくれれば今日は大丈夫です。
意図的に間違えている人もたまにいますが、心が汚れすぎていると思うのでお寺で座禅とかした方がいいと思います。
今までの記事を拝見させて頂き、みんな真面目に色々Tipsを書いているのでニッチ狙い&初心者の僕は
「MySQLに対して、カジュアルにやってはいけない事をやってみよう」がメインテーマです。
今回行うのは
「INSERT、UPDATE、DELETEなどゴリゴリ走っているMySQLにkill -9 を実行して壊してみよう」です。
まあ、こんなブログでわざわざ言われなくても、みんなは毎日カジュアルに壊していると思いますけどね!
以下の内容は全てInnoDBが前提となりますのでその旨宜しくお願いします。
環境はCentOS 5.6(64bit)+remiレポジトリを利用したmysql-server-5.5.19-1.el5.remiです。
configは、もちろんインストールしたまんまのカジュアルなDBです。
まず、こんな感じのDBを作ります。
CREATE TABLE `insert_table` ( `log_id` bigint(20) unsigned NOT NULL AUTO_INCREMENT, `1` varchar(255) DEFAULT NULL, `2` varchar(255) DEFAULT NULL, `3` varchar(255) DEFAULT NULL, PRIMARY KEY (`log_id`), KEY `1_idx` (`1`), KEY `2_idx` (`2`), KEY `3_idx` (`3`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8
インデックス全貼りや、カラム名が1〜3とかとてもカジュアルですよね!
※より壊れやすくしたいからで、いつもはやっていないですよ。
同じ物をUPDATE用、DELETE用を作っておきます。
カジュアルにCREATE TABLE hoge LIKE fuga;を使いました。
mysql> show tables; +------------------+ | Tables_in_casual | +------------------+ | delete_table | | insert_table | | update_table | +------------------+ 3 rows in set (0.00 sec) UPDATE用とDELETE用のテーブルには事前に mysql> SELECT * FROM update_table LIMIT 2; +--------+------+------+------+ | log_id | 1 | 2 | 3 | +--------+------+------+------+ | 1 | TEST | hoge | fuga | | 2 | TEST | hoge | fuga | +--------+------+------+------+
的な感じのテキトーなデータを100万件用意します。
突っ込んだ後に念のためmysqlcheckも実行します。
# mysqlcheck -a -u root -p casual Enter password: casual.delete_table OK casual.insert_table OK casual.update_table OK
大丈夫そうですね。
さあ準備は出来たので、こんな感じのカジュアル感たっぷりなスクリプトを利用して
INSERT、UPDATE、DELETE処理を手動並列でカジュアルに実行して、DBがゴリゴリ処理をしている最中に
# ps -eaf | grep mysql root 3500 1 0 19:53 pts/0 00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --socket=/var/lib/mysql/mysql.sock --pid-file=/var/run/mysqld/mysqld.pid --basedir=/usr --user=mysql mysql 3700 3500 16 19:53 pts/0 00:18:52 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock root 8110 7690 0 21:44 pts/1 00:00:00 mysql -u root -p casual root 8125 8079 0 21:45 pts/4 00:00:00 grep mysql # kill -9 3500 3700 # ps -eaf | grep mysql root 8128 8079 0 21:46 pts/4 00:00:00 grep mysql
を実行しました。ちゃんとmysqlプロセスが死んでいますね。
直後にログインしようとしても
# mysql -u root -p Enter password: ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/lib/mysql/mysql.sock' (111)
駄目ですね。
ログを確認しても
# cat /var/log/mysqld.log 111215 19:53:03 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql 111215 19:53:03 [Note] Plugin 'FEDERATED' is disabled. 111215 19:53:03 InnoDB: The InnoDB memory heap is disabled 111215 19:53:03 InnoDB: Mutexes and rw_locks use GCC atomic builtins 111215 19:53:03 InnoDB: Compressed tables use zlib 1.2.3 111215 19:53:03 InnoDB: Using Linux native AIO 111215 19:53:03 InnoDB: Initializing buffer pool, size = 128.0M 111215 19:53:03 InnoDB: Completed initialization of buffer pool InnoDB: The first specified data file ./ibdata1 did not exist: InnoDB: a new database to be created! 111215 19:53:03 InnoDB: Setting file ./ibdata1 size to 10 MB InnoDB: Database physically writes the file full: wait... 111215 19:53:03 InnoDB: Log file ./ib_logfile0 did not exist: new to be created InnoDB: Setting log file ./ib_logfile0 size to 5 MB InnoDB: Database physically writes the file full: wait... 111215 19:53:03 InnoDB: Log file ./ib_logfile1 did not exist: new to be created InnoDB: Setting log file ./ib_logfile1 size to 5 MB InnoDB: Database physically writes the file full: wait... InnoDB: Doublewrite buffer not found: creating new InnoDB: Doublewrite buffer created InnoDB: 127 rollback segment(s) active. InnoDB: Creating foreign key constraint system tables InnoDB: Foreign key constraint system tables created 111215 19:53:04 InnoDB: Waiting for the background threads to start 111215 19:53:05 InnoDB: 1.1.8 started; log sequence number 0 111215 19:53:05 [Note] Event Scheduler: Loaded 0 events 111215 19:53:05 [Note] /usr/libexec/mysqld: ready for connections. Version: '5.5.19' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server (GPL) by Remi
kill -9で稼働中にいきなり殺したので、ログが起動で終わってますね。
じゃあ、起動してみましょう。きっとなんらかのエラーで起動出来ない事でしょう。
こりゃーデータベース作り直しだわー!俺ぐらいのスーパーハカーだと分かるわー!
かーっ、きついなー!下手したら再インストールだわー!
徹夜かなー!俺昨日も実質2時間しか寝ていないわー!
# /etc/init.d/mysqld start mysqld を起動中: [ OK ]
あれ?出来た?(・ω・)
# ps -eaf root 8168 1 0 21:47 pts/1 00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --socket=/var/lib/mysql/mysql.sock --pid-file=/var/run/ mysql 8363 8168 28 21:47 pts/1 00:00:01 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql root 8401 7690 0 21:47 pts/1 00:00:00 ps -eaf
出来ていますね・・・。(・ω・)
入ってみましょう。
# mysql -u root -p casual Enter password: mysql> show tables; +------------------+ | Tables_in_casual | +------------------+ | delete_table | | insert_table | | update_table | +------------------+ 3 rows in set (0.00 sec)
普通に入れたのでmysqlcheckで確認してみましょう。
# mysqlcheck -a -u root -p casual Enter password: casual.delete_table OK casual.insert_table OK casual.update_table OK
問題無いですね。
ちなみにクライアント側でも、椅子を投げられないようにこんな感じのログを出していました。
2011-12-15 21:46:03 : DB execute OK! 32090 DBD::mysql::st execute failed: Lost connection to MySQL server during query at ./insert.pl line 40. sql execute error 接続が相手からリセットされました [32091]!! at ./insert.pl line 40.
最後に失敗したログが出ているので、ログに出力されている所までの処理状況をDBで確認すると
INSERT、UPDATE、DELETE共にスクリプトで最後に実行した所まで問題無く格納されていました。
一体何が起こったのでしょうか?
ではMySQLのログを見てみると、なんとカジュアルにリカバリ処理が実行されています。
cat /var/log/mysqld.log 〜一部割愛〜 111215 21:47:16 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql 111215 21:47:17 [Note] Plugin 'FEDERATED' is disabled. 111215 21:47:17 InnoDB: The InnoDB memory heap is disabled 111215 21:47:17 InnoDB: Mutexes and rw_locks use GCC atomic builtins 111215 21:47:17 InnoDB: Compressed tables use zlib 1.2.3 111215 21:47:17 InnoDB: Using Linux native AIO 111215 21:47:17 InnoDB: Initializing buffer pool, size = 128.0M 111215 21:47:17 InnoDB: Completed initialization of buffer pool 111215 21:47:17 InnoDB: highest supported file format is Barracuda. InnoDB: Log scan progressed past the checkpoint lsn 1888005832 111215 21:47:17 InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... InnoDB: Doing recovery: scanned up to log sequence number 1893248512 InnoDB: Doing recovery: scanned up to log sequence number 1893823631 InnoDB: 1 transaction(s) which must be rolled back or cleaned up InnoDB: in total 1 row operations to undo InnoDB: Trx id counter is 206300 111215 21:47:17 InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percents: 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 InnoDB: Apply batch completed InnoDB: Starting in background the rollback of uncommitted transactions 111215 21:47:18 InnoDB: Rolling back trx with id 2061AF, 1 rows to undo 111215 21:47:18 InnoDB: Waiting for the background threads to start InnoDB: Rolling back of trx id 2061AF completed 111215 21:47:18 InnoDB: Rollback of non-prepared transactions completed 111215 21:47:19 InnoDB: 1.1.8 started; log sequence number 1893823631 111215 21:47:19 [Note] Event Scheduler: Loaded 0 events 111215 21:47:19 [Note] /usr/libexec/mysqld: ready for connections. Version: '5.5.19' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server (GPL) by Remi
ざーっと要点を見ると
InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite
でinnodb_doublewriteによるクラッシュ対策により可能な限りのリカバリ処理が走り、
InnoDB: Doing recovery: scanned up to log sequence number 1893248512 InnoDB: Doing recovery: scanned up to log sequence number 1893823631 InnoDB: 1 transaction(s) which must be rolled back or cleaned up
でバイナリログからロールバック・綺麗にして無事DBがリカバリされているようです。
<追記>
上記は間違いでid:sh2さんから指摘を頂きました>< ありがとうございます!
Doing recoveryがリカバリの本体で、読んでいるのはバイナリログではなくてInnoDBログ。innodb_doublewriteはPartial Write対策で、kill -9程度ならOFFでも壊れないはず。doublewriteなしで壊れうるのはリアル電プチのとき http://bit.ly/q8SuDB
http://b.hatena.ne.jp/sh2/20111221#bookmark-72852109
詳細はこちら。(5.5は英訳のみなので、5.1のリファレンスですが)
http://dev.mysql.com/doc/refman/5.1/ja/innodb-parameters.html
innodb_doublewrite デフォルトで、InnoDB は全てのデータを2回格納します。 一回目は二重書き込み バッファに、そして次に実際のデータ ファイルに格納します。 この変数はデフォルトで有効化されています。それは、データの整合性や起こり得る失敗に対する心配よりも、 ベンチマークや最高性能が要求される時に、--skip-innodb_doublewrite を利用して止める事ができます。
こりゃ素晴らしい!
もう少し自動復旧処理の細かい内容はこちら。
InnoDB データベースのバックアップと復旧
チェックポイント
もしDB側に一部反映されていなくても、今回はログがあるので最悪自力でそこまで復旧できますね。
もし、このリカバリで直らなかったらどうするの?DB作り直しなの?死ぬの?となりますが、
Linuxのランレベル的な物がMySQLにもあり、復旧の強制という事も出来ます。
こんな感じでmy.cnfに書いて制限付きの起動をさせます。
[mysqld] innodb_force_recovery = 4
詳細はこちら。
InnoDB 復旧の強制
上記の内容に沿ってなんとか起動できたらdumpを取得し、再度DBを再作成出来れば全て作り直すよりは段違いですね。
という訳で、今回は僕がカジュアルに「pkill -9 mysql」とかで「間違えてDBいきなり落としちゃった☆彡」ってやっても
MySQLはそれを上回るカジュアルさでDBを守っているという結果でした。
余談としてこれは悩ましいことですが、INSERTやUPDATEなど書き込みが多いとその分二重書き込みのオーバーヘッドが
発生する訳です。但し、書き込みが多いほどこの機構で安全にする恩恵は大きい訳です。
@nippondanjiさんのブログでは、ZFSを利用することでファイルシステム側で書き込みの信頼性を
担保するという一例が書かれていますね。
http://nippondanji.blogspot.com/2010/01/mysqlinnodbzfs.html
そんな訳でTipsでもなんでも無いですが、今回のようにやってはいけない事をやっても
innodb_doublewrite等の機構によりMySQLが守ってくれるというお話でした。
明日は@k12uさんです。お楽しみに!