[MDEV-15683] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool (unbelievably slow) Created: 2018-03-26  Updated: 2018-05-08  Resolved: 2018-05-07

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

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Thirunarayanan Balathandayuthapani
Resolution: Duplicate Votes: 0
Labels: None

Issue Links:
Duplicate
duplicates MDEV-15554 InnoDB page_cleaner shutdown sometime... Closed

 Description   

10.3 containing MDEV-13785 fix and pr #671 max_prepared_stmt_count to 1G

Ran sysbench oltp tests. Hit out of memory and was killed.

Mar 26 04:45:17 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service: main process exited, code=killed, status=9/KILL
 
Mar 26 04:45:17 opsky7.aus.stglabs.ibm.com systemd[1]: Unit mariadb.service entered failed state.
 
Mar 26 04:45:17 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service failed.
 
Mar 26 04:45:22 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service holdoff time over, scheduling restart.
 
Mar 26 04:45:23 opsky7.aus.stglabs.ibm.com systemd[1]: Starting MariaDB 10.3.6 database server...
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] /usr/local/mysql/bin/mysqld (mysqld 10.3.6-MariaDB) starting as process 57988 ...
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Uses event mutexes
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Using Linux native AIO
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Number of pools: 1
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Initializing buffer pool, total size = 128G, instances = 8, chunk size = 1G
 
Mar 26 04:45:57 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:57 0 [Note] InnoDB: Completed initialization of buffer pool
 
Mar 26 04:45:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:59 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See t
 
Mar 26 04:46:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:00 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=38095597389
 
Mar 26 04:46:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:14 0 [Note] InnoDB: Read redo log up to LSN=37328381952
 
Mar 26 04:46:20 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:20 0 [Note] InnoDB: Starting final batch to recover 549794 pages from redo log.
 
Mar 26 04:46:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:29 0 [Note] InnoDB: To recover: 537699 pages from log
 
Mar 26 04:46:44 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:44 0 [Note] InnoDB: To recover: 505862 pages from log
 
Mar 26 04:46:54 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service start operation timed out. Terminating.
 
Mar 26 04:46:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:59 0 [Note] InnoDB: To recover: 459982 pages from log
 
Mar 26 04:47:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:14 0 [Note] InnoDB: To recover: 414658 pages from log
 
Mar 26 04:47:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:29 0 [Note] InnoDB: To recover: 368367 pages from log
 
Mar 26 04:47:44 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:44 0 [Note] InnoDB: To recover: 322961 pages from log
 
Mar 26 04:47:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:59 0 [Note] InnoDB: To recover: 278069 pages from log
 
Mar 26 04:48:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:14 0 [Note] InnoDB: To recover: 237498 pages from log
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service stop-final-sigterm timed out. Skipping SIGKILL. Entering failed mode.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: Failed to start MariaDB 10.3.6 database server.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: Unit mariadb.service entered failed state.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service failed.
 
Mar 26 04:48:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:29 0 [Note] InnoDB: To recover: 192424 pages from log
 
Mar 26 04:48:44 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:44 0 [Note] InnoDB: To recover: 146854 pages from log
 
Mar 26 04:48:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:59 0 [Note] InnoDB: To recover: 100860 pages from log
 
Mar 26 04:49:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:14 0 [Note] InnoDB: To recover: 55217 pages from log
 
Mar 26 04:49:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:29 0 [Note] InnoDB: To recover: 8860 pages from log
 
Mar 26 04:49:33 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:33 0 [Warning] InnoDB: Failed to set memory to DODUMP: Invalid argument ptr 0x2aebc0000000 size 2097152
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Waiting for purge to start
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: 5.7.21 started; log sequence number 38095618140; transaction id 96064
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] Plugin 'FEEDBACK' is disabled.
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] Recovering after a crash using tc.log
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] Starting crash recovery...
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] Crash recovery finished.
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Buffer pool(s) load completed at 180326  4:49:35
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] Server socket created on IP: '::'.
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Uses event mutexes
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Using Linux native AIO
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Number of pools: 1
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Initializing buffer pool, total size = 128G, instances = 8, chunk size = 1G
 
Mar 26 04:45:57 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:57 0 [Note] InnoDB: Completed initialization of buffer pool
 
Mar 26 04:45:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:59 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See th
 
Mar 26 04:46:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:00 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=38095597389
 
