在测试环境中，一条针对mysql表t_customer_info的SQL更新语句（根据id主键列更新记录）执行速度异常缓慢，只在更新id为1时出现这种情况，导致事务超时。已知表中数据量少，硬件配置良好，没有锁等待。通过show profiles和explain等信息，发现只有该语句在执行，且存在等待锁的情况。
近期公司的新项目的测试环境的mysql环境,一条sql根据id列(主键)更新一条记录,速度奇慢.找不到原因,请大家帮忙分析下.
硬件
ibm x3550 8g内存
mysql 5.6.21 x64 单机
基本上没有负载,表的情况,大概只有不到100行的数据.
这个是当时执行的sql
id为自增长的主键列
update t_customer_info set update_time='2014-11-17 12:25:30' where id=1;
当更新id为1时,语句执行时间超过默认设定50秒的事务超时时间,报错.但奇葩的是，条件为其他的id值得时候，更新就是毫秒级别的。
当时show processlist，没有任何锁的情况。只有这一条语句在执行。
下面是相关信息，求明白的朋友帮忙分析下，为何只有根据id=1时更新速度会奇慢。
mysql> update t_customer_info set update_time='2014-11-17 12:25:30' where id=1;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
mysql> show profiles;
+----------+-------------+-------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+-------------------------------------------------------------------------+
| 1 | 0.00014150 | start transaction |
| 2 | 51.00503625 | update t_customer_info set update_time='2014-11-17 12:25:30' where id=1 |
+----------+-------------+-------------------------------------------------------------------------+
2 rows in set, 1 warning (0.00 sec)
mysql> show profile;
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| starting | 0.000062 |
| checking permissions | 0.000008 |
| Opening tables | 0.000030 |
| init | 0.000033 |
| System lock | 0.000054 |
| updating | 51.004749 |
| end | 0.000030 |
| query end | 0.000010 |
| closing tables | 0.000013 |
| freeing items | 0.000035 |
| cleaning up | 0.000014 |
+----------------------+-----------+
11 rows in set, 1 warning (0.00 sec)
---------------------
explain
mysql> explain update t_customer_info set update_time='2014-11-17 12:25:12' where id=1;
+----+-------------+-----------------+-------+---------------+---------+---------+-------+------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+-----------------+-------+---------------+---------+---------+-------+------+-------------+
| 1 | SIMPLE | t_customer_info | range | PRIMARY | PRIMARY | 8 | const | 1 | Using where |
+----+-------------+-----------------+-------+---------------+---------+---------+-------+------+-------------+
---------------------
当时innodb status
[BEGIN] 2014/11/17 12:37:41
show engine innodb status\G
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2014-11-17 12:35:36 7f10c87ac700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 57 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 300 srv_active, 0 srv_shutdown, 234460 srv_idle
srv_master_thread log flush and writes: 234760
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 346
OS WAIT ARRAY INFO: signal count 349
Mutex spin waits 99, rounds 475, OS waits 11
RW-shared spins 334, rounds 10020, OS waits 334
RW-excl spins 0, rounds 51, OS waits 1
Spin rounds per wait: 4.80 mutex, 30.00 RW-shared, 51.00 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 75681
Purge done for trx's n
< 75677 undo n
< 0 state: running but idle
History list length 1009
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 264, OS thread handle 0x7f10c87ac700, query id 83102 localhost root init
show engine innodb status
---TRANSACTION 75677, not started
MySQL thread id 224, OS thread handle 0x7f10cb1a5700, query id 83099 172.16.17.25 root cleaning up
---TRANSACTION 75658, not started
MySQL thread id 261, OS thread handle 0x7f10c882e700, query id 82882 172.16.29.221 thinkgem cleaning up
---TRANSACTION 75672, not started
MySQL thread id 262, OS thread handle 0x7f10cb470700, query id 82949 172.16.29.221 thinkgem cleaning up
---TRANSACTION 75625, not started
MySQL thread id 259, OS thread handle 0x7f10cb4f2700, query id 82636 172.16.29.221 thinkgem cleaning up
---TRANSACTION 0, not started
MySQL thread id 223, OS thread handle 0x7f10cb3ad700, query id 83098 172.16.17.25 root cleaning up
---TRANSACTION 75285, not started
MySQL thread id 212, OS thread handle 0x7f10cb227700, query id 81591 172.16.29.217 thinkgem cleaning up
---TRANSACTION 75284, not started
MySQL thread id 217, OS thread handle 0x7f10cb678700, query id 81586 172.16.29.217 thinkgem cleaning up
---TRANSACTION 75661, not started
MySQL thread id 173, OS thread handle 0x7f10cb5f6700, query id 82899 172.16.29.221 p2p_oper cleaning up
---TRANSACTION 75200, not started
MySQL thread id 172, OS thread handle 0x7f10cb32b700, query id 81681 172.16.29.185 root cleaning up
---TRANSACTION 73926, not started
MySQL thread id 169, OS thread handle 0x7f10cb268700, query id 73059 172.16.29.67 p2p_oper cleaning up
---TRANSACTION 74711, not started
MySQL thread id 165, OS thread handle 0x7f10cb2ea700, query id 78641 172.16.29.197 p2p_oper cleaning up
---TRANSACTION 75232, not started
MySQL thread id 162, OS thread handle 0x7f10cb574700, query id 81219 172.16.17.34 p2p_oper cleaning up
---TRANSACTION 0, not started
MySQL thread id 60, OS thread handle 0x7f10cb1e6700, query id 66952 172.16.17.25 root cleaning up
---TRANSACTION 75680, ACTIVE 5 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 225, OS thread handle 0x7f10cb6b9700, query id 83101 localhost root updating
update t_customer_info set update_time='2014-11-17 12:25:30' where id=1
------- TRX HAS BEEN WAITING 5 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 101 page no 3 n bits 120 index `PRIMARY` of table `p2p`.`t_customer_info` trx id 75680 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 49; compact format; info bits 0
0: len 8; hex 8000000000000001; asc ;;
1: len 6; hex 000000012612; asc & ;;
2: len 7; hex 6f0000021a062f; asc o /;;
3: len 16; hex 6675777566656940373631312e636f6d; asc fuwufei@7611.com;;
4: len 1; hex 81; asc ;;
5: len 3; hex 8fbd49; asc I;;
6: len 11; hex 3133383130323137333531; asc 13810217351;;
7: len 1; hex 80; asc ;;
8: len 6; hex e7a195e5a3ab; asc ;;
9: len 18; hex 313130313038313938383131313031323334; asc 110108198811101234;;
10: len 2; hex 3031; asc 01;;
11: len 1; hex 80; asc ;;
12: len 1; hex 80; asc ;;
13: len 1; hex 86; asc ;;
14: SQL NULL;
15: SQL NULL;
16: SQL NULL;
17: SQL NULL;
18: len 1; hex 80; asc ;;
19: SQL NULL;
20: SQL NULL;
21: SQL NULL;
22: SQL NULL;
23: SQL NULL;
24: len 8; hex 8000000000000000; asc ;;
25: len 8; hex 80000f355c000000; asc 5\ ;;
26: len 8; hex 80000f355c000000; asc 5\ ;;
27: len 8; hex 8000000000000000; asc ;;
28: len 8; hex 8000005eec000000; asc ^ ;;
29: len 8; hex 8000000000000000; asc ;;
30: len 8; hex 8000000000000000; asc ;;
31: SQL NULL;
32: SQL NULL;
33: len 4; hex 80000001; asc ;;
34: len 5; hex 999414f710; asc ;;
35: len 5; hex 999462bcc8; asc b ;;
36: len 8; hex 8000000000000001; asc ;;
37: len 8; hex 8000000000000001; asc ;;
38: len 30; hex 653130616463333934396261353961626265353665303537663230663838; asc e10adc3949ba59abbe56e057f20f88; (total 32 bytes);
39: len 4; hex 80000001; asc ;;
40: len 1; hex 30; asc 0;;
41: len 4; hex 80000000; asc ;;
42: len 3; hex e7868a; asc ;;
43: len 1; hex 80; asc ;;
44: SQL NULL;
45: SQL NULL;
46: SQL NULL;
47: len 1; hex 80; asc ;;
48: len 1; hex 80; asc ;;
------------------
---TRANSACTION 75282, ACTIVE 2813 sec
3 lock struct(s), heap size 360, 1 row lock(s), undo log entries 2
MySQL thread id 213, OS thread handle 0x7f10c886f700, query id 81561 172.16.29.217 thinkgem cleaning up
--------
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, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1187 OS file reads, 4880 OS file writes, 3736 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, 6 merges
merged operations:
insert 12, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 4730647, node heap has 3 buffer(s)
0.02 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 16741527
Log flushed up to 16741527
Pages flushed up to 16741527
Last checkpoint at 16741527
0 pending log writes, 0 pending chkp writes
1287 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 2197815296; in additional pool allocated 0
Dictionary memory allocated 634665
Buffer pool size 131064
Free buffers 129919
Database pages 1142
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1079, created 63, written 2494
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 1142, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size 16383
Free buffers 16194
Database pages 188
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 183, created 5, written 678
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: 188, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size 16383
Free buffers 16278
Database pages 104
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 101, created 3, written 142
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: 104, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size 16383
Free buffers 16298
Database pages 84
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 84, created 0, written 171
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: 84, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size 16383
Free buffers 16221
Database pages 162
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 162, created 0, written 239
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: 162, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size 16383
Free buffers 16214
Database pages 169
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 167, created 2, written 363
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: 169, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size 16383
Free buffers 16217
Database pages 166
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 165, created 1, written 292
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 166, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size 16383
Free buffers 16248
Database pages 135
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 102, created 33, written 276
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: 135, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size 16383
Free buffers 16249
Database pages 134
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 115, created 19, written 333
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: 134, unzip_LRU len: 0
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
Main thread process no. 26999, id 139710143153920, state: sleeping
Number of rows inserted 6990, updated 507, deleted 12, read 2395623
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 row in set (0.00 sec)
mysql>
[END] 2014/11/17 12:38:03
扫一扫
1898
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
