Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-9867

InnoDB can be a second behind the server

    XMLWordPrintable

Details

    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

          Activity

            People

              jplindst Jan Lindström (Inactive)
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.