Mar 26 04:46:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:14 0 [Note] InnoDB: Read redo log up to LSN=37328381952
 
Mar 26 04:46:20 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:20 0 [Note] InnoDB: Starting final batch to recover 549794 pages from redo log.
 
Mar 26 04:46:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:29 0 [Note] InnoDB: To recover: 537699 pages from log
 
Mar 26 04:46:44 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:44 0 [Note] InnoDB: To recover: 505862 pages from log
 
Mar 26 04:46:54 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service start operation timed out. Terminating.
 
Mar 26 04:46:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:59 0 [Note] InnoDB: To recover: 459982 pages from log
 
Mar 26 04:47:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:14 0 [Note] InnoDB: To recover: 414658 pages from log
 
Mar 26 04:47:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:29 0 [Note] InnoDB: To recover: 368367 pages from log
 
Mar 26 04:47:44 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:44 0 [Note] InnoDB: To recover: 322961 pages from log
 
Mar 26 04:47:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:59 0 [Note] InnoDB: To recover: 278069 pages from log
 
Mar 26 04:48:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:14 0 [Note] InnoDB: To recover: 237498 pages from log
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service stop-final-sigterm timed out. Skipping SIGKILL. Entering failed mode.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: Failed to start MariaDB 10.3.6 database server.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: Unit mariadb.service entered failed state.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service failed.
 
Mar 26 04:48:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:29 0 [Note] InnoDB: To recover: 192424 pages from log
 
Mar 26 04:48:44 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:44 0 [Note] InnoDB: To recover: 146854 pages from log
 
Mar 26 04:48:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:59 0 [Note] InnoDB: To recover: 100860 pages from log
 
Mar 26 04:49:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:14 0 [Note] InnoDB: To recover: 55217 pages from log
 
Mar 26 04:49:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:29 0 [Note] InnoDB: To recover: 8860 pages from log
 
Mar 26 04:49:33 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:33 0 [Warning] InnoDB: Failed to set memory to DODUMP: Invalid argument ptr 0x2aebc0000000 size 2097152
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Waiting for purge to start
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: 5.7.21 started; log sequence number 38095618140; transaction id 96064
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] Plugin 'FEEDBACK' is disabled.
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] Recovering after a crash using tc.log
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] Starting crash recovery...
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] Crash recovery finished.
 
Mar 26 04:49:35 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:49:35 0 [Note] InnoDB: Buffer pool(s) load completed at 180326  4:49:35
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] Server socket created on IP: '::'.
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] /usr/local/mysql/bin/mysqld (unknown): Normal shutdown
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] Reading of all Master_info entries succeded
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] Added new Master_info '' to hash table
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: Version: '10.3.6-MariaDB'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] Event Scheduler: Purging the queue. 0 events
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] InnoDB: FTS optimize thread exiting.
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] InnoDB: Starting shutdown...
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
 
Mar 26 04:50:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:50:00 0 [Note] InnoDB: Buffer pool(s) dump completed at 180326  4:50:00
 
Mar 26 04:51:01 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:51:01 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:52:01 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:52:01 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:53:01 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:53:01 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:54:01 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:54:01 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:55:02 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:55:02 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:56:02 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:56:02 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:57:02 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:57:02 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:58:02 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:58:02 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:59:02 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:59:02 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 05:00:02 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  5:00:02 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 05:01:03 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  5:01:03 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 05:02:03 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  5:02:03 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
.....
 
Mar 26 16:21:06 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26 16:21:06 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 16:22:06 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26 16:22:06 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 16:23:06 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26 16:23:06 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 16:24:07 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26 16:24:07 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 16:25:07 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26 16:25:07 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 16:26:07 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26 16:26:07 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Uses event mutexes
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Using Linux native AIO
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Number of pools: 1
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
Mar 26 04:45:24 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:24 0 [Note] InnoDB: Initializing buffer pool, total size = 128G, instances = 8, chunk size = 1G
 
Mar 26 04:45:57 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:57 0 [Note] InnoDB: Completed initialization of buffer pool
 
Mar 26 04:45:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:45:59 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See th
 
Mar 26 04:46:00 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:00 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=38095597389
 
Mar 26 04:46:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:14 0 [Note] InnoDB: Read redo log up to LSN=37328381952
 
Mar 26 04:46:20 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:20 0 [Note] InnoDB: Starting final batch to recover 549794 pages from redo log.
 
