Elena Stepanova added a comment - 2016-03-13 01:29 It turned out to be easy enough to reproduce by running the test with repeat: .... sys_vars.innodb_buffer_pool_load_now_basic 'innodb_plugin' [ pass ] 713 sys_vars.innodb_buffer_pool_load_now_basic 'innodb_plugin' [ pass ] 814 sys_vars.innodb_buffer_pool_load_now_basic 'innodb_plugin' [ pass ] 813 sys_vars.innodb_buffer_pool_load_now_basic 'innodb_plugin' [ fail ] Test ended at 2016-03-12 20:10:07   CURRENT_TEST: sys_vars.innodb_buffer_pool_load_now_basic --- /bld/10.0-release/mysql-test/suite/sys_vars/r/innodb_buffer_pool_load_now_basic.result 2016-01-17 10:16:40.000000000 -0500 +++ /bld/10.0-release/mysql-test/suite/sys_vars/r/innodb_buffer_pool_load_now_basic.reject 2016-03-12 20:10:07.434489216 -0500 @@ -3,6 +3,12 @@ @orig 0 SET GLOBAL innodb_buffer_pool_dump_now = ON; +Timeout in wait_condition.inc for SELECT variable_value != 'Buffer pool(s) dump completed at 160312 20:09:36' + 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 +79 root localhost test Query 0 init show full processlist 0.000 SET GLOBAL innodb_buffer_pool_load_now = ON; SELECT variable_value FROM information_schema.global_status Here is what we have in the error log: ... CURRENT_TEST: sys_vars.innodb_buffer_pool_load_now_basic 2016-03-12 20:09:35 7fd8705fb700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool 2016-03-12 20:09:35 7fd8705fb700 InnoDB: Buffer pool(s) dump completed at 160312 20:09:35 2016-03-12 20:09:35 7fd8705fb700 InnoDB: Loading buffer pool(s) from .//ib_buffer_pool 2016-03-12 20:09:35 7fd8705fb700 InnoDB: Buffer pool(s) load completed at 160312 20:09:35 CURRENT_TEST: sys_vars.innodb_buffer_pool_load_now_basic 2016-03-12 20:09:36 7fd8705fb700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool 2016-03-12 20:09:36 7fd8705fb700 InnoDB: Buffer pool(s) dump completed at 160312 20:09:36 2016-03-12 20:09:36 7fd8705fb700 InnoDB: Loading buffer pool(s) from .//ib_buffer_pool 2016-03-12 20:09:36 7fd8705fb700 InnoDB: Buffer pool(s) load completed at 160312 20:09:36 CURRENT_TEST: sys_vars.innodb_buffer_pool_load_now_basic 2016-03-12 20:09:36 7fd8705fb700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool 2016-03-12 20:09:36 7fd8705fb700 InnoDB: Buffer pool(s) dump completed at 160312 20:09:36 2016-03-12 20:10:07 7fd8705fb700 InnoDB: Loading buffer pool(s) from .//ib_buffer_pool 2016-03-12 20:10:07 7fd8705fb700 InnoDB: Buffer pool(s) load completed at 160312 20:10:07 That is, the last test says the dump was performed on the same second as the previous one. But here is what we have in the general log: 79 Query SELECT TRIM(SUBSTR('Buffer pool(s) dump completed at 160312 20:09:36', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s') 79 Query SELECT TRIM(SUBSTR('Buffer pool(s) dump completed at 160312 20:09:36', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s') 79 Query SELECT TRIM(SUBSTR('Buffer pool(s) dump completed at 160312 20:09:36', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s') 79 Query SELECT TRIM(SUBSTR('Buffer pool(s) dump completed at 160312 20:09:36', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s') 79 Query SELECT TRIM(SUBSTR('Buffer pool(s) dump completed at 160312 20:09:36', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s') 79 Query SELECT TRIM(SUBSTR('Buffer pool(s) dump completed at 160312 20:09:36', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s') 79 Query SELECT TRIM(SUBSTR('Buffer pool(s) dump completed at 160312 20:09:36', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s') 160312 20:09:37 79 Query SELECT TRIM(SUBSTR('Buffer pool(s) dump completed at 160312 20:09:36', -8)) != DATE_FORMAT(CURTIME(), '%k:%i:%s') 79 Query SET GLOBAL innodb_buffer_pool_dump_now = ON 79 Query SELECT variable_value != 'Buffer pool(s) dump completed at 160312 20:09:36' AND SUBSTR(variable_value, 1, 33) = 'Buffer pool(s) dump completed at ' FROM information_schema.global_status So, the waiting on the current time worked perfectly – the test did wait till CURTIME switched to the next second, only only then, at 20:09:37, the dump was performed. However, InnoDB still wrote its records to the error log with the older timestamp, and used the same for the variable value. Further failure is caused by this inconsistency. Thinking about it, it's no news that InnoDB has its own understanding of time, but I didn't know it would affect seconds . I don't know if it's a bug, maybe it is, but it's so tiny that I doubt anybody would care fixing it. Just for accuracy, lets ask jplindst : see the explanation above – do you want to look into why InnoDB would use different time comparing to the server? If not, I'll think of some other way to fix the test. sleep 1 also does not help here, it can hit the same problem; maybe longer sleeps could do the trick, but then again, if InnoDB can be 1 second late, maybe it can be 10 seconds late? On a separate note, while running the test repeatedly I found out that the final part of the test, the LOAD part, also does not work properly, on a similar reason to what we had here initially: if the status variable was previously set, the last SELECT from I_S can happen too early and show an unexpected value. I'll fix it along with re-fixing the current issue.

Jan Lindström (Inactive) added a comment - 2016-03-14 08:13 I think this is because InnoDB log is written first and then (when stmt completed ?) to general log, if we are near to end of second it could mean that there looks like there is a second difference. Both logs should have more accuracy on timestamps.

Elena Stepanova added a comment - 2016-03-14 08:28 - edited jplindst , I don't think it can be so. First, statements are written to the general log before they are executed, otherwise we would never have crashing queries in general logs, and we always do. But more importantly, even the previous statement, the last SELECT TRIM , is also written with the newer timestamp. Now, it cannot possibly be explained by InnoDB writing its log before the SET statement was written to the general log. By this time, InnoDB knew nothing about future request for the dump.

Elena Stepanova added a comment - 2016-03-29 13:18 As discussed with jplindst , the reason of the issue with InnoDB timestamps is currently unknown, so I will change the test not to fail due to it, and instead will file a bug about the timestamp problem.

Elena Stepanova added a comment - 2016-04-04 14:22 The InnoDB timestamp issue filed as MDEV-9867 , the wait condition has been replaced with a conditional sleep. https://github.com/MariaDB/server/commit/f8adeccd78bff80725a95b73447e34a5f4528179