2018-09-10T10:13:33.779770Z 0 [Warning] InnoDB: A long semaphore wait: --Thread 140114698192640 has waited at srv0srv.cc line 2330 for 244.00 seconds the semaphore: 2018-09-10T10:13:34.966424Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5862ms. The settings might not be optimal. (flushed=6, during the time.) X-lock on RW-latch at 0x2c83188 created in file dict0dict.cc line 1198 number of readers 0, waiters flag 0, lock_word: 20000000 Last time read locked in file row0purge.cc line 865 Last time write locked in file /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/ubuntu-xenial-64bit/percona-server-5.7-5.7.19-17/storage/innobase/dict/dict0stats.cc line 2375 InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 2018-09-10T10:13:50.874730Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4082ms. The settings might not be optimal. (flushed=3, during the time.) ===================================== 2018-09-10 11:13:53 0x7f6eff505700 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 81 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 31673 srv_active, 0 srv_shutdown, 8691 srv_idle srv_master_thread log flush and writes: 40359 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 176873 --Thread 140114653017856 has waited at que0que.cc line 1248 for 3.00 seconds the semaphore: Mutex at 0x2c832e8, Mutex DICT_SYS created dict0dict.cc:1183, lock var 1 OS WAIT ARRAY INFO: signal count 701481 RW-shared spins 0, rounds 1425502, OS waits 92141 RW-excl spins 0, rounds 3276109, OS waits 21740 RW-sx spins 183549, rounds 2774050, OS waits 15359 Spin rounds per wait: 1425502.00 RW-shared, 3276109.00 RW-excl, 15.11 RW-sx ------------ TRANSACTIONS ------------ Trx id counter 552301135 Purge done for trx's n:o < 552300639 undo n:o < 0 state: running but idle History list length 151 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421590992179872, not started mysql tables in use 1, locked 0 0 lock struct(s), heap size 1136, 0 row lock(s) MySQL thread id 263723, OS thread handle 140114653218560, query id 12102594 xxx.xxx.xxx.xxx xx Sending data SELECT * FROM `xxx`.xxx WHERE xxx="xxxx" ---TRANSACTION 421590992201472, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992200272, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992199072, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992193072, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992183472, not started2018-09-10T10:14:07.525450Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 12925ms. The settings might not be optimal. (flushed=11, during the time.) InnoDB: ###### Diagnostic info printed to the standard error stream 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992170272, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992182272, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992166672, not started mysql tables in use 1, locked 0 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992160672, not started mysql tables in use 1, locked 0 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992164272, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992188272, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992184672, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992181072, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992176272, not started inserting mysql tables in use 1, locked 1 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992173872, not started inserting mysql tables in use 1, locked 1 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992172672, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992167872, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992194272, not started inserting mysql tables in use 1, locked 1 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992171472, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992175072, not started inserting mysql tables in use 1, locked 1 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992169072, not started inserting mysql tables in use 1, locked 1 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992161872, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992158272, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421590992159472, not started 0 lock struct(s), heap size 1136, 0 row lock(s) -------- 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 (read thread) I/O thread 5 state: waiting for completed aio requests (read thread) I/O thread 6 state: waiting for completed aio requests (write thread) I/O thread 7 state: waiting for completed aio requests (write thread) I/O thread 8 state: waiting for completed aio requests (write thread) I/O thread 9 state: waiting for completed aio requests (write thread) Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] , ibuf aio reads:, log i/o's:, sync i/o's: Pending flushes (fsync) log: 0; buffer pool: 0 172922 OS file reads, 5088965 OS file writes, 3767579 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 1.04 writes/s, 0.88 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 117, seg size 119, 7653 merges merged operations: insert 19380, delete mark 4024, delete 1366 discarded operations: insert 0, delete mark 0, delete 0 Hash table size 276671, node heap has 134 buffer(s) Hash table size 276671, node heap has 424 buffer(s) Hash table size 276671, node heap has 1097 buffer(s) Hash table size 276671, node heap has 704 buffer(s) Hash table size 276671, node heap has 334 buffer(s) Hash table size 276671, node heap has 336 buffer(s) Hash table size 276671, node heap has 1066 buffer(s) Hash table size 276671, node heap has 141 buffer(s) 4.91 hash searches/s, 2.95 non-hash searches/s --- LOG --- Log sequence number 271672974462 Log flushed up to 271672974462 Pages flushed up to 271672974375 Last checkpoint at 271672972156 Max checkpoint age 80826164 Checkpoint age target 78300347 Modified age 87 Checkpoint age 2306 0 pending log flushes, 0 pending chkp writes 3486222 log i/o's done, 0.29 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total large memory allocated 1117782016 Dictionary memory allocated 308212366 Internal hash tables (constant factor + variable factor) Adaptive hash index 87143232 (17706944 + 69436288) Page hash 1107112 (buffer pool 0 only) Dictionary cache 312636470 (4426736 + 308209734) File system 41392000 (812272 + 40579728) Lock system 2696936 (2657176 + 39760) Recovery system 0 (0 + 0) Buffer pool size 65528 Buffer pool size, bytes 1073610752 Free buffers 1024 Database pages 60268 Old database pages 22227 Modified db pages 1 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 54473, not young 1949390 0.00 youngs/s, 0.00 non-youngs/s Pages read 109605, created 10249, written 1560327 0.00 reads/s, 0.00 creates/s, 0.65 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 2018-09-10T10:14:44.931523Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 12679ms. The settings might not be optimal. (flushed=16, during the time.) Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 60268, unzip_LRU len: 0 I/O sum[60]:cur[0], unzip sum[0]:cur[0] -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 8 read views open inside InnoDB 0 RW transactions active inside InnoDB ---OLDEST VIEW--- Read view low limit trx n:o 552300637 Trx read view will not see trx with id >= 552300637, sees < 552300636 Read view individually stored trx ids: Read view trx id 552300636 ----------------- Process ID=60823, Main thread ID=140114698192640, state: sleeping Number of rows inserted 3978680, updated 531822, deleted 3035128, read 2567406895 0.16 inserts/s, 0.07 updates/s, 0.01 deletes/s, 19.35 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================ 2018-09-10T10:15:05.266616Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4057ms. The settings might not be optimal. (flushed=4, during the time.) 2018-09-10T10:15:16.166679Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5841ms. The settings might not be optimal. (flushed=7, during the time.) 2018-09-10T10:15:29.674051Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 10686ms. The settings might not be optimal. (flushed=13, during the time.) ... 2018-09-10T10:29:45.094563Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5916ms. The settings might not be optimal. (flushed=7, during the time.) 2018-09-10T10:30:14.830827Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2018-09-10T10:30:14.830951Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release. 2018-09-10T10:30:14.836596Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.19-17) starting as process 930 ... 2018-09-10T10:30:14.926525Z 0 [Note] InnoDB: PUNCH HOLE support available 2018-09-10T10:30:14.926548Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2018-09-10T10:30:14.926573Z 0 [Note] InnoDB: Uses event mutexes 2018-09-10T10:30:14.926576Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2018-09-10T10:30:14.926579Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8 2018-09-10T10:30:14.926582Z 0 [Note] InnoDB: Using Linux native AIO 2018-09-10T10:30:14.929610Z 0 [Note] InnoDB: Number of pools: 1 2018-09-10T10:30:14.938571Z 0 [Note] InnoDB: Using CPU crc32 instructions 2018-09-10T10:30:14.940460Z 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 1, chunk size = 128M 2018-09-10T10:30:14.984931Z 0 [Note] InnoDB: Completed initialization of buffer pool 2018-09-10T10:30:15.000805Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2018-09-10T10:30:15.042020Z 0 [Note] InnoDB: Recovering partial pages from the parallel doublewrite buffer at /mnt/data1/mysql-data/xb_doublewrite 2018-09-10T10:30:15.063548Z 0 [Note] InnoDB: Opened 6 undo tablespaces 2018-09-10T10:30:15.063572Z 0 [Note] InnoDB: 6 undo tablespaces made active 2018-09-10T10:30:15.064029Z 0 [Note] InnoDB: Highest supported file format is Barracuda. 2018-09-10T10:30:15.178240Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 271673072456 2018-09-10T10:30:15.178269Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 271673081960 2018-09-10T10:30:15.245247Z 0 [Note] InnoDB: Database was not shutdown normally! 2018-09-10T10:30:15.245270Z 0 [Note] InnoDB: Starting crash recovery. 2018-09-10T10:30:15.431816Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /mnt/data1/mysql-data/xb_doublewrite, size 3932160 bytes 2018-09-10T10:30:15.681079Z 0 [Note] InnoDB: 2 transaction(s) which must be rolled back or cleaned up in total 13 row operations to undo 2018-09-10T10:30:15.681103Z 0 [Note] InnoDB: Trx id counter is 552301824 2018-09-10T10:30:15.681915Z 0 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 2018-09-10T10:30:16.237592Z 0 [Note] InnoDB: Apply batch completed 2018-09-10T10:32:31.570500Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions 2018-09-10T10:32:31.571733Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" 2018-09-10T10:32:31.580439Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2018-09-10T10:32:31.580441Z 0 [Note] InnoDB: Rolling back trx with id 552301514, 1 rows to undo 2018-09-10T10:32:31.580509Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2018-09-10T10:32:31.626958Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2018-09-10T10:32:31.626961Z 0 [Note] InnoDB: Rollback of trx with id 552301514 completed 2018-09-10T10:32:31.627026Z 0 [Note] InnoDB: Rolling back trx with id 552301495, 12 rows to undo 2018-09-10T10:32:31.631035Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active. 2018-09-10T10:32:31.631051Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active. 2018-09-10T10:32:31.631146Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 136631ms. The settings might not be optimal. (flushed=0, during the time.) 2018-09-10T10:32:31.631274Z 0 [Note] InnoDB: Waiting for purge to start 2018-09-10T10:32:31.637277Z 0 [Note] InnoDB: Rollback of trx with id 552301495 completed 2018-09-10T10:32:31.637293Z 0 [Note] InnoDB: Rollback of non-prepared transactions completed 2018-09-10T10:32:31.681408Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.19-17 started; log sequence number 271673081960 2018-09-10T10:32:31.681594Z 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/data1/mysql-data/ib_buffer_pool 2018-09-10T10:32:31.686141Z 0 [Note] Plugin 'FEDERATED' is disabled. 2018-09-10T10:32:31.715539Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them. 2018-09-10T10:32:31.718797Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory. 2018-09-10T10:32:31.723082Z 0 [Warning] CA certificate ca.pem is self signed. 2018-09-10T10:32:31.723123Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory. 2018-09-10T10:32:31.725378Z 0 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306 2018-09-10T10:32:31.726519Z 0 [Note] - '0.0.0.0' resolves to '0.0.0.0'; 2018-09-10T10:32:31.726549Z 0 [Note] Server socket created on IP: '0.0.0.0'. 2018-09-10T10:32:31.806242Z 0 [Note] Event Scheduler: Loaded 0 events 2018-09-10T10:32:31.806416Z 0 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.7.19-17' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Percona Server (GPL), Release '17', Revision 'e19a6b7b73f' 2018-09-10T10:32:31.806431Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check. 2018-09-10T10:32:31.806434Z 0 [Note] Beginning of list of non-natively partitioned tables 2018-09-10T10:32:40.768106Z 0 [Note] End of list of non-natively partitioned tables 2018-09-10T10:32:40.953521Z 0 [Note] InnoDB: Buffer pool(s) load completed at 180910 11:32:40