Mar 26 04:46:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:29 0 [Note] InnoDB: To recover: 537699 pages from log
 
Mar 26 04:46:44 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:44 0 [Note] InnoDB: To recover: 505862 pages from log
 
Mar 26 04:46:54 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service start operation timed out. Terminating.
 
Mar 26 04:46:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:46:59 0 [Note] InnoDB: To recover: 459982 pages from log
 
Mar 26 04:47:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:14 0 [Note] InnoDB: To recover: 414658 pages from log
 
Mar 26 04:47:29 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:29 0 [Note] InnoDB: To recover: 368367 pages from log
 
Mar 26 04:47:44 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:44 0 [Note] InnoDB: To recover: 322961 pages from log
 
Mar 26 04:47:59 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:47:59 0 [Note] InnoDB: To recover: 278069 pages from log
 
Mar 26 04:48:14 opsky7.aus.stglabs.ibm.com mysqld[57988]: 2018-03-26  4:48:14 0 [Note] InnoDB: To recover: 237498 pages from log
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service stop-final-sigterm timed out. Skipping SIGKILL. Entering failed mode.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: Failed to start MariaDB 10.3.6 database server.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: Unit mariadb.service entered failed state.
 
Mar 26 04:48:24 opsky7.aus.stglabs.ibm.com systemd[1]: mariadb.service failed.


[Thread debugging using libthread_db enabled]
 
Using host libthread_db library "/lib64/libthread_db.so.1".
 
0x00007fc29b553945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
 
 
Thread 17 (Thread 0x7fc296e60700 (LWP 57989)):
 
#0  0x00007fc29b553cf2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x0000000000c63c61 in inline_mysql_cond_timedwait (mutex=<optimized out>, src_line=<optimized out>, that=<optimized out>, mutex=<optimized out>, abstime=<optimized out>, src_file=<optimized out>, src_line=<optimized out>) at /home/dan/mariadb-server/include/mysql/psi/mysql_thread.h:1215
 
#2  timer_handler (arg=<optimized out>) at /home/dan/mariadb-server/mysys/thr_timer.c:292
 
#3  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#4  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 16 (Thread 0x7fc294938700 (LWP 57990)):
 
#0  0x00007fc29b553cf2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x0000000000b7a093 in inline_mysql_cond_timedwait (src_line=<optimized out>, that=<optimized out>, mutex=<optimized out>, abstime=<optimized out>, src_file=<optimized out>, src_line=<optimized out>) at /home/dan/mariadb-server/include/mysql/psi/mysql_thread.h:1215
 
#2  my_service_thread_sleep (control=0x1534cc0 <checkpoint_control>, sleep_time=<optimized out>) at /home/dan/mariadb-server/storage/maria/ma_servicethread.c:115
 
#3  0x0000000000b73a11 in ma_checkpoint_background (arg=0x1e) at /home/dan/mariadb-server/storage/maria/ma_checkpoint.c:707
 
#4  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#5  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 15 (Thread 0x7fc28d29b700 (LWP 58255)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fc28d29aa70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fc28d29aa70, m1=0x7fc28d29ad28, m2=<optimized out>, request=0x7fc28d29ad10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fc28d29ad28, m2=0x7fc28d29ad08, request=0x7fc28d29ad10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=0) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 14 (Thread 0x7fc28ca9a700 (LWP 58256)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fc28ca99a70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fc28ca99a70, m1=0x7fc28ca99d28, m2=<optimized out>, request=0x7fc28ca99d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fc28ca99d28, m2=0x7fc28ca99d08, request=0x7fc28ca99d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=1) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 13 (Thread 0x7fbff5e06700 (LWP 58257)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fbff5e05a70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fbff5e05a70, m1=0x7fbff5e05d28, m2=<optimized out>, request=0x7fbff5e05d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fbff5e05d28, m2=0x7fbff5e05d08, request=0x7fbff5e05d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=2) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 12 (Thread 0x7fbff5605700 (LWP 58258)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fbff5604a70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fbff5604a70, m1=0x7fbff5604d28, m2=<optimized out>, request=0x7fbff5604d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fbff5604d28, m2=0x7fbff5604d08, request=0x7fbff5604d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=3) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 11 (Thread 0x7fbff4e04700 (LWP 58259)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fbff4e03a70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fbff4e03a70, m1=0x7fbff4e03d28, m2=<optimized out>, request=0x7fbff4e03d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fbff4e03d28, m2=0x7fbff4e03d08, request=0x7fbff4e03d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=4) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 10 (Thread 0x7fbff4603700 (LWP 58260)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fbff4602a70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fbff4602a70, m1=0x7fbff4602d28, m2=<optimized out>, request=0x7fbff4602d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fbff4602d28, m2=0x7fbff4602d08, request=0x7fbff4602d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=5) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 9 (Thread 0x7fbff3e02700 (LWP 58261)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fbff3e01a70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fbff3e01a70, m1=0x7fbff3e01d28, m2=<optimized out>, request=0x7fbff3e01d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fbff3e01d28, m2=0x7fbff3e01d08, request=0x7fbff3e01d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=6) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 8 (Thread 0x7fbff3601700 (LWP 58262)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fbff3600a70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fbff3600a70, m1=0x7fbff3600d28, m2=<optimized out>, request=0x7fbff3600d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fbff3600d28, m2=0x7fbff3600d08, request=0x7fbff3600d10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=7) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 7 (Thread 0x7fbff2e00700 (LWP 58263)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fbff2dffa70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fbff2dffa70, m1=0x7fbff2dffd28, m2=<optimized out>, request=0x7fbff2dffd10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fbff2dffd28, m2=0x7fbff2dffd08, request=0x7fbff2dffd10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=8) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 6 (Thread 0x7fbff25ff700 (LWP 58264)):
 
