[MDEV-11695] Define a reasonable upper limit for innodb_spin_wait_delay Created: 2016-12-30  Updated: 2017-01-07  Resolved: 2017-01-03

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2
Fix Version/s: 10.2.4

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-11693 Assertion `prev != 0 && next != 0' fa... Closed

 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



 Comments   
Comment by Marko Mäkelä [ 2017-01-03 ]

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.

Comment by Marko Mäkelä [ 2017-01-03 ]

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().

Comment by Marko Mäkelä [ 2017-01-03 ]

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.

Comment by Jan Lindström (Inactive) [ 2017-01-03 ]

ok to push.

Generated at Thu Feb 08 07:51:57 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.