[MDEV-17339] encryption.innodb_encryption_tables failed in buildbot, server crashed on restart Created: 2018-10-01  Updated: 2021-04-21  Resolved: 2021-04-09

Status: Closed
Project: MariaDB Server
Component/s: Server, Tests
Affects Version/s: 10.3
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Thirunarayanan Balathandayuthapani
Resolution: Cannot Reproduce Votes: 1
Labels: need_feedback

Issue Links:
Relates
relates to MDEV-23456 fil_space_crypt_t::write_page0() is a... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-zyp-sles114-amd64/builds/2555

encryption.innodb_encryption_tables 'innodb' w1 [ fail ]
        Test ended at 2018-08-24 14:43:14
 
CURRENT_TEST: encryption.innodb_encryption_tables
mysqltest: In included file "./include/wait_until_connected_again.inc": 
included from ./include/start_mysqld.inc at line 18:
included from ./include/restart_mysqld.inc at line 11:
included from /usr/share/mysql-test/suite/encryption/t/innodb_encryption_tables.test at line 67:
At line 23: Server failed to restart
 
The result from queries just before the failure was:
< snip >
select count(*) from innodb_compressed t1, innodb_normal t2 where
t1.c1 = t2.c1 and t1.b = t2.b;
count(*)
2000
select count(*) from innodb_redundant t1, innodb_normal t2 where
t1.c1 = t2.c1 and t1.b = t2.b;
count(*)
2000
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_encrypted';
variable_value >= 0
1
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_decrypted';
variable_value >= 0
1
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_page_compressed';
variable_value >= 0
1
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_page_decompressed';
variable_value >= 0
1
 
More results from queries before failure can be found in /dev/shm/var/1/log/innodb_encryption_tables.log
 
 - skipping '/dev/shm/var/1/log/encryption.innodb_encryption_tables-innodb/'

CURRENT_TEST: encryption.innodb_encryption_tables
2018-08-24 14:34:50 0 [Note] /usr/sbin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
2018-08-24 14:34:50 0 [Note] Event Scheduler: Purging the queue. 0 events
2018-08-24 14:34:50 0 [Note] InnoDB: FTS optimize thread exiting.
2018-08-24 14:34:50 0 [Note] InnoDB: Starting shutdown...
2018-08-24 14:34:50 0 [Note] InnoDB: Dumping buffer pool(s) to /dev/shm/var/1/mysqld.1/data/ib_buffer_pool
2018-08-24 14:34:50 0 [Note] InnoDB: Instance 0, restricted to 127 pages due to innodb_buf_pool_dump_pct=25
2018-08-24 14:34:50 0 [Note] InnoDB: Buffer pool(s) dump completed at 180824 14:34:50
2018-08-24 14:34:51 0 [Note] InnoDB: Shutdown completed; log sequence number 9959112; transaction id 147
2018-08-24 14:34:51 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-08-24 14:34:51 0 [Note] /usr/sbin/mysqld: Shutdown complete
 
