MySQL Bugs: #93462: InnoDB: Waiting for master thread to be suspended

Bug #93462	InnoDB: Waiting for master thread to be suspended
Submitted:	4 Dec 2018 5:37	Modified:	4 Jan 2019 13:19
Reporter:	Jim Smith	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.7.17	OS:	Windows
Assigned to:		CPU Architecture:	Any
Tags:	shutdown, startup

Description:
Shutdown of the MySQL server hangs with message

InnoDB: Waiting for master thread to be suspended

Seems to be in a infinite loop printing the above every 1 minute.

Some History

1) We installed a new mysql server community edition 5.3.17 instance
2) Created a database and restored it from a mysqldump
3) Stopped the server (this work perfectly fine see log)
4) Started the server (This log mentions that database )
       [Note] InnoDB: Database was not shutdown normally!
       [Note] InnoDB: Starting crash recovery.
5) Server comes up after the doing the recovery
6) Now when we shutdown the server again we get the message
       [Note] InnoDB: Waiting for master thread to be suspended
This has been going on for 1 hr 15 min

In the past when this has happened and when we kill the mysqld process the startup of the server never completes and hangs
after show the following in the log file
      [Note] InnoDB: Starting crash recovery. 

How to repeat:
Attached is the log output

Attached is the log output

2018-12-04T00:21:21.038242Z 0 [Note] InnoDB: FTS optimize thread exiting.
2018-12-04T00:21:21.039249Z 0 [Note] InnoDB: Starting shutdown...
2018-12-04T00:21:21.140262Z 0 [Note] InnoDB: Dumping buffer pool(s) to E:\ProgramData\MySQL\MySQL Server 5.7\Data\ib_buffer_pool
2018-12-04T00:21:21.141259Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 181203 19:21:21
2018-12-04T00:21:22.457309Z 0 [Note] InnoDB: Shutdown completed; log sequence number 2534589
2018-12-04T00:21:22.457309Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-04T00:21:22.457309Z 0 [Note] Shutting down plugin 'MEMORY'
2018-12-04T00:21:22.458311Z 0 [Note] Shutting down plugin 'CSV'
2018-12-04T00:21:22.458311Z 0 [Note] Shutting down plugin 'sha256_password'
2018-12-04T00:21:22.458311Z 0 [Note] Shutting down plugin 'mysql_native_password'
2018-12-04T00:21:22.458311Z 0 [Note] Shutting down plugin 'binlog'
2018-12-04T00:21:22.461310Z 0 [Note] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: Shutdown complete

2018-12-04T00:33:49.268883Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-12-04T00:33:49.269881Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2018-12-04T00:33:49.271880Z 0 [Note] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe (mysqld 5.7.17-log) starting as process 5580 ...
2018-12-04T00:33:49.281880Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2018-12-04T00:33:49.281880Z 0 [Note] InnoDB: Uses event mutexes
2018-12-04T00:33:49.281880Z 0 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2018-12-04T00:33:49.282880Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-12-04T00:33:49.282880Z 0 [Note] InnoDB: Number of pools: 1
2018-12-04T00:33:49.283880Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2018-12-04T00:33:49.285881Z 0 [Note] InnoDB: Initializing buffer pool, total size = 32G, instances = 8, chunk size = 128M
2018-12-04T00:33:51.446003Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-04T00:33:52.100048Z 0 [Note] InnoDB: Setting log file f:\Logs\ib_logfile101 size to 512 MB
2018-12-04T00:33:52.102042Z 0 [Note] InnoDB: Progress in MB:
 100 200 300 400 500
2018-12-04T00:33:54.444394Z 0 [Note] InnoDB: Setting log file f:\Logs\ib_logfile1 size to 512 MB
2018-12-04T00:33:54.445390Z 0 [Note] InnoDB: Progress in MB:
 100 200 300 400 500
2018-12-04T00:33:56.997772Z 0 [Note] InnoDB: Renaming log file f:\Logs\ib_logfile101 to f:\Logs\ib_logfile0
2018-12-04T00:33:56.999771Z 0 [Warning] InnoDB: New log files created, LSN=2534589
2018-12-04T00:33:57.000767Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-12-04T00:33:57.305783Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2534924
2018-12-04T00:33:57.306785Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 2534933
2018-12-04T00:33:57.598800Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 2534933
	
