ファイルシステムと違い、fail toleranceを重視し、実現するためにデータベースが色々な複雑なことをやっています。今回ではMysqlのログ機能を使って、RDBMSの動作を考察してみたいと思います。

InnoDBのデータの書き込み方法

InnoDBはストレージエンジンであり、優れたトランザクション機能を持っています。Mysql 5.7のデフォルトストレージエンジンです。
ユーザー(DBA)からSQL(データベース言語)を受け取ったら、直接にハードディスクにあるデータを操作（デリート、アップデートなどのオペレーション）するではなく、メモリー上操作を記録し、データを取り込み、操作してからハードディスクに書き込みます。データ操作のロジックフローは以下となります。

SQLをパーシングします
操作対象となるデータページ単位でメモリー上のBuffer Poolに呼び出します
データに操作を行い、そのページがDirty Pageになります
Redo Logに操作と操作対象テーターなど情報を書きます
Redo Logをハードディスクに書き込みます
Dirty Pageを（ハードディスクにある）Double Write Bufferに書き込みます。
Double Write BufferにあるDirty Pageをハードディスクのページが元ある場所に書き戻します。

ここに幾つポイントがあります：
- Redo Logはとても重要です。システムクラッシュ、パワーダウンなどによりデータが破損する時、初期状態のデータに操作を再現(Redo)するためのログです。
- Redo LogはまずBuffer Poolに書き込まれますが、あとでハードディスクに書き込まれます（Double Write Bufferを経由しません）、Dirty Pageの書き込みよりは前です。
- いつなったらハードディスクにRedo Logを書きますか？
　A:設定(innodb_flush_log_at_trx_commit)とハードウェアによりますバックグラウンドスレッドをバリバリ働かせて１秒に一回書かせるは可能です。(一回で書ききれない場合は実際に多くあります、実装上write queueを使って少しずつ書き込みます)

以上の書き込み方法を使って、InnoDBがfail toleranceを実現しています。なので、Redo Logを読めばこの方法を解読できると思います。

Redo Logに関して

MysqlのRedo Log（ハードディスク上）はサイクリングバッファ形式で実装されています。溜まったら参照されていないログのスペースが解放され、新しいログを入れられるようになります。もしスペースに空きがなく、新しいログを書けなくなったらデータベースは動けなくなり待ち続けます。Redo LogにはLSN(Log Sequence Number)を持っています、新しいRedo Logほど大きいLSNを持っています。データベースエンジンがLSNの小さいLogから参照されていないログを探し、使われていたスペースを解放します。

LSNをみて見る

ここでrootユーザー権限でmysql clientに入り、InnoDBのstatus(状態)をみてみましょう

show engine innodb status \G

ログとBuffer Pool関連情報をみて見ると

---
LOG
---
Log sequence number 9542414
Log flushed up to   9542414
Pages flushed up to 9542414
Last checkpoint at  9542405
0 pending log flushes, 0 pending chkp writes
10 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137428992
Dictionary memory allocated 290846
Buffer pool size   8192
Free buffers       7802
Database pages     390
Old database pages 0
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 355, created 35, written 37
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 390, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]

ここで現在のInnoDBのBuffer Poolのサイズなど情報がみれます。LOGのセッションをみて見ると、現在最新のRedo LogのLSNは9542414であり、そして最新のログまで全部ハードディスクに書き込み済み(flush)です。また、各データページのヘッダーにはそのページの一番古い操作のRedo LogのLSNを持っています。Pages flushed up to 9542414は最新の操作を受けたデータページもハードディスクに書き戻しましたという意味です。Inno db はfussy checkpointを実装してます、詳しくはこちら
ここで色々テーター操作を行いましょう

CREATE DATABASE newdummy;
USE newdumy;
CREATE TABLE a_table( t_id INT);
INSET INTO a_table (t_id) VALUES(100);

すぐInnoDBのstutasをみてみましょう：

