最近有一個接口偶然出現超時報500的情況，通過服務后台log，發現以下錯誤，說白了就是在更新mysql的時候，獲取排它鎖超時導致更新失敗了。
org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: PreparedStatementCallback; SQL [UPDATE news SET news.quality = ? WHERE news.pk = ?]; Lock wait timeout exceeded; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
exception的堆棧如下：
這是什么原因呢？我在想，會不會是代碼在同一個事務里面有死鎖的情況，於是查看了代碼，發現代碼使用的是spring“聲明式”事務，該接口的業務層面不會發生死鎖的情況。
於是我想，會不會是和其他的事務有交叉加鎖而導致死鎖呢？於是通過mysql的“show engine innodb status;”語句把最近的死鎖信息copy出來檢查了一遍，發現最近的“LATEST DETECTED DEADLOCK”的相關數據里面並沒有和news表相關的dead lock，那說明可能不是死鎖導致的。
於是我想着去服務器看下報錯的那個時間附近有沒有相關的慢查詢，通過耗時和時間過濾，一看，果然，報錯的附近時間剛好有一個很慢的慢查詢，如下圖最后一行，耗時達到了57s，掃描了六千多萬行記錄，嚇我一跳，如下圖：
上圖的第一行，就是報錯接口業務層執行的更新語句，說明接口在更新mysql的時候，等待了51s，還沒競爭到鎖，所以失敗了。但是那個慢查詢是select類型的語句，根據mysql的mvvc樂觀鎖，不應該鎖表才對啊，於是猜測可能是同一個事物里面，包含了update的語句以及該慢查詢。這個事務先是update news表，這時候鎖住相關記錄，然后再執行這個慢查詢，等慢查詢結束之后，才釋放鎖，那就說明確實是這個慢查詢的長事務導致的。於是根據這個sql的來源ip，原來是大數據團隊的sql，通過大數據團隊的確認，確實是猜想的那樣，有個長事務，在同一個事務里面，先是update了news表，然后執行了上面的慢查詢。於是讓大數據團隊趕緊優化sql，優化sql之后，持續跟蹤了一段時間，發現這個問題不在出現。
這里還有一個小問題，上面的報錯接口業務執行的update語句，為什么是持續競爭鎖51s之后，就報錯了呢？mysql的innodb引擎是有個事務鎖超時的時間的，通過以下語句可以查到：
# 查詢全局等待事務鎖超時時間 SHOW GLOBAL VARIABLES LIKE 'innodb_lock_wait_timeout'; # 查詢當前會話等待事務鎖超時時間 SHOW VARIABLES LIKE 'innodb_lock_wait_timeout';
通過查詢，mysql服務器的事務鎖超時時間剛好是50s，如下，和上面實際獲取鎖超時51s相差了1s，可能是有一定的誤差的吧。
innodb_lock_wait_timeout 50
謝謝觀賞~
歡迎關注微信公眾號“ismallboy”，請掃碼並關注以下公眾號，並在公眾號下面回復“lock”，獲得本文最新內容。
