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

Define a reasonable upper limit for innodb_spin_wait_delay

Details

    Description

      To reproduce:

      • start the server on a clean datadir with --innodb_write_io_threads=30 --innodb_spin_wait_delay=1647236602 --innodb-read-only
      • run mysql -e shutdown

      It takes a while (~1.5 min on my machine), but eventually it fails with

      10.2 f2fe65106f

      2016-12-30 20:44:17 140353941136128 [Note] InnoDB: Starting shutdown...
      2016-12-30 20:45:57 140353941136128 [Warning] InnoDB: 1 threads created by InnoDB had not exited at shutdown!
      Pending normal aio reads: 0
      Pending normal aio writes: 0
      Pending sync i/o's: 0
      2016-12-30 20:45:57 0x7fa6b2cde300  InnoDB: Assertion failure in thread 140353941136128 in file srv0start.cc line 1305
      InnoDB: Failing assertion: 0
      InnoDB: We intentionally generate a memory trap.
       
      #6  0x00007fa6b2370995 in ut_dbg_assertion_failed (expr=0x7fa6b28a09f4 "0", file=0x7fa6b28a0ee8 "/data/src/10.2/storage/innobase/srv/srv0start.cc", line=1305) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:67
      #7  0x00007fa6b230fe69 in srv_shutdown_all_bg_threads () at /data/src/10.2/storage/innobase/srv/srv0start.cc:1305
      #8  0x00007fa6b2313c82 in innobase_shutdown_for_mysql () at /data/src/10.2/storage/innobase/srv/srv0start.cc:2811
      #9  0x00007fa6b213fd0e in innobase_end (hton=0x7fa6ae8130f0, type=HA_PANIC_CLOSE) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:4862
      #10 0x00007fa6b1f00c1f in ha_finalize_handlerton (plugin=0x7fa6aeafc7f8) at /data/src/10.2/sql/handler.cc:451
      #11 0x00007fa6b1cb035a in plugin_deinitialize (plugin=0x7fa6aeafc7f8, ref_check=true) at /data/src/10.2/sql/sql_plugin.cc:1217
      #12 0x00007fa6b1cb07c0 in reap_plugins () at /data/src/10.2/sql/sql_plugin.cc:1294
      #13 0x00007fa6b1cb273f in plugin_shutdown () at /data/src/10.2/sql/sql_plugin.cc:1945
      #14 0x00007fa6b1bb9dc0 in clean_up (print_message=true) at /data/src/10.2/sql/mysqld.cc:2201
      #15 0x00007fa6b1bb9921 in unireg_end () at /data/src/10.2/sql/mysqld.cc:2076
      #16 0x00007fa6b1bb981e in kill_server (sig_ptr=0x0) at /data/src/10.2/sql/mysqld.cc:2003
      #17 0x00007fa6b1bb9860 in kill_server_thread (arg=0x7fa6b2dbba10) at /data/src/10.2/sql/mysqld.cc:2026
      #18 0x00007fa6b12c60a4 in start_thread (arg=0x7fa6b2cde300) at pthread_create.c:309
      #19 0x00007fa6af27387d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
      

      Not reproducible on 10.0, 10.1, MySQL 5.6, MySQL 5.7.
      10.0, 10.1 and MySQL 5.7 does shut down immediately.
      For MySQL 5.7 it takes long to shut down, but eventually it happens normally:

      2016-12-30T17:11:34.340405Z 0 [Note] InnoDB: Starting shutdown...
      2016-12-30T17:12:34.676760Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2016-12-30T17:13:34.813170Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2016-12-30T17:14:34.949136Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2016-12-30T17:15:35.085153Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2016-12-30T17:16:35.221218Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2016-12-30T17:17:35.361830Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2016-12-30T17:18:35.497375Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2016-12-30T17:19:35.633573Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2016-12-30T17:20:08.099067Z 0 [Note] InnoDB: Shutdown completed; log sequence number 1455166
      2016-12-30T17:20:08.101920Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      2016-12-30T17:20:08.103314Z 0 [Note] /data/bld/mysql-5.7/bin/mysqld: Shutdown complete
      

      Attachments

        Issue Links

          Activity

            For me, it already hangs at startup in SysTablespace::open_or_create() on mutex_enter(&fil_system->mutex), conflicting with fil_validate() from an io_handler_thread.
            I think that there should be a reasonable upper limit to innodb_spin_wait_delay. It just does not make any sense to invoke ut_delay() with insanely large values.
            I will try a bit more to repeat the reported scenario.

            marko Marko Mäkelä added a comment - For me, it already hangs at startup in SysTablespace::open_or_create() on mutex_enter(&fil_system->mutex), conflicting with fil_validate() from an io_handler_thread. I think that there should be a reasonable upper limit to innodb_spin_wait_delay. It just does not make any sense to invoke ut_delay() with insanely large values. I will try a bit more to repeat the reported scenario.

            I cannot repeat the hang as described, but it could be a timing issue. I think that we only need a conflict on some mutex (fil_system->mutex is a good candidate), and then the insanely long ut_delay() will trip the 100-second timeout in srv_shutdown_all_bg_threads().

            marko Marko Mäkelä added a comment - I cannot repeat the hang as described, but it could be a timing issue. I think that we only need a conflict on some mutex (fil_system->mutex is a good candidate), and then the insanely long ut_delay() will trip the 100-second timeout in srv_shutdown_all_bg_threads().

            There is no upper limit for innodb_spin_wait_delay in MySQL either (other than ~0UL which is practically infinite on systems with 64-bit long). Given that ut_delay() is documented to be an approximate delay in microseconds on a 100MHz Intel Pentium processor and given that innodb_spin_wait_delay is the maximum value for the argument passed to ut_delay(), I think that the upper limit should be some thousands. The default value is 6. Even though today’s processors are faster than an Intel Pentium running at 100MHz, it does not make sense to busy-wait without polling the condition even for a millisecond.

            marko Marko Mäkelä added a comment - There is no upper limit for innodb_spin_wait_delay in MySQL either (other than ~0UL which is practically infinite on systems with 64-bit long). Given that ut_delay() is documented to be an approximate delay in microseconds on a 100MHz Intel Pentium processor and given that innodb_spin_wait_delay is the maximum value for the argument passed to ut_delay(), I think that the upper limit should be some thousands. The default value is 6. Even though today’s processors are faster than an Intel Pentium running at 100MHz, it does not make sense to busy-wait without polling the condition even for a millisecond.

            ok to push.

            jplindst Jan Lindström (Inactive) added a comment - ok to push.

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.