2018-08-24 14:34:52 0 [Note] /usr/sbin/mysqld (mysqld 10.3.10-MariaDB-log) starting as process 22749 ...
2018-08-24 14:34:52 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4182)
2018-08-24 14:34:52 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2018-08-24 14:34:52 0 [Warning] Plugin 'example_key_management' is of maturity level experimental while the server is stable
2018-08-24 14:34:52 0 [Note] Plugin 'partition' is disabled.
2018-08-24 14:34:52 0 [Note] InnoDB: Using Linux native AIO
2018-08-24 14:34:52 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-08-24 14:34:52 0 [Note] InnoDB: Uses event mutexes
2018-08-24 14:34:52 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
2018-08-24 14:34:52 0 [Note] InnoDB: Number of pools: 1
2018-08-24 14:34:52 0 [Note] InnoDB: Using generic crc32 instructions
2018-08-24 14:34:52 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2018-08-24 14:34:52 0 [Note] InnoDB: Completed initialization of buffer pool
2018-08-24 14:34:52 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-08-24 14:34:52 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-08-24 14:34:52 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-08-24 14:34:52 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-08-24 14:34:52 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-08-24 14:34:52 0 [Note] InnoDB: Waiting for purge to start
2018-08-24 14:34:52 0 [Note] InnoDB: 10.3.10 started; log sequence number 9959112; transaction id 150
2018-08-24 14:34:52 0 [Note] InnoDB: Creating #1 encryption thread id 140148355213056 total threads 4.
2018-08-24 14:34:52 0 [Note] InnoDB: Creating #2 encryption thread id 140148264134400 total threads 4.
2018-08-24 14:34:52 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var/1/mysqld.1/data/ib_buffer_pool
2018-08-24 14:34:52 0 [Note] InnoDB: Creating #3 encryption thread id 140148255741696 total threads 4.
2018-08-24 14:34:52 0 [Note] InnoDB: Creating #4 encryption thread id 140148247348992 total threads 4.
2018-08-24 14:34:52 0 [Note] InnoDB: Buffer pool(s) load completed at 180824 14:34:52
2018-08-24 14:34:52 0 [Note] Plugin 'SEQUENCE' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_CMP' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'user_variables' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2018-08-24 14:34:52 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2018-08-24 14:34:52 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2018-08-24 14:34:52 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2018-08-24 14:34:52 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2018-08-24 14:34:52 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
2018-08-24 14:34:52 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
180824 14:34:52 [ERROR] mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.3.10-MariaDB-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=5
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63172 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x49000
2018-08-24 14:38:53 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:38:53 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:38:53 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 240.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:39:12 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 65 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 260.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 259.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-08-24 14:39:24 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 272.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:39:24 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 271.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
2018-08-24 14:39:24 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 272.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:39:24 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 271.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:39:32 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 280.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 279.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
 
=====================================
2018-08-24 14:39:52 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 300.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 299.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-08-24 14:39:55 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 303.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:39:55 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 302.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
2018-08-24 14:39:55 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 303.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:39:55 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 302.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:40:12 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 320.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 319.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-08-24 14:40:26 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 334.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:40:26 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 333.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
2018-08-24 14:40:26 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 334.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:40:26 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 333.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:40:32 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 340.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 339.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
 
=====================================
2018-08-24 14:40:52 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 360.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 359.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-08-24 14:40:57 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 365.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:40:57 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 364.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
2018-08-24 14:40:57 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 365.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:40:57 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 364.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:41:12 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 380.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 379.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-08-24 14:41:28 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 396.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:41:28 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 395.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
2018-08-24 14:41:28 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 396.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:41:28 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 395.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:41:32 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 400.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 399.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
 
=====================================
2018-08-24 14:41:52 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 420.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 419.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-08-24 14:41:59 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 427.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:41:59 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 426.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
2018-08-24 14:41:59 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 427.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:41:59 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 426.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:42:12 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 440.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 439.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-08-24 14:42:30 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 458.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:42:30 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 457.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
2018-08-24 14:42:30 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 458.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:42:30 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 457.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:42:32 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 460.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 459.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
 
=====================================
2018-08-24 14:42:52 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 480.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 479.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-08-24 14:43:01 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 489.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:43:01 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 488.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
2018-08-24 14:43:01 0 [Note] InnoDB: A semaphore wait:
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 489.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
2018-08-24 14:43:01 0 [Note] InnoDB: A semaphore wait:
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 488.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 0, writes 0
 
=====================================
2018-08-24 14:43:12 0x7f76d86e1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3049
--Thread 140148371998464 has waited at buf0buf.cc line 4330 for 500.00 seconds the semaphore:
S-lock on RW-latch at 0x7f76ddcf78a8 created in file buf0buf.cc line 1638
a writer (thread id 0) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file buf0buf.cc line 5563
--Thread 140148439140096 has waited at srv0srv.cc line 2015 for 499.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x246f570 created in file dict0dict.cc line 1105
a writer (thread id 140148439140096) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffe
Last time write locked in file fts0fts.cc line 7157
OS WAIT ARRAY INFO: signal count 2020
RW-shared spins 0, rounds 153, OS waits 43
RW-excl spins 0, rounds 882, OS waits 8
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 153.00 RW-shared, 882.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 150
Purge done for trx's n:o < 147 undo n:o < 0 state: running
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
422 OS file reads, 1 OS file writes, 1 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 11 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
Hash table size 2267, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 9959121
Log flushed up to   0
Pages flushed up to 9959121
Last checkpoint at  9959112
1 pending log flushes, 0 pending chkp writes
7 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 10682368
Dictionary memory allocated 65970
Buffer pool size   511
Free buffers       0
Database pages     484
Old database pages 0
Modified db pages  131
Percent of dirty pages(LRU & free pages): 27.010
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 401, created 131, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 484, unzip_LRU len: 33
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22749, Main thread ID=140148439140096, state: enforcing dict cache limit
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
CURRENT_TEST: encryption.innodb_encryption_tables



 Comments   
