oranie's blog

旧:iをgに変えると・・・なんだっけ・・・

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さんです。お楽しみに!