#0  0x00007fc29b120644 in __io_getevents_0_4 () from /lib64/libaio.so.1
 
#1  0x00000000009bd3af in LinuxAIOHandler::collect (this=0x7fbff25fea70) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:1891
 
#2  0x00000000009bd7b6 in LinuxAIOHandler::poll (this=0x7fbff25fea70, m1=0x7fbff25fed28, m2=<optimized out>, request=0x7fbff25fed10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2036
 
#3  0x00000000009c1312 in os_aio_linux_handler (global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>, global_segment=<optimized out>, m1=<optimized out>, m2=<optimized out>, request=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:2090
 
#4  os_aio_handler (segment=<optimized out>, m1=0x7fbff25fed28, m2=0x7fbff25fed08, request=0x7fbff25fed10) at /home/dan/mariadb-server/storage/innobase/os/os0file.cc:5668
 
#5  0x0000000000afd864 in fil_aio_wait (segment=9) at /home/dan/mariadb-server/storage/innobase/fil/fil0fil.cc:5323
 
#6  0x0000000000a3b188 in io_handler_thread (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:339
 
#7  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#8  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 5 (Thread 0x7fbff1dfe700 (LWP 58265)):
 
#0  0x00007fc29b556e4d in nanosleep () from /lib64/libpthread.so.0
 
#1  0x00000000009c52af in os_thread_sleep (tm=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0thread.cc:230
 
#2  0x0000000000ab44ca in buf_flush_page_cleaner_close () at /home/dan/mariadb-server/storage/innobase/buf/buf0flu.cc:2713
 
#3  buf_flush_page_cleaner_coordinator () at /home/dan/mariadb-server/storage/innobase/buf/buf0flu.cc:3426
 
#4  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#5  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 4 (Thread 0x7fbff15fd700 (LWP 58266)):
 
#0  0x00007fc29b553945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x00000000009c4cb6 in wait (this=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0event.cc:163
 
#2  os_event::wait_low (this=0x17a563d30, reset_sig_count=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0event.cc:333
 
#3  0x0000000000ab51c3 in buf_flush_page_cleaner_worker (arg=<optimized out>) at /home/dan/mariadb-server/storage/innobase/buf/buf0flu.cc:3505
 
#4  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#5  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 3 (Thread 0x7fc133fff700 (LWP 60268)):
 
#0  0x00007fc29b553cf2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x00000000007c58ec in inline_mysql_cond_timedwait (that=<optimized out>, mutex=<optimized out>, abstime=<optimized out>, src_file=<optimized out>, src_line=<optimized out>) at /home/danmariadb-server/include/mysql/psi/mysql_thread.h:1215
 
#2  timer_thread (param=0x15d85f8 <pool_timer>) at /home/dan/mariadb-server/sql/threadpool_generic.cc:655
 
#3  0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#4  0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 2 (Thread 0x7fc294137700 (LWP 60270)):
 
#0  0x00007fc29b556e4d in nanosleep () from /lib64/libpthread.so.0
 