2018-12-04T00:33:58.325497Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-04T00:33:58.326500Z 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-04T00:33:58.367506Z 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
2018-12-04T00:33:58.369499Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-12-04T00:33:58.369499Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-12-04T00:33:58.370500Z 0 [Note] InnoDB: Waiting for purge to start
2018-12-04T00:33:58.421508Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6338ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2018-12-04T00:33:58.421508Z 0 [Note] InnoDB: 5.7.17 started; log sequence number 2534933
2018-12-04T00:33:58.422507Z 0 [Note] InnoDB: Loading buffer pool(s) from e:\ProgramData\MySQL\MySQL Server 5.7\Data\ib_buffer_pool
2018-12-04T00:33:58.422507Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-12-04T00:33:58.435529Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2018-12-04T00:33:58.435529Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2018-12-04T00:33:58.436506Z 0 [Note] IPv6 is available.
2018-12-04T00:33:58.436506Z 0 [Note]   - '::' resolves to '::';
2018-12-04T00:33:58.436506Z 0 [Note] Server socket created on IP: '::'.
2018-12-04T00:33:58.451505Z 0 [Note] InnoDB: Buffer pool(s) load completed at 181203 19:33:58
2018-12-04T00:33:58.473505Z 0 [Note] Event Scheduler: Loaded 0 events
2018-12-04T00:33:58.473505Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check. 
2018-12-04T00:33:58.474505Z 0 [Note] Beginning of list of non-natively partitioned tables
2018-12-04T00:33:58.507508Z 0 [Note] End of list of non-natively partitioned tables
2018-12-04T00:33:58.508507Z 0 [Note] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: ready for connections.
Version: '5.7.17-log'  socket: ''  port: 3306  MySQL Community Server (GPL)
2018-12-04T03:56:52.588419Z 0 [Note] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: Normal shutdown

2018-12-04T03:56:52.589425Z 0 [Note] Giving 2 client threads a chance to die gracefully
2018-12-04T03:56:52.589425Z 0 [Note] Shutting down slave threads
2018-12-04T03:56:54.592072Z 0 [Note] Forcefully disconnecting 2 remaining clients
2018-12-04T03:56:54.592072Z 0 [Warning] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: Forcing close of thread 4  user: 'root'

2018-12-04T03:56:54.592072Z 0 [Warning] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: Forcing close of thread 3  user: 'root'

2018-12-04T03:56:54.593066Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2018-12-04T03:56:54.594069Z 0 [Note] Binlog end
2018-12-04T03:56:54.600068Z 0 [Note] Shutting down plugin 'ngram'
2018-12-04T03:56:54.601075Z 0 [Note] Shutting down plugin 'partition'
2018-12-04T03:56:54.601075Z 0 [Note] Shutting down plugin 'BLACKHOLE'
2018-12-04T03:56:54.601075Z 0 [Note] Shutting down plugin 'ARCHIVE'
2018-12-04T03:56:54.601075Z 0 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
....
2018-12-04T03:56:54.611069Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2018-12-04T03:56:54.611069Z 0 [Note] Shutting down plugin 'INNODB_TRX'
2018-12-04T03:56:54.611069Z 0 [Note] Shutting down plugin 'InnoDB'
2018-12-04T03:56:54.612069Z 0 [Note] InnoDB: FTS optimize thread exiting.
2018-12-04T03:56:54.612069Z 0 [Note] InnoDB: Starting shutdown...
2018-12-04T03:56:54.713511Z 0 [Note] InnoDB: Dumping buffer pool(s) to e:\ProgramData\MySQL\MySQL Server 5.7\Data\ib_buffer_pool
2018-12-04T03:56:54.944523Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 181203 22:56:54
2018-12-04T03:57:00.029707Z 0 [Note] InnoDB: Shutdown completed; log sequence number 98355462162
2018-12-04T03:57:00.030708Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-04T03:57:00.030708Z 0 [Note] Shutting down plugin 'MEMORY'
2018-12-04T03:57:00.030708Z 0 [Note] Shutting down plugin 'CSV'
2018-12-04T03:57:00.031711Z 0 [Note] Shutting down plugin 'sha256_password'
2018-12-04T03:57:00.031711Z 0 [Note] Shutting down plugin 'mysql_native_password'
2018-12-04T03:57:00.031711Z 0 [Note] Shutting down plugin 'keyring_file'
2018-12-04T03:57:00.033708Z 0 [Note] Shutting down plugin 'binlog'
2018-12-04T03:57:00.039708Z 0 [Note] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: Shutdown complete