Comment by Elena Stepanova [ 2018-10-01 ]

http://buildbot.askmonty.org/buildbot/builders/kvm-zyp-sles114-x86/builds/2626

encryption.innodb-page_encryption_log_encryption 'cbc,innodb' w3 [ fail ]
        Test ended at 2018-09-09 10:49:56
 
CURRENT_TEST: encryption.innodb-page_encryption_log_encryption
mysqltest: In included file "./include/wait_until_connected_again.inc": 
included from ./include/start_mysqld.inc at line 18:
included from ./include/restart_mysqld.inc at line 11:
included from /usr/share/mysql-test/suite/encryption/t/innodb-page_encryption_log_encryption.test at line 50:
At line 23: Server failed to restart
 
The result from queries just before the failure was:
< snip >
set current_num = 0;
while current_num < repeat_count do
insert into innodb_normal values(current_num, substring(MD5(RAND()), -64));
set current_num = current_num + 1;
end while;
end//
commit;
begin;
call innodb_insert_proc(2000);
insert into innodb_compact select * from innodb_normal;
insert into innodb_compressed select * from innodb_normal;
insert into innodb_dynamic select * from innodb_normal;
insert into innodb_redundant select * from innodb_normal;
commit;
SELECT variable_value > 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_encrypted';
variable_value > 0
1
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_decrypted';
variable_value >= 0
1
 
More results from queries before failure can be found in /dev/shm/var/3/log/innodb-page_encryption_log_encryption.log

Comment by Marko Mäkelä [ 2019-05-10 ]

At first, I was thinking if this InnoDB hang could be due to crash recovery encountered a corrupted page, which was fixed as part of MDEV-12699, but it is not the case, because both server log excerpts indicate that the hung restart was preceded by a normal clean shutdown.

Comment by Thirunarayanan Balathandayuthapani [ 2019-05-21 ]

let me put the analysis:

thread is waiting for block->lock in buf_wait_for_read() and it holds dict_sys->mutex
Master thread is waiting for dict_sys->mutex. Basically, we should find out what happens
to the block.

The general thing to note is that free list length is 0 according to elenst reported log
and srv_active is 0. So I assume that it happens after the restart but before user query execution.

valerii reported stack trace has a similar problem expect holding dict_sys->mutex.
The thing to note down here is that n_pending_reads are 13 and aio pending reads are 13.
It could be a problem with aio event processing. srv_active is 3 and the problem appears 6hrs after
the server startup, So it mostly used by read query.

Comment by Thirunarayanan Balathandayuthapani [ 2019-06-18 ]

I put the analysis in the comment. There is no FTS, compression table involved.
Basically, purge thread is waiting for block->lock. Other threads are waiting for
dict_operation_lock which was held by purge thread.

If you can able to repeat it then it will be a great help for me to analyse the failure.
You can even try it on 10.3.10 version.

Comment by Matthias Leich [ 2019-06-19 ]

Up till now all attempts to replay the current bug based on
- 10.3.10 b9a5ff364466d2d1495352dd6c932d877923a61
- innodb_encryption_tables.test or shrinked derivates of it
- an environment with no up till extreme artificial CPU and/or IO load
failed.  Most tests pass and some small fraction replays
https://jira.mariadb.org/browse/MDEV-13644

Comment by Marko Mäkelä [ 2020-10-17 ]

elenst, I believe that MDEV-23456 could have fixed this. Are there any recent failures of this kind? The buildbot cross-reference did not find anything.

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