#1  0x00000000009c52af in os_thread_sleep (tm=<optimized out>) at /home/dan/mariadb-server/storage/innobase/os/os0thread.cc:230
 
#2  0x00000000009ad8fd in logs_empty_and_mark_files_at_shutdown () at /home/dan/mariadb-server/storage/innobase/log/log0log.cc:1996
 
#3  0x0000000000a41f7d in innodb_shutdown () at /home/dan/mariadb-server/storage/innobase/srv/srv0start.cc:2808
 
#4  0x000000000096cc55 in innobase_end () at /home/dan/mariadb-server/storage/innobase/handler/ha_innodb.cc:4298
 
#5  0x00000000007f0588 in ha_finalize_handlerton (plugin=0x2e86928) at /home/dan/mariadb-server/sql/handler.cc:461
 
#6  0x00000000006386b9 in plugin_deinitialize (plugin=0x2e86928, ref_check=true) at /home/dan/mariadb-server/sql/sql_plugin.cc:1258
 
#7  0x0000000000636fba in reap_plugins () at /home/dan/mariadb-server/sql/sql_plugin.cc:1334
 
#8  0x0000000000638925 in plugin_shutdown () at /home/dan/mariadb-server/sql/sql_plugin.cc:2000
 
#9  0x000000000057dcad in clean_up (print_message=true) at /home/dan/mariadb-server/sql/mysqld.cc:2243
 
#10 0x000000000057dbdb in unireg_end () at /home/dan/mariadb-server/sql/mysqld.cc:2115
 
#11 0x000000000057db87 in kill_server (sig_ptr=<optimized out>) at /home/dan/mariadb-server/sql/mysqld.cc:2042
 
#12 kill_server_thread (arg=0x7fc294135498) at /home/dan/mariadb-server/sql/mysqld.cc:2065
 
#13 0x00007fc29b54fe25 in start_thread () from /lib64/libpthread.so.0
 
#14 0x00007fc29970534d in clone () from /lib64/libc.so.6
 
 
 
Thread 1 (Thread 0x7fc29b9418c0 (LWP 57988)):
 
#0  0x00007fc29b553945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x00000000005813fb in inline_mysql_cond_wait (that=<optimized out>, mutex=<optimized out>, src_file=<optimized out>, src_line=<optimized out>) at /home/dan/mariadb-server/include/mysql/si/mysql_thread.h:1178
 
#2  mysqld_main (argc=27, argv=0x2e1c658) at /home/dan/mariadb-server/sql/mysqld.cc:6180
 
#3  0x00007fc29962ec05 in __libc_start_main () from /lib64/libc.so.6
 
#4  0x000000000057c759 in _start ()


#2  0x00000000009ad8fd in logs_empty_and_mark_files_at_shutdown () at /home/dan/mariadb-server/storage/innobase/log/log0log.cc:1996
 
1996                    os_thread_sleep(100000);
 
(gdb) info locals
 
count = 259
 
lsn = <optimized out>
 
(gdb) p *log_sys
 