---
LOG
---
Log sequence number 9547307
Log flushed up to   9547307
Pages flushed up to 9547307
Last checkpoint at  9547298
0 pending log flushes, 0 pending chkp writes
24 log i/o's done, 0.00 log i/o's/second

LSNがたくさん増えました。

binlogをみて見る

Mysqlのデータ(tablespace)はdatadirに置いてあります、まずこのパスを出します

show variables like 'datadir';
+---------------+-----------------------+
| Variable_name | Value                 |
+---------------+-----------------------+
| datadir       | /usr/local/var/mysql/ |
+---------------+-----------------------+
1 row in set (0.00 sec)

中にRedo Logが入ってたib_logfile0とib_logfile1というファイルがありますが、直接には見れません。ここでは代わりbinlogの中身をみます。もともとbinlogはレプリケーションのためのログです。つまり中にはRedo Logと同じくデータベースへの操作に関連する情報があります。そしてmysqlbinlogで中身をみれます。
binlogはデフォルトオフにされています。まずセッティングファイルを変更し、binlog機能をオンにします。

my.cnf

...
bind-address = 127.0.0.1
log-bin=mysql-bin
server-id=master-01

上記の設定を入れ、mysql serverをrestartさせます

mysqld restart

これでbinlogが有効になり、mysql-bin.index、mysql-bin.000001などbinlogファイルが作成されます。（実は最初からbinlogを有効にしたので）先ほどの操作のbinlogみてみると

mysqlbinlog mysql-bin.000001

出力（部分）

# at 686
#170721 18:10:18 server id 0  end_log_pos 751 CRC32 0x488e1bbe  Anonymous_GTID  last_committed=3        sequence_number=4
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 751
#170721 18:10:18 server id 0  end_log_pos 857 CRC32 0x3b7294ee  Query   thread_id=3     exec_time=0     error_code=0
SET TIMESTAMP=1500628218/*!*/;
create database newdummy
/*!*/;
# at 857
#170721 18:11:44 server id 0  end_log_pos 922 CRC32 0x59155156  Anonymous_GTID  last_committed=4        sequence_number=5
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 922
#170721 18:11:44 server id 0  end_log_pos 1035 CRC32 0xb1f9c254         Query   thread_id=3     exec_time=0     error_code=0
use `newdummy`/*!*/;
SET TIMESTAMP=1500628304/*!*/;
create table a_table(t_id int )
/*!*/;
# at 1035
#170721 18:14:20 server id 0  end_log_pos 1100 CRC32 0x1d6f15f2         Anonymous_GTID  last_committed=5        sequence_number=6
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1100
#170721 18:14:20 server id 0  end_log_pos 1176 CRC32 0x21dd0434         Query   thread_id=3     exec_time=0     error_code=0
SET TIMESTAMP=1500628460/*!*/;
BEGIN
/*!*/;
# at 1176
#170721 18:14:20 server id 0  end_log_pos 1230 CRC32 0xe42983fc         Table_map: `newdummy`.`a_table` mapped to number 304
# at 1230
#170721 18:14:20 server id 0  end_log_pos 1270 CRC32 0x5c080f8e         Write_rows: table id 304 flags: STMT_END_F

BINLOG '
7MVxWRMAAAAANgAAAM4EAAAAADABAAAAAAEACG5ld2R1bW15AAdhX3RhYmxlAAEDAAH8gynk
7MVxWR4AAAAAKAAAAPYEAAAAADABAAAAAAEAAgAB//5kAAAAjg8IXA==
'/*!*/;
# at 1270
#170721 18:14:20 server id 0  end_log_pos 1301 CRC32 0x5f7dd845         Xid = 29
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file

これでエンジンのハイレベルな動きが見れるようになります。

One Last Thing

InnoDBのケースを説明しているわけではありませんが、一般的なデータベースのRedo LoggingとRecoveryはこれを読むと色々勉強できます。

MysqlのInnoDBエンジンにおけるデータ操作考察

InnoDBのデータの書き込み方法

Redo Logに関して

LSNをみて見る

binlogをみて見る

One Last Thing