===================================== 2019-05-15 19:31:18 0x1764 INNODB MONITOR OUTPUT
Per second averages calculated from the last 20 seconds
BACKGROUND THREAD
srv_master_thread loops: 137 srv_active, 0 srv_shutdown, 8488 srv_idle srv_master_thread log flush and writes: 8625
SEMAPHORES
OS WAIT ARRAY INFO: reservation count 247 OS WAIT ARRAY INFO: signal count 221 RW-shared spins 0, rounds 174, OS waits 95 RW-excl spins 0, rounds 296, OS waits 9 RW-sx spins 1, rounds 7, OS waits 0 Spin rounds per wait: 174.00 RW-shared, 296.00 RW-excl, 7.00 RW-sx
TRANSACTIONS
Trx id counter 29703html
Purge done for trx's n:o < 29697 undo n:o < 0 state: running but idlenode
History list length 84mysql
LIST OF TRANSACTIONS FOR EACH SESSION:sql
---TRANSACTION 281475151307376, not started 0 lock struct(s), heap size 1136, 0 row lock(s)數據庫
---TRANSACTION 281475151311736, not started 0 lock struct(s), heap size 1136, 0 row lock(s)服務器
---TRANSACTION 281475151310864, not started 0 lock struct(s), heap size 1136, 0 row lock(s)dom
---TRANSACTION 281475151309992, not started 0 lock struct(s), heap size 1136, 0 row lock(s)tcp
---TRANSACTION 281475151309120, not started 0 lock struct(s), heap size 1136, 0 row lock(s)ide
---TRANSACTION 281475151308248, not started 0 lock struct(s), heap size 1136, 0 row lock(s)oop
---TRANSACTION 281475151306504, not started 0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281475151305632, not started 0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281475151304760, not started 0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281475151303888, not started 0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281475151303016, not started 0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281475151302144, not started 0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281475151301272, not started 0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281475151300400, not started 0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 29699, ACTIVE 998 sec 1 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 28, OS thread handle 5988, query id 862 localhost 127.0.0.1 root starting show engine innodb status
---TRANSACTION 29658, ACTIVE 1539 sec 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 31, OS thread handle 3588, query id 696 localhost 127.0.0.1 root
FILE I/O
I/O thread 0 state: wait Windows aio (insert buffer thread) I/O thread 1 state: wait Windows aio (log thread) I/O thread 2 state: wait Windows aio (read thread) I/O thread 3 state: wait Windows aio (read thread) I/O thread 4 state: wait Windows aio (read thread) I/O thread 5 state: wait Windows aio (read thread) I/O thread 6 state: wait Windows aio (write thread) I/O thread 7 state: wait Windows aio (write thread) I/O thread 8 state: wait Windows aio (write thread) I/O thread 9 state: wait Windows aio (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 589 OS file reads, 1338 OS file writes, 327 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 34679, node heap has 0 buffer(s) Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s) Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s) Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s) Hash table size 34679, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
LOG
Log sequence number 27292033 Log flushed up to 27292033 Pages flushed up to 27292033 Last checkpoint at 27292024 0 pending log flushes, 0 pending chkp writes 213 log i/o's done, 0.00 log i/o's/second
BUFFER POOL AND MEMORY
Total large memory allocated 137297920 Dictionary memory allocated 107008 Buffer pool size 8192 Free buffers 7691 Database pages 501 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 386, created 115, written 1063 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: 501, 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 Process ID=1616, Main thread ID=1476, state: sleeping Number of rows inserted 2145, updated 0, deleted 11, read 2184 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
END OF INNODB MONITOR OUTPUT
排查 MySQL innodb Lock wait timeout exceeded; try restarting transaction的問題 OMG寫的時候崩潰了一次。
觸發關注這個問題的事情是 咱們在使用pt-online-schedule 改表的時候老是拿不到鎖，而且報出mysql innodb Lock wait timeout exceeded; try restarting transaction的問題，因此纔想到要排查。
首先最早想到的確定是
show processlist; 來查看當前正在運行的查詢 或者等待休眠中的查詢是哪些，包括使用了多少時間等，相似
複製代碼 *************************** 582. row *************************** Id: 7485594 User: xcf Host: cc:59580 db: xx Command: Query Time: 0 State: init Info: show processlist Rows_sent: 0 Rows_examined: 0 *************************** 583. row *************************** Id: 7485595 User: xcf Host: cc-19:42614 db: xx Command: Sleep Time: 0 State: Info: NULL Rows_sent: 0 Rows_examined: 0 複製代碼 可是能夠看到,當有不少任務在執行的時候，processlist將會很是大，想要從這裏面獲取對咱們有用的信息很是很是困難，最多也就簡單的看下，哪一個query耗時的確過長，會不會是由於事務沒有提交致使的拿不到鎖，來推測而且使用kill task_id來殺掉相應的task。
其次咱們若是有權限，可使用能看到相對來講更爲複雜和詳細的信息
SHOW ENGINE INNODB STATUS\G; 經過innodb status 提供的詳細的系統狀況來分析問題。
若是我沒沒有使用show engine innodb status的權限，退而求其次咱們可使用另一種思路來找到是哪一個表持續被鎖，致使拿不到鎖的問題。
show open tables where in_use>0; 查看如今系統正在使用的表，而後使用
show processlist; 查找正在query該表的任務，查看代碼是否有一直沒有提交事物，卻沒有commit的代碼，用這個思路來找問題出如今哪兒。
另外在mysql5.5以後，information_schema數據庫加了三個關於鎖的表。
innodb_trx ## 當前運行的全部事務 innodb_locks ## 當前出現的鎖 innodb_lock_waits ## 鎖等待的對應關係 備忘一下他們的表結構
複製代碼 mysql> desc information_schema.innodb_trx; +----------------------------+---------------------+------+-----+---------------------+-------+ | Field | Type | Null | Key | Default |Extra | +----------------------------+---------------------+------+-----+---------------------+-------+ | trx_id | varchar(18) | NO | | | | # 事務id | trx_state | varchar(13) | NO | | | | # 事務狀態 | trx_started | datetime | NO | | 0000-00-00 00:00:00 | | # 事務開始的時間 | trx_requested_lock_id | varchar(81) | YES | | NULL | | # 事務請求到鎖的id | trx_wait_started | datetime | YES | | NULL | | # 事務開始等待的時間 | trx_weight | bigint(21) unsigned | NO | | 0 | | # 事務權重 | trx_mysql_thread_id | bigint(21) unsigned | NO | | 0 | | # 事務線程的id | trx_query | varchar(1024) | YES | | NULL | | # 事務sql語句 | trx_operation_state | varchar(64) | YES | | NULL | | # 事務當前的操做狀態 | trx_tables_in_use | bigint(21) unsigned | NO | | 0 | | # 事務中有多少個表正在被使用 | trx_tables_locked | bigint(21) unsigned | NO | | 0 | | # 事務擁有多少個鎖 | trx_lock_structs | bigint(21) unsigned | NO | | 0 | | | trx_lock_memory_bytes | bigint(21) unsigned | NO | | 0 | | # 事務鎖住的內存大小 | trx_rows_locked | bigint(21) unsigned | NO | | 0 | | # 事務鎖住的行數 | trx_rows_modified | bigint(21) unsigned | NO | | 0 | | # 事務改變的行數 | trx_concurrency_tickets | bigint(21) unsigned | NO | | 0 | | | trx_isolation_level | varchar(16) | NO | | | | # 事務隔離等級 | trx_unique_checks | int(1) | NO | | 0 | | # 惟一鍵檢測 | trx_foreign_key_checks | int(1) | NO | | 0 | | # 外鍵檢測 | trx_last_foreign_key_error | varchar(256) | YES | | NULL | | | trx_adaptive_hash_latched | int(1) | NO | | 0 | | | trx_adaptive_hash_timeout | bigint(21) unsigned | NO | | 0 | | | trx_is_read_only | int(1) | NO | | 0 | | # 是不是隻讀事務 | trx_autocommit_non_locking | int(1) | NO | | 0 | | +----------------------------+---------------------+------+-----+---------------------+-------+ 複製代碼 這個表對於排查由於事務未提交引發的鎖問題能夠說是舉足輕重。當咱們有事務長時間未提交致使鎖住數據庫，其餘程序拿不到鎖的時候，由於對這張表進行排查。
好比咱們獲取一條記錄的線程id， 便可拿着該線程id去information_schma.processlist中獲取他的具體狀況。
複製代碼 mysql> select * from information_schema.processlist where id=701520; +--------+------+----------------+-----------+---------+------+-------+------+---------+-----------+---------------+ | ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | TIME_MS | ROWS_SENT | ROWS_EXAMINED | +--------+------+----------------+-----------+---------+------+-------+------+---------+-----------+---------------+ | 701520 | ppp | hazelnut:50308 | xxxxxxxxx | Sleep | 5492 | | NULL | 5492065 | 0 | 0 | +--------+------+----------------+-----------+---------+------+-------+------+---------+-----------+---------------+ 複製代碼 而後找到在佔用服務器50308端口的程序
netstat -nlatp |grep 50308 piperck@grape:~$ netstat -nlatp | grep 46698 (No info could be read for "-p": geteuid()=1025 but you should be root.) tcp 0 0 192.168.2.79:46698 192.168.2.83:3306 ESTABLISHED - 能夠看到協議 本機端口 去往mysql 也就是咱們起初的數據庫， 這裏 established後面 本正常會顯示佔用程序的pid -p參數能夠將其顯示出來。
接下來看下記錄鎖信息的表 innodb_locks
複製代碼 mysql> desc information_schema.innodb_locks; +-------------+---------------------+------+-----+---------+-------+ | Field | Type | Null | Key | Default | Extra | +-------------+---------------------+------+-----+---------+-------+ | lock_id | varchar(81) | NO | | | | # 鎖id | lock_trx_id | varchar(18) | NO | | | | # 擁有鎖的事務id | lock_mode | varchar(32) | NO | | | | # 鎖模式 | lock_type | varchar(32) | NO | | | | # 鎖類型 | lock_table | varchar(1024) | NO | | | | # 被鎖的表 | lock_index | varchar(1024) | YES | | NULL | | # 被鎖的索引 | lock_space | bigint(21) unsigned | YES | | NULL | | # 被鎖的表空間號 | lock_page | bigint(21) unsigned | YES | | NULL | | # 被鎖的頁號 | lock_rec | bigint(21) unsigned | YES | | NULL | | # 被鎖的記錄號 | lock_data | varchar(8192) | YES | | NULL | | # 被鎖的數據 +-------------+---------------------+------+-----+---------+-------+ 複製代碼 若是 咱們要排查的問題正鎖死咱們的某張表，那麼該表的數據表就會有所體現。同時和這個表使用的 還有information_schema.innodb_lock_waits
複製代碼 +-------------------+-------------+------+-----+---------+-------+ | Field | Type | Null | Key | Default | Extra | +-------------------+-------------+------+-----+---------+-------+ | requesting_trx_id | varchar(18) | NO | | | | # 請求鎖的事務id | requested_lock_id | varchar(81) | NO | | | | # 請求鎖的鎖id | blocking_trx_id | varchar(18) | NO | | | | # 擁有鎖的事務id | blocking_lock_id | varchar(81) | NO | | | | # 擁有鎖的鎖id +-------------------+-------------+------+-----+---------+-------+ 複製代碼 結合以上兩個表再查對應的信息 能夠說已經很方便了。那天出問題，我回家的時候就已經被解決了。我並無在線上環境嘗試過，可是模擬了幾回，使用這些辦法提供的線索都能解決問題，等我有機會解決線上問題的時候，再補一個詳細例子。
Reference:
http://stackoverflow.com/questions/5836623/getting-lock-wait-timeout-exceeded-try-restarting-transaction-even-though-im getting-lock-wait-timeout-exceeded-try-restarting-transaction-even-though-im http://blog.csdn.net/hw_libo/article/details/39080809 MySQL鎖阻塞分析 http://blog.sina.com.cn/s/blog_6bb63c9e0100s7cb.html MySQL innodb_lock_wait 鎖等待 http://dev.mysql.com/doc/refman/5.6/en/innodb-information-schema-understanding-innodb-locking.html mysql5.6官方文檔