[#MDEV-9867] InnoDB can be a second behind the server

It is just a tiny nuisance, but since we discussed it, and since it affects the test which I need to change to avoid it (~~MDEV-9713~~), I'm extracting the problem into a separate JIRA entry.

Sometimes InnoDB can use a timestamp which is behind the time in the server (1 second behind, I didn't get it to differ more). The test below demonstrates it.

The test repeatedly sets innodb_buffer_pool_dump_now to ON; then it waits while the value of the status variable innodb_buffer_pool_dump_status changes; then it waits when the next second in the server starts, and does it all over again.

So, the innodb_buffer_pool_dump_now is always set at a new second, there cannot be two dumps at the same time. However, at some point InnoDB reports that the dump was completed on the previous second. All of this can be seen in the test output.
This is how two normal consequent cycles look:

-------------------------------------------------

Starting the dump at

2016-04-04 15:37:47.005442

Variable_name   Value

Innodb_buffer_pool_dump_status  Buffer pool(s) dump completed at 160404 15:37:47

Variable_name   Value

Com_set_option  18

-------------------------------------------------

Starting the dump at

2016-04-04 15:37:48.039787

Variable_name   Value

Innodb_buffer_pool_dump_status  Buffer pool(s) dump completed at 160404 15:37:48

Variable_name   Value

Com_set_option  19

And here is how the failed cycle looks:

-------------------------------------------------

Starting the dump at

2016-04-04 15:37:49.072215

Variable_name   Value

Innodb_buffer_pool_dump_status  Buffer pool(s) dump completed at 160404 15:37:49

Variable_name   Value

Com_set_option  20

-------------------------------------------------

Starting the dump at

2016-04-04 15:37:50.000915

Timeout in wait_condition.inc for SELECT variable_value != 'Buffer pool(s) dump completed at 160404 15:37:49'

         AND SUBSTR(variable_value, 1, 33) = 'Buffer pool(s) dump completed at '

      FROM information_schema.global_status

WHERE LOWER(variable_name) = 'innodb_buffer_pool_dump_status'

Id      User    Host    db      Command Time    State   Info    Progress

3       root    localhost       test    Query   0       init    show full processlist   0.000

Variable_name   Value

Innodb_buffer_pool_dump_status  Buffer pool(s) dump completed at 160404 15:37:49

Variable_name   Value

Com_set_option  21

####### ERROR: ######################################################################

# We hit the error - the timestamps in the status variable is less than it should be.

# See the output above, note that the timestamp in the variable is less than

# the timestamp was on the server BEFORE we sent the command.

# Also, see the error log below which shows that InnoDB indeed reported two dumps

# in one second.

#####################################################################################

2016-04-04 15:37:46 7fa2b7dfe700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool

2016-04-04 15:37:46 7fa2b7dfe700 InnoDB: Buffer pool(s) dump completed at 160404 15:37:46

2016-04-04 15:37:47 7fa2b7dfe700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool

2016-04-04 15:37:47 7fa2b7dfe700 InnoDB: Buffer pool(s) dump completed at 160404 15:37:47

2016-04-04 15:37:48 7fa2b7dfe700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool

2016-04-04 15:37:48 7fa2b7dfe700 InnoDB: Buffer pool(s) dump completed at 160404 15:37:48

2016-04-04 15:37:49 7fa2b7dfe700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool

2016-04-04 15:37:49 7fa2b7dfe700 InnoDB: Buffer pool(s) dump completed at 160404 15:37:49

2016-04-04 15:37:49 7fa2b7dfe700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool

2016-04-04 15:37:49 7fa2b7dfe700 InnoDB: Buffer pool(s) dump completed at 160404 15:37:49

test case
-- source include/have_innodb.inc

-- let $run=100

# It does not flush innodb_buffer_pool_dump_status, but should flush com_set_option, which we'll also check
FLUSH STATUS;
while ($run)
{
-- echo -------------------------------------------------
let $old_status= `SELECT variable_value FROM information_schema.global_status
WHERE LOWER(variable_name) = 'innodb_buffer_pool_dump_status'`;

# A previous test could have run buffer pool dump already;
# in this case we want to make sure that the current time is different
# from the timestamp in the status variable

let $wait_condition =
SELECT TRIM(SUBSTR('$old_status', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s');
-- source include/wait_condition.inc

-- disable_query_log
# Do the dump
SELECT NOW(6) AS `Starting the dump at`;
SET GLOBAL innodb_buffer_pool_dump_now = ON;

# Wait for the dump to complete
let $wait_condition =
SELECT variable_value != '$old_status'
AND SUBSTR(variable_value, 1, 33) = 'Buffer pool(s) dump completed at '
FROM information_schema.global_status
WHERE LOWER(variable_name) = 'innodb_buffer_pool_dump_status';
-- source include/wait_condition.inc
-- disable_query_log
SHOW STATUS LIKE 'innodb_buffer_pool_dump_status';
SHOW STATUS LIKE 'Com_set_option';
if (`SELECT variable_value = '$old_status' FROM information_schema.global_status WHERE LOWER(variable_name) = 'innodb_buffer_pool_dump_status'`)
{
-- echo ####### ERROR: ######################################################################
-- echo # We hit the error - the timestamps in the status variable is less than it should be.
-- echo # See the output above, note that the timestamp in the variable is less than
-- echo # the timestamp was on the server BEFORE we sent the command.
-- echo # Also, see the error log below which shows that InnoDB indeed reported two dumps
-- echo # in one second.
-- echo #####################################################################################
-- exec tail $MYSQLTEST_VARDIR/log/mysqld.1.err
-- die
}
--dec $run
}
--enable_query_log

[MDEV-9867] InnoDB can be a second behind the server Created: 2016-04-04 Updated: 2023-04-12 Resolved: 2023-04-11
Status:	Closed
Project:	MariaDB Server
Component/s:	Storage Engine - InnoDB
Affects Version/s:	10.0, 10.1
Fix Version/s:	N/A

[MDEV-9867] InnoDB can be a second behind the server Created: 2016-04-04 Updated: 2023-04-12 Resolved: 2023-04-11