2018-12-04T03:57:11.124969Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-12-04T03:57:11.124969Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2018-12-04T03:57:11.126967Z 0 [Note] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe (mysqld 5.7.17-log) starting as process 5240 ...
2018-12-04T03:57:11.147973Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2018-12-04T03:57:11.148971Z 0 [Note] InnoDB: Uses event mutexes
2018-12-04T03:57:11.148971Z 0 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2018-12-04T03:57:11.148971Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-12-04T03:57:11.149970Z 0 [Note] InnoDB: Number of pools: 1
2018-12-04T03:57:11.149970Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2018-12-04T03:57:11.152970Z 0 [Note] InnoDB: Initializing buffer pool, total size = 32G, instances = 8, chunk size = 128M
2018-12-04T03:57:12.809102Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-04T03:57:13.196128Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-12-04T03:58:12.103316Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-04T03:58:12.104318Z 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-04T03:58:12.148786Z 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
2018-12-04T03:58:12.151784Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-12-04T03:58:12.151784Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-12-04T03:58:12.152784Z 0 [Note] InnoDB: Waiting for purge to start
2018-12-04T03:58:12.203793Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 59028ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2018-12-04T03:58:12.203793Z 0 [Note] InnoDB: 5.7.17 started; log sequence number 98355462162
2018-12-04T03:58:12.204787Z 0 [Note] InnoDB: Loading buffer pool(s) from e:\ProgramData\MySQL\MySQL Server 5.7\Data\ib_buffer_pool
2018-12-04T03:58:12.204787Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-12-04T03:58:12.228794Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2018-12-04T03:58:12.228794Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2018-12-04T03:58:12.229790Z 0 [Note] IPv6 is available.
2018-12-04T03:58:12.229790Z 0 [Note]   - '::' resolves to '::';
2018-12-04T03:58:12.230790Z 0 [Note] Server socket created on IP: '::'.
2018-12-04T03:58:12.370801Z 0 [Note] Event Scheduler: Loaded 0 events
2018-12-04T03:58:12.370801Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check. 
2018-12-04T03:58:12.371801Z 0 [Note] Beginning of list of non-natively partitioned tables
2018-12-04T03:58:16.376518Z 0 [Note] End of list of non-natively partitioned tables
2018-12-04T03:58:16.377524Z 0 [Note] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: ready for connections.
Version: '5.7.17-log'  socket: ''  port: 3306  MySQL Community Server (GPL)
2018-12-04T03:58:53.711014Z 0 [Note] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: Normal shutdown

2018-12-04T03:58:53.711014Z 0 [Note] Giving 1 client threads a chance to die gracefully
2018-12-04T03:58:53.711014Z 0 [Note] Shutting down slave threads
2018-12-04T03:58:55.712142Z 0 [Note] Forcefully disconnecting 1 remaining clients
2018-12-04T03:58:55.712142Z 0 [Warning] E:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe: Forcing close of thread 3  user: 'root'

2018-12-04T03:58:55.712142Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2018-12-04T03:58:55.713143Z 0 [Note] Binlog end
2018-12-04T03:58:55.725141Z 0 [Note] Shutting down plugin 'ngram'
2018-12-04T03:58:55.725141Z 0 [Note] Shutting down plugin 'partition'
2018-12-04T03:58:55.725141Z 0 [Note] Shutting down plugin 'BLACKHOLE'
.....
2018-12-04T03:58:55.732141Z 0 [Note] Shutting down plugin 'INNODB_CMP'
2018-12-04T03:58:55.732141Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2018-12-04T03:58:55.732141Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2018-12-04T03:58:55.732141Z 0 [Note] Shutting down plugin 'INNODB_TRX'
2018-12-04T03:58:55.732141Z 0 [Note] Shutting down plugin 'InnoDB'
2018-12-04T03:58:55.733142Z 0 [Note] InnoDB: FTS optimize thread exiting.
2018-12-04T03:58:55.733142Z 0 [Note] InnoDB: Starting shutdown...
2018-12-04T03:58:55.733142Z 0 [Note] InnoDB: Buffer pool(s) load completed at 181203 22:58:55
2018-12-04T03:58:55.734145Z 0 [Note] InnoDB: Dumping buffer pool(s) to e:\ProgramData\MySQL\MySQL Server 5.7\Data\ib_buffer_pool
2018-12-04T03:58:55.743144Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 181203 22:58:55
2018-12-04T03:59:56.435033Z 0 [Note] InnoDB: Waiting for master thread to be suspended
2018-12-04T04:00:57.135924Z 0 [Note] InnoDB: Waiting for master thread to be suspended
.....
2018-12-04T05:21:53.293068Z 0 [Note] InnoDB: Waiting for master thread to be suspended

Updated the Version

Description specifies the wrong version.  The version we are using is 5.7.17

Thank you for the bug report. Please test latest version 5.7.24 if the issue continues please provide the my.ini file.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".