information_schema.INNODB_BUFFER_PAGEのACCESS_TIMEが何か変な件

取り敢えずBugsにも上げたんですけど、エスパーさんでないと伝わらない気がしています。

http://bugs.mysql.com/bug.php?id=68981


MySQL 5.6.2, 5.5.28, 5.1.66に搭載された新しいinformation_schema、INNODB_BUFFER_PAGEとINNODB_BUFFER_PAGE_LRU。
⇒ http://yoku0825.blogspot.jp/2013/02/informationschemainnodbbufferpage.html

これの中身をちょこちょこ確認していたところ、どうにも`ACCESS_TIME`が納得のいく値にならないことに気付いた。

mysql56> DESC INNODB_BUFFER_PAGE;
+---------------------+---------------------+------+-----+---------+-------+
| Field               | Type                | Null | Key | Default | Extra |
+---------------------+---------------------+------+-----+---------+-------+
| POOL_ID             | bigint(21) unsigned | NO   |     | 0       |       |
| BLOCK_ID            | bigint(21) unsigned | NO   |     | 0       |       |
| SPACE               | bigint(21) unsigned | NO   |     | 0       |       |
| PAGE_NUMBER         | bigint(21) unsigned | NO   |     | 0       |       |
| PAGE_TYPE           | varchar(64)         | YES  |     | NULL    |       |
| FLUSH_TYPE          | bigint(21) unsigned | NO   |     | 0       |       |
| FIX_COUNT           | bigint(21) unsigned | NO   |     | 0       |       |
| IS_HASHED           | varchar(3)          | YES  |     | NULL    |       |
| NEWEST_MODIFICATION | bigint(21) unsigned | NO   |     | 0       |       |
| OLDEST_MODIFICATION | bigint(21) unsigned | NO   |     | 0       |       |
| ACCESS_TIME         | bigint(21) unsigned | NO   |     | 0       |       |
| TABLE_NAME          | varchar(1024)       | YES  |     | NULL    |       |
| INDEX_NAME          | varchar(1024)       | YES  |     | NULL    |       |
| NUMBER_RECORDS      | bigint(21) unsigned | NO   |     | 0       |       |
| DATA_SIZE           | bigint(21) unsigned | NO   |     | 0       |       |
| COMPRESSED_SIZE     | bigint(21) unsigned | NO   |     | 0       |       |
| PAGE_STATE          | varchar(64)         | YES  |     | NULL    |       |
| IO_FIX              | varchar(64)         | YES  |     | NULL    |       |
| IS_OLD              | varchar(3)          | YES  |     | NULL    |       |
| FREE_PAGE_CLOCK     | bigint(21) unsigned | NO   |     | 0       |       |
+---------------------+---------------------+------+-----+---------+-------+
20 rows in set (0.00 sec)



mysql56> SELECT TABLE_NAME, INDEX_NAME, ACCESS_TIME FROM INNODB_BUFFER_PAGE WHERE TABLE_NAME = '`d4`.`t1`';
+------------+------------+-------------+
| TABLE_NAME | INDEX_NAME | ACCESS_TIME |
+------------+------------+-------------+
| `d4`.`t1`  | num        |   386123651 |
+------------+------------+-------------+
1 row in set (0.02 sec)

UNIXTIMEとしては桁が1個おかしい。
NEWEST_MODIFICATION, OLDEST_MODIFICATIONはLSNが記載されるんだけど、それでもない。
EPOCH(1970/01/01 00:00:00)からの経過秒数じゃなくて起動してからの秒数かなとか思っても、
やっぱり計算が全然合わない。

取り敢えず、storage/innobase/handler/i_s.ccなんてあつらえ向きのものがあるので探してみる。
そこからコソコソたどっていくと、storage/innobase/include/buf0buf.icの中で
bpage->access_time = ut_time_ms(); とやっているのを発見。

ut_time_ms()は現在時刻をミリ秒単位でunsigned longで返す関数らしい(storage/innobase/ut/ut0ut.cc)ので、
ページを読み込んだタイミングのUNIXTIME * 1000くらいの値になりそうなもんだが、
ただでさえ桁がおかしいのに更に計算が合わなくなる。

( ´-｀).oO（ここで3日くらい悩んだ）

まあステップ実行かな！ とgdbを仕掛けて、i_sにアクセスするところでブレーク。

Breakpoint 3, i_s_innodb_buffer_page_get_info (bpage=0x7f04aa1c3000, pool_id=0, pos=0, page_info=0x7f0484076f78)
    at /home/yoku0825/mysql-5.6.10/storage/innobase/handler/i_s.cc:5076
5076    {

 (gdb) p *bpage
$4 = {space = 261, offset = 240, state = 3, flush_type = 0, io_fix = 0, buf_fix_count = 0, buf_pool_index = 0, zip = {
    data = 0x0, m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 0}, hash = 0x0, list = {prev = 0x7f04aa1c3180,
    next = 0x7f04aa1eaf00}, newest_modification = 0, oldest_modification = 0, LRU = {prev = 0x7f04aa1c3180, next = 0x0},
  old = 1, freed_page_clock = 1507, access_time = 41213048}

 
(gdb) p ut_time_ms()
$2 = 1366183980583

ｳｪｰｲ、この時点でaccess_timeは変な値になってるし、ut_time_ms()はちゃんとUNIXTIME * 1000ぽいスケールの戻り値。。

なんでそう思ったのかよく判らないけれど、何故かaccess_timeの型を調べる気になって叩いてみると、

(gdb) whatis bpage->access_time
type = unsigned int

unsigned int…32bit INTかYO!!

mysql56> create table d4.t1 ( num serial ); select unix_timestamp(now(3)), (unix_timestamp(now(3)) * 1000) & ( pow(2, 32) - 1);
Query OK, 0 rows affected (0.04 sec)

 +------------------------+-----------------------------------------------------+
| unix_timestamp(now(3)) | (unix_timestamp(now(3)) * 1000) & ( pow(2, 32) - 1) |
+------------------------+-----------------------------------------------------+
|         1366185723.810 |                                           386123682 |
+------------------------+-----------------------------------------------------+
1 row in set (0.01 sec)

 mysql56> SELECT TABLE_NAME, INDEX_NAME, ACCESS_TIME FROM INNODB_BUFFER_PAGE WHERE TABLE_NAME = '`d4`.`t1`';
+------------+------------+-------------+
| TABLE_NAME | INDEX_NAME | ACCESS_TIME |
+------------+------------+-------------+
| `d4`.`t1`  | num        |   386123651 |
+------------+------------+-------------+
1 row in set (0.02 sec)

現在のUNIXTIME（5.6なのでミリ秒まで取れるのだ） * 1000の下32bitだけ取り出すと、おお、大体合う。
あとからよく見てみると、あっちゃこっちゃで unsigned access_time で定義されているのを見つける。

あー、すっきり。
でも英語下手すぎてだめぽ。。