$1 = {pad1 = '\000' <repeats 63 times>, lsn = 38095655874, buf_free = 450, pad2 = '\000' <repeats 63 times>, mutex = {m_impl = {m_lock_word = 0, m_event = 0x17a5609a0, m_policy = {
 
        m_count = {m_spins = 0, m_waits = 0, m_calls = 0, m_enabled = false}, m_id = LATCH_ID_LOG_SYS}}, m_ptr = 0x0}, pad3 = '\000' <repeats 63 times>, write_mutex = {m_impl = {
 
      m_lock_word = 0, m_event = 0x17a560ab0, m_policy = {m_count = {m_spins = 0, m_waits = 0, m_calls = 0, m_enabled = false}, m_id = LATCH_ID_LOG_WRITE}}, m_ptr = 0x0},
 
  pad4 = '\000' <repeats 63 times>, log_flush_order_mutex = {m_impl = {m_lock_word = 0, m_event = 0x17a560f60, m_policy = {m_count = {m_spins = 0, m_waits = 0, m_calls = 0,
 
          m_enabled = false}, m_id = LATCH_ID_LOG_FLUSH_ORDER}}, m_ptr = 0x0}, buf = 0x2aeb80000000 "\004oV\312\001\302", <incomplete sequence \302>, first_in_use = true,
 
  buf_size = 67108864, max_buf_free = 33486848, check_flush_or_checkpoint = false, log = {n_files = 4, format = 103, file_size = 1073741824, state = LOG_GROUP_OK, lsn = 38095637015,
 
    lsn_offset = 3735963671, file_header_bufs_ptr = 0x17a5857e0, file_header_bufs = 0x17a585810, scanned_lsn = 38095618140, checkpoint_buf_ptr = 0x17a588080 "",
 
    checkpoint_buf = 0x17a588200 ""}, buf_next_to_write = 450, is_extending = false, write_lsn = 38095655874, current_flush_lsn = 38095655874, flushed_to_disk_lsn = 38095655874,
 
  n_pending_flushes = 0, flush_event = 0x17a561070, n_log_ios = 13372, n_log_ios_old = 13369, last_printout_time = 1522057775, log_group_capacity = 3865463194,
 
  max_modified_age_async = 3043432951, max_modified_age_sync = 3260821019, max_checkpoint_age_async = 3369515053, max_checkpoint_age = 3478209086, next_checkpoint_no = 965,
 
  last_checkpoint_lsn = 37223755687, next_checkpoint_lsn = 37223755687, append_on_checkpoint = 0x0, n_pending_checkpoint_writes = 0, checkpoint_lock = {lock_word = 536870912, waiters = 0,
 
    sx_recursive = 0, writer_is_wait_ex = false, writer_thread = 0, event = 0x17a5610f0, wait_ex_event = 0x17a561170,
 
    cfile_name = 0xecc160 "/home/dan/mariadb-server/storage/innobase/log/log0log.cc", last_x_file_name = 0xecc160 "/home/dan/mariadb-server/storage/innobase/log/log0log.cc", cline = 753,
 
    is_block_lock = 0, last_x_line = 1525, count_os_wait = 2, list = {prev = 0x17a584cd0, next = 0x17a5581c0}, pfs_psi = 0x0}, checkpoint_buf_ptr = 0x17a5611f0 "",
 
  checkpoint_buf = 0x17a561200 ""}


[mariadb]
 
datadir=/var/lib/mysql
 
thread_handling=pool-of-threads
 
thread_pool_stall_limit=1ms
 
 
 
max-connections=4096
 
 
 
large_pages=1
 
memlock=1
 
 
 
query_cache_type=0
 
 
 
# Was set to match P9's memory page size
 
#innodb_page_size=64k
 
 
 
innodb-buffer-pool-size=128G
 
# 1G - 32M - based off buf_chunk_init to keep the
 
# allocation in 1G chunks
 
# 16k page size
 
# (gdb) p (1 << 30) / (16 * 1024) * sizeof(buf_block_t) + (16384 - 1)
 
#$2 = 25182207
 
# 64k page size
 
#(gdb) p (1 << 30) / (65536) * sizeof(buf_block_t) + (65536 - 1)
 
#$3 = 6356991
 
#(gdb) p 1 << 30 - (32 * 1<< 20)
 
#$4 = 1073741824
 
innodb_buffer_pool_chunk_size=1073741824
 
 
 
innodb_file_per_table=1
 
innodb_flush_method=O_DIRECT
 
 
 
innodb_lru_scan_depth=20000
 
innodb_io_capacity=10k
 
innodb_io_capacity_max=20k
 
 
 
innodb_log_buffer_size=64M
 
innodb_thread_concurrency=0
 
innodb_max_dirty_pages_pct=25
 
innodb_adaptive_flushing=1
 
innodb_read_io_threads=4
 
innodb_write_io_threads=4
 
innodb_purge_threads=1
 
 
 
innodb_log_file_size=1G
 
innodb_log_files_in_group=4
 
 
 
performance_schema=OFF
 
 
 
max_prepared_stmt_count=16M



 Comments   
Comment by Daniel Black [ 2018-04-02 ]

Ok bit more info. and related to https://github.com/systemd/systemd/issues/8630

mysqld shut-down. Its a bit slow (huge innodb log file size), systemd times the service out, but doesn't kill it off (SendSigkill=no) but during restart starts a second instance while the first is online (hence systemd bug above).

During the startup we're getting a proliferation of cannot start file locked, as expected and the whole second instance fails while the first one continues with the 'InnoDB: Waiting for page_cleaner to finish flushing of buffer pool' continuing.

Below information is an extension of https://github.com/systemd/systemd/issues/8630#issuecomment-378080993:

Apr 02 18:23:37 zaiuslp5 numactl[111391]: 2018-04-02 18:23:37 0 [Note] InnoDB: Buffer pool(s) dump completed at 180402 18:23:37
 
Apr 02 18:24:38 zaiuslp5 numactl[111391]: 2018-04-02 18:24:38 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:25:07 zaiuslp5 systemd[1]: mariadb0@0.service: State 'stop-sigterm' timed out. Skipping SIGKILL.
 
Apr 02 18:25:38 zaiuslp5 numactl[111391]: 2018-04-02 18:25:38 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:26:37 zaiuslp5 systemd[1]: mariadb0@0.service: State 'stop-final-sigterm' timed out. Skipping SIGKILL. Entering failed mode.
 
Apr 02 18:26:37 zaiuslp5 systemd[1]: Stopped MariaDB @VERSION@ database server (multi-instance).
 
Apr 02 18:26:37 zaiuslp5 systemd[1]: mariadb0@0.service: Unit entered failed state.
 
Apr 02 18:26:37 zaiuslp5 systemd[1]: mariadb0@0.service: Failed with result 'timeout'.
 
Apr 02 18:26:37 zaiuslp5 systemd[1]: Starting MariaDB @VERSION@ database server (multi-instance)...
 
Apr 02 18:26:38 zaiuslp5 mysql_install_db[148699]: Installing MariaDB/MySQL system tables in '/var/lib/mysql/node0/0' ...
 
Apr 02 18:26:38 zaiuslp5 numactl[111391]: 2018-04-02 18:26:38 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:26:39 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:26:39 0 [ERROR] RocksDB: Error opening instance, Status Code: 5, Status: IO error: While lock file: ./#rocksdb/LOCK: Resource temporarily unavailable
 
Apr 02 18:26:39 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:26:39 0 [ERROR] Plugin 'ROCKSDB' init function returned error.
 
Apr 02 18:26:39 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:26:39 0 [ERROR] Plugin 'ROCKSDB' registration as a STORAGE ENGINE failed.
 
Apr 02 18:26:39 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:26:39 0 [ERROR] mysqld: Can't lock aria control file '/var/lib/mysql/node0/0/aria_log_control' for exclusive use, error: 11. Will retry for 30 seconds
 
Apr 02 18:27:10 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:10 0 [ERROR] mysqld: Got error 'Could not get an exclusive lock; file is probably in use by another process' when trying to use aria control file '/var/lib/mysql/node0/0/aria_log_control'
 
Apr 02 18:27:10 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:10 0 [ERROR] Plugin 'Aria' init function returned error.
 
Apr 02 18:27:10 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:10 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
 
Apr 02 18:27:10 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:10 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:11 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:11 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:12 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:12 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:13 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:13 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:14 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:14 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:15 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:15 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:16 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:16 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:17 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:17 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:18 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:18 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:19 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:19 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:20 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:20 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:21 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:21 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:22 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:22 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:23 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:23 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:24 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:24 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:25 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:25 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:26 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:26 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:27 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:27 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:28 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:28 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:29 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:29 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:30 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:30 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:31 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:31 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:32 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:32 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:33 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:33 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:34 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:34 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:35 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:35 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:36 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:36 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:37 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:37 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:38 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:38 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:38 zaiuslp5 numactl[111391]: 2018-04-02 18:27:38 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:27:39 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:39 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:40 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:40 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:41 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:41 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:42 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:42 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:43 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:43 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:44 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:44 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:45 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:45 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:46 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:46 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:47 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:47 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:48 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:48 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:49 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:49 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:50 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:50 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:51 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:51 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:52 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:52 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:53 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:53 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:54 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:54 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:55 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:55 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:56 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:56 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:57 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:57 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:58 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:58 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:27:59 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:27:59 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:00 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:28:00 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:01 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:28:01 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:02 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:28:02 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:03 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:28:03 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:04 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:28:04 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:05 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:28:05 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:06 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:28:06 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:07 zaiuslp5 mysql_install_db[148699]: 2018-04-02 18:28:07 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
Apr 02 18:28:08 zaiuslp5 systemd[1]: mariadb0@0.service: Start-pre operation timed out. Terminating.
 
Apr 02 18:28:38 zaiuslp5 numactl[111391]: 2018-04-02 18:28:38 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:29:38 zaiuslp5 systemd[1]: mariadb0@0.service: State 'stop-final-sigterm' timed out. Skipping SIGKILL. Entering failed mode.
 
