Description:
innodb_version : 5.7.11
version: 5.7.11
version_compile_machine: x86_64
version_compile_os: Linux
# thread insert sql is hang , time is 39197
(user:root time: 10:45)[db: (none)] select left(INFO,'100') ,id,host,USER,time,state from information_schema.PROCESSLIST where COMMAND <> 'Sleep'\G
*************************** 1. row ***************************
left(INFO,'100'): select left(INFO,'100') ,id,host,USER,time,state from information_schema.PROCESSLIST where COMMAND <
id: 41826
host:
USER: root
time: 0
state: executing
*************************** 2. row ***************************
left(INFO,'100'): INSERT INTO `t_user_a` VALUES (239747817,'123asdadsqwe123',NULL,NULL,'iPhon
id: 5922
host:
USER: root
time: 39197
state: update
2 rows in set (0.01 sec)
# master thread state: making checkpoint
# scn not change..
#
(user:root time: 10:31)[db: information_schema] show engine innodb status\G
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2016-04-05 10:31:32 0x7f4b8c28a700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 170 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 83150 srv_active, 0 srv_shutdown, 4294 srv_idle
srv_master_thread log flush and writes: 87444
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3137945
OS WAIT ARRAY INFO: signal count 3445201
RW-shared spins 0, rounds 5327382, OS waits 1811369
RW-excl spins 0, rounds 4755999, OS waits 201116
RW-sx spins 250310, rounds 1387334, OS waits 19409
Spin rounds per wait: 5327382.00 RW-shared, 4755999.00 RW-excl, 5.54 RW-sx
------------
TRANSACTIONS
------------
---TRANSACTION 918320, ACTIVE 38331 sec inserting /* 10 H */
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 841
MySQL thread id 5922, OS thread handle 139962722412288, query id 654838 127.0.0.1 root update
INSERT INTO `t_user_a` VALUES (239747817,' /* ....... */
---
LOG
---
Log sequence number 1404873811472
Log flushed up to 1404871162017
Pages flushed up to 1400500360367
Last checkpoint at 1400467300720
1 pending log flushes, 0 pending chkp writes
375335 log i/o's done, 0.00 log i/o's/second
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=12019, Main thread ID=139962764973824, state: making checkpoint
Number of rows inserted 2898973416, updated 0, deleted 0, read 47081
0.04 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.04 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
# pstack check mysqld pis but not active thread
[root@host191 ~]# pstack 12019
Thread 2 (LWP 5743):
#0 0x000000391160b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000dac90b in Per_thread_connection_handler::block_until_new_connection() ()
#2 0x0000000000daca86 in handle_connection ()
#3 0x00000000011c24c1 in pfs_spawn_thread ()
#4 0x0000003911607a51 in start_thread () from /lib64/libpthread.so.0
#5 0x00000039112e893d in clone () from /lib64/libc.so.6
Thread 1 (LWP 12019):
#0 0x00000039112df113 in poll () from /lib64/libc.so.6
#1 0x0000000000dadf19 in Mysqld_socket_listener::listen_for_connection_event() ()
#2 0x00000000007930e2 in mysqld_main(int, char**) ()
#3 0x000000391121ed5d in __libc_start_main () from /lib64/libc.so.6
#4 0x0000000000788d01 in _start ()
[root@host191 ~]# strace -p 12019 -f -c
Process 12019 attached with 21 threads
.....
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
99.13 0.457929 1413 324 io_getevents
0.43 0.002000 667 3 futex
0.43 0.002000 2000 1 restart_syscall
0.00 0.000000 0 1 read
0.00 0.000000 0 1 open
0.00 0.000000 0 2 close
0.00 0.000000 0 1 1 stat
0.00 0.000000 0 3 poll
0.00 0.000000 0 3 madvise
0.00 0.000000 0 1 accept
0.00 0.000000 0 4 sendto
0.00 0.000000 0 11 3 recvfrom
0.00 0.000000 0 1 shutdown
0.00 0.000000 0 1 getpeername
0.00 0.000000 0 2 setsockopt
0.00 0.000000 0 1 gettid
------ ----------- ----------- --------- --------- ----------------
100.00 0.461929 360 4 total
How to repeat:
1.get sql file
mysqldump -uroot --default-character-set=utf8 --quick --single-transaction --hex-blob \
--routines --triggers --events database1 |gzip --fast > db1.sql.gz
2.exec sql to mysql
zcat db1.sql.gz | mysql -uroot database1 &>/dev/null &
3. wait rand long time
4.show processlist # time is long and sql not change
Command: Query
Time: 40255
State: update
Description: innodb_version : 5.7.11 version: 5.7.11 version_compile_machine: x86_64 version_compile_os: Linux # thread insert sql is hang , time is 39197 (user:root time: 10:45)[db: (none)] select left(INFO,'100') ,id,host,USER,time,state from information_schema.PROCESSLIST where COMMAND <> 'Sleep'\G *************************** 1. row *************************** left(INFO,'100'): select left(INFO,'100') ,id,host,USER,time,state from information_schema.PROCESSLIST where COMMAND < id: 41826 host: USER: root time: 0 state: executing *************************** 2. row *************************** left(INFO,'100'): INSERT INTO `t_user_a` VALUES (239747817,'123asdadsqwe123',NULL,NULL,'iPhon id: 5922 host: USER: root time: 39197 state: update 2 rows in set (0.01 sec) # master thread state: making checkpoint # scn not change.. # (user:root time: 10:31)[db: information_schema] show engine innodb status\G *************************** 1. row *************************** Type: InnoDB Name: Status: ===================================== 2016-04-05 10:31:32 0x7f4b8c28a700 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 170 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 83150 srv_active, 0 srv_shutdown, 4294 srv_idle srv_master_thread log flush and writes: 87444 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 3137945 OS WAIT ARRAY INFO: signal count 3445201 RW-shared spins 0, rounds 5327382, OS waits 1811369 RW-excl spins 0, rounds 4755999, OS waits 201116 RW-sx spins 250310, rounds 1387334, OS waits 19409 Spin rounds per wait: 5327382.00 RW-shared, 4755999.00 RW-excl, 5.54 RW-sx ------------ TRANSACTIONS ------------ ---TRANSACTION 918320, ACTIVE 38331 sec inserting /* 10 H */ mysql tables in use 1, locked 1 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 841 MySQL thread id 5922, OS thread handle 139962722412288, query id 654838 127.0.0.1 root update INSERT INTO `t_user_a` VALUES (239747817,' /* ....... */ --- LOG --- Log sequence number 1404873811472 Log flushed up to 1404871162017 Pages flushed up to 1400500360367 Last checkpoint at 1400467300720 1 pending log flushes, 0 pending chkp writes 375335 log i/o's done, 0.00 log i/o's/second -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 0 read views open inside InnoDB Process ID=12019, Main thread ID=139962764973824, state: making checkpoint Number of rows inserted 2898973416, updated 0, deleted 0, read 47081 0.04 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.04 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================ # pstack check mysqld pis but not active thread [root@host191 ~]# pstack 12019 Thread 2 (LWP 5743): #0 0x000000391160b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000dac90b in Per_thread_connection_handler::block_until_new_connection() () #2 0x0000000000daca86 in handle_connection () #3 0x00000000011c24c1 in pfs_spawn_thread () #4 0x0000003911607a51 in start_thread () from /lib64/libpthread.so.0 #5 0x00000039112e893d in clone () from /lib64/libc.so.6 Thread 1 (LWP 12019): #0 0x00000039112df113 in poll () from /lib64/libc.so.6 #1 0x0000000000dadf19 in Mysqld_socket_listener::listen_for_connection_event() () #2 0x00000000007930e2 in mysqld_main(int, char**) () #3 0x000000391121ed5d in __libc_start_main () from /lib64/libc.so.6 #4 0x0000000000788d01 in _start () [root@host191 ~]# strace -p 12019 -f -c Process 12019 attached with 21 threads ..... % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 99.13 0.457929 1413 324 io_getevents 0.43 0.002000 667 3 futex 0.43 0.002000 2000 1 restart_syscall 0.00 0.000000 0 1 read 0.00 0.000000 0 1 open 0.00 0.000000 0 2 close 0.00 0.000000 0 1 1 stat 0.00 0.000000 0 3 poll 0.00 0.000000 0 3 madvise 0.00 0.000000 0 1 accept 0.00 0.000000 0 4 sendto 0.00 0.000000 0 11 3 recvfrom 0.00 0.000000 0 1 shutdown 0.00 0.000000 0 1 getpeername 0.00 0.000000 0 2 setsockopt 0.00 0.000000 0 1 gettid ------ ----------- ----------- --------- --------- ---------------- 100.00 0.461929 360 4 total How to repeat: 1.get sql file mysqldump -uroot --default-character-set=utf8 --quick --single-transaction --hex-blob \ --routines --triggers --events database1 |gzip --fast > db1.sql.gz 2.exec sql to mysql zcat db1.sql.gz | mysql -uroot database1 &>/dev/null & 3. wait rand long time 4.show processlist # time is long and sql not change Command: Query Time: 40255 State: update