MySQL Bugs: #68981: bpage->access

Bug #68981	bpage->access_time is unsigned int
Submitted:	17 Apr 2013 7:29	Modified:	3 Jul 2013 16:07
Reporter:	Tsubasa Tanaka (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.5.30, 5.6.10	OS:	Any
Assigned to:	Paul DuBois	CPU Architecture:	Any

Description:
`ACCESS_TIME` in information_schema.INNODB_BUFFER_PAGE displays strange value like this.

mysql55> show status like 'uptime';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Uptime        | 22    |
+---------------+-------+
1 row in set (0.01 sec)

mysql55> SELECT ACCESS_TIME, NOW(), UNIX_TIMESTAMP() FROM INNODB_BUFFER_PAGE LIMIT 1;
+-------------+---------------------+------------------+
| ACCESS_TIME | NOW()               | UNIX_TIMESTAMP() |
+-------------+---------------------+------------------+
|   382741389 | 2013-04-17 16:06:18 |       1366182378 |
+-------------+---------------------+------------------+
1 row in set (0.01 sec)

This seems bpage->access_time's overflow.

It is setted ut_time_ms(), millisecond from epoch, in buf_page_is_accessed() in storage/innobase/include/buf0buf.ic.
But it is defiend as unsigned 32bits int in buf_page_struct in storage/innobase/include/buf0buf.h.

Is purpose of `ACCESS_TIME` "only context between each pages"?
(If so, this is "Not a Bug")

How to repeat:
See Description.

Breakpoint 3, i_s_innodb_buffer_page_get_info (bpage=0x7f04aa1c3000, pool_id=0, pos=0, page_info=0x7f0484076f78)
    at /home/ttanaka/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) whatis bpage->access_time
type = unsigned int

(gdb) p ut_time_ms()
$2 = 1366183980583

1366183980583 is greater than 2^32.

mysql56> SELECT TABLE_NAME, INDEX_NAME, ACCESS_TIME FROM INNODB_BUFFER_PAGE WHERE TABLE_NAME = '`d4`.`t1`';
Empty set (0.02 sec)

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)

Verified with code inspection. If one were to trust comments:

unsigned	access_time;	/*!< time of first access, or
				0 if the block was never accessed
				in the buffer pool. Protected by
				block mutex */

So it really is supposed to give the date/time of first access only, or 0 otherwise. Updating is only done within buf_page_set_accessed(), and only "if (!bpage->access_time)"

Given the overflow, I question whether the old/young LRU management is functioning correctly in buf_page_peek_if_too_old():

		if (access_time > 0
		    && ((ib_uint32_t) (ut_time_ms() - access_time))
		    >= buf_LRU_old_threshold_ms) {
			return(TRUE);
		}

Hello,

buf_page_t::access_time is expected to wrap around. It is measured in milliseconds since epoch and is stored in 32 bit unsigned integer.

The documentation http://dev.mysql.com/doc/refman/5.6/en/innodb-buffer-page-table.html says "Time of first access" which is misleading - the exact specification is "The least significant 32 bits from the number of milliseconds since epoch of the first access". If that is too cryptic, the doc should say "an abstract number used to judge the first access time".

About the check in buf_page_peek_if_too_old() (notice that ut_time_ms() returns ulint which is 64 bit on 64 bit systems (no wrap) and 32 bit on 32 bit systems (will wrap)):

 179                 unsigned        access_time = buf_page_is_accessed(bpage);
 180 
 181                 if (access_time > 0
 182                     && ((ib_uint32_t) (ut_time_ms() - access_time))
 183                     >= buf_LRU_old_threshold_ms) {
 184                         return(TRUE);
 185                 }

In either 64 or 32 bit systems it works correctly most of the time. But there is an edge case where it would fail to provide the expected result. The thing is that 2^32 milliseconds pass in about 50 days. So if the difference between ut_time_ms() and access_time is more than 50 days, then it will not work correctly.

Here is an example:

(gdb) p (unsigned)(1372832535000 - (unsigned)1368537567000)
$1 = 704

In this case it would assume that the page was first accessed 0.704 seconds ago, but:

1368537567000 milliseconds since epoch correspond to Tue May 14 13:19:27 UTC 2013 and
1372832535000 milliseconds since epoch correspond to Wed Jul  3 06:22:15 UTC 2013, i.e. the page was first accessed about 50 days ago.

It is not worth increasing the size of buf_page_t with 32 bits (change access_time from 32 bit to 64 bit) in order to fix the issue with buf_page_peek_if_too_old() misbehaving for some 50+ days old pages. It could sometimes wrongly return FALSE when it should return TRUE - if the page's age is in the interval [50 days, 50 days + buf_LRU_old_threshold_ms).

The documentation at http://dev.mysql.com/doc/refman/5.6/en/innodb-buffer-page-table.html should be changed from "Time of first access" to "An abstract number used to judge the first access time of the page".

reminds me of http://bugs.mysql.com/bug.php?id=52111

Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly, and will be included in the next release of the relevant products.