Apr 02 18:29:38 zaiuslp5 systemd[1]: Failed to start MariaDB @VERSION@ database server (multi-instance).
 
Apr 02 18:29:38 zaiuslp5 systemd[1]: mariadb0@0.service: Unit entered failed state.
 
Apr 02 18:29:38 zaiuslp5 systemd[1]: mariadb0@0.service: Failed with result 'timeout'.
 
Apr 02 18:29:38 zaiuslp5 numactl[111391]: 2018-04-02 18:29:38 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:30:39 zaiuslp5 numactl[111391]: 2018-04-02 18:30:39 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:31:39 zaiuslp5 numactl[111391]: 2018-04-02 18:31:39 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:32:39 zaiuslp5 numactl[111391]: 2018-04-02 18:32:39 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:33:39 zaiuslp5 numactl[111391]: 2018-04-02 18:33:39 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:34:39 zaiuslp5 numactl[111391]: 2018-04-02 18:34:39 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:35:39 zaiuslp5 numactl[111391]: 2018-04-02 18:35:39 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
Apr 02 18:36:39 zaiuslp5 numactl[111391]: 2018-04-02 18:36:39 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
...
 
systemctl  status mariadb0@0.service
 
● mariadb0@0.service - MariaDB @VERSION@ database server (multi-instance)
 
   Loaded: loaded (/etc/systemd/system/mariadb0@.service; disabled; vendor preset: enabled)
 
  Drop-In: /etc/systemd/system/mariadb0@.service.d
 
           └─multi.conf
 
   Active: failed (Result: timeout) since Mon 2018-04-02 18:29:38 CDT; 18min ago
 
     Docs: man:mysqld(8)
 
           https://mariadb.com/kb/en/library/systemd/
 
  Process: 148699 ExecStartPre=/usr/bin/mysql_install_db $MYSQLD_MULTI_INSTANCE --user=mysql (code=killed, signal=TERM)
 
 Main PID: 111391
 
    Tasks: 80
 
   CGroup: /system.slice/system-mariadb0.slice/mariadb0@0.service
 
           └─111391 /usr/sbin/mysqld --datadir=/var/lib/mysql/node0/0 --socket=/var/run/mysqld/mysqld-n0-0.sock

Comment by Marko Mäkelä [ 2018-05-07 ]

danblack, which exact revision did you use?

This looks much like a duplicate of MDEV-15554. You mentioned that a fix was included:

commit 402c7584a81c6c2bca00ae7890d501221c5f8096
 
Author: Daniel Black <daniel@linux.vnet.ibm.com>
 
Date:   Fri Mar 23 12:58:11 2018 +1100
 
 
 
    MDEV-13785: move defination HAVE_LARGE_PAGES -> HAVE_LINUX_LARGE_PAGES

This one was apparently pushed to the 10.3 branch around March 28, that is, one day after you filed this issue. But, the MDEV-15554 fix also was on March 13.

It would be useful to always include the commit hash. Clearly the server version must be older than the actual 10.3.6 release, because the 10.3.6 release tag was much later, on April 13.

In any case, the function buf_flush_page_cleaner_close() that is present in the stack trace was removed by MDEV-15554, which fixed a 'lost signal' issue when using multiple buffer pools and page cleaner threads.

Comment by Daniel Black [ 2018-05-08 ]

Apologies, tested at:

git log
 
 
 
commit fb4e1aeda7762c73dc2cbe9aa1a8f5c4ec1d4d2a (HEAD -> 10.3)
 
Author: Daniel Black <daniel@linux.vnet.ibm.com>
 
Date:   Sun Mar 25 19:54:32 2018 -0500
 
 
 
    extend maximium max_prepared_stmt_count
 
 
 
commit fa0988629cb13292f543f092386bea905a357655
 
Author: Daniel Black <daniel@linux.vnet.ibm.com>
 
Date:   Thu Mar 22 18:44:53 2018 -0500
 
 
 
    MDEV-13785: large pages
 
 
 
commit 865cec928a0f33ea1e6f71d0a3d8ac0d0570252a (origin/HEAD, origin/10.3)
 
Merge: 4359c6b4806 33aad1d2738
 
Author: Marko Mäkelä <marko.makela@mariadb.com>
 
Date:   Wed Mar 21 16:29:30 2018 +0200

Generated at Thu Feb 08 08:23:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.