Details
-
Bug
-
Status: Closed (View Workflow)
-
Trivial
-
Resolution: Won't Fix
-
10.0(EOL), 10.1(EOL)
-
None
Description
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 |
Attachments
Issue Links
- relates to
-
-
- Closed
-