隱藏了兩年的Bug,終于連根拔起,悲觀鎖并沒有那么簡單
接手的新項目,接二連三的出現賬不平的問題,作為程序員中比較執著的人,不解決誓不罷休。最終,經過兩次,歷時多日終于將其連根拔起。實屬不易,特寫篇文章記錄一下。
文章中不僅會講到使用悲觀鎖踩到的坑,以及本人是如何排查問題的,某些思路和方法或許能對大家有所幫助。
事情的起源
運營同事時不時就提出查賬調賬的需求,原因很簡單,賬不平,不查不行。如果你有過財務相關系統的工作經歷,賬務問題始終是最難攻克的。
雖然剛接手項目,雖然很多業務邏輯還不了解,但出現這樣的技術挑戰,還是要堅決攻克的。
其實,這類問題的原因很簡單:熱點賬戶。當很多服務或線程操作同一個用戶的賬戶時,就會出現一個更新把另外一個更新覆蓋掉的情況。
賬戶不平
上圖可輕易看出,當兩個服務或線程同時查詢數據庫的一條數據(熱點賬戶),然后內存中做修改,最后更新到數據庫。如果出現并發情況,兩個線程都讀取了100,一個計算得80,一個計算得60,后更新的就有可能將前面的覆蓋掉。
解決方案通常有:
- 單服務線程鎖;
- 集群分布式鎖;
- 集群數據庫悲觀鎖;
項目中已采用了悲觀鎖,就基于來進行排查追蹤原因。
何謂悲觀鎖
悲觀鎖是在對數據被的修改持悲觀態度,在整個數據處理過程中會將數據鎖定。
悲觀鎖的實現,往往依靠數據庫提供的鎖機制(也只有數據庫層提供的鎖機制才能真正保證數據訪問的排他性,否則,即使在應用層中實現了加鎖機制,也無法保證外部系統不會修改數據)。
通常會使用select ... for update語句來實現對數據的枷鎖。
for update僅適用于InnoDB,且必須在事務塊(BEGIN/COMMIT)中才能生效。在進行事務操作時,通過“for update”語句,MySQL會對查詢結果集中每行數據都添加排他鎖,其他線程對該記錄的更新與刪除操作都會阻塞。排他鎖包含行鎖、表鎖。
如下示例展示了悲觀鎖的基本使用流程:
- set autocommit=0;
- //設置完autocommit后,執行正常業務。具體如下:
- //0.開始事務
- begin;/begin work;/start transaction; (三者選一就可以)
- //1.查詢出商品信息
- select status from t_goods where id=1 for update;
- //2.根據商品信息生成訂單
- insert into t_orders (id,goods_id) values (null,1);
- //3.修改商品status為2
- update t_goods set status=2;
- //4.提交事務
- commit;/commit work;
因為關閉了數據庫自動提交,這里通過begin/commit來管理事務。
使用select…for update的方式通過數據庫實現了悲觀鎖。其中,id為1的那條數據就被鎖定,其它的事務必須等本次事務提交之后才能執行。這樣就保證了在操作期間數據不會被其它事務修改。
原因初步分析
在了解了賬不平的原因和悲觀鎖的基本原理之后,就可以進行問題的排查了。既然系統已經使用了悲觀鎖,竟然還會出現問題,那肯定是哪里漏掉了什么。
于是,排查了所有賬戶(account表)更新的地方,還真找到一處bug。
大多數地方都使用了悲觀鎖,先for update查詢一下,然后計算新的余額,再進行更新數據庫。但有一處竟然先查詢到了計算了余額,然后再進行加鎖,最后更新。
基本流程如下:
錯誤加鎖
在上述情況中,雖然線程B進行了加鎖處理,但由于計算新余額并未在鎖中,導致雖然使用了悲觀鎖,但依舊存在問題。正確的使用方式就是將計算余額的邏輯放在鎖中。
當然,如果線程B完全被遺忘加鎖了,也會出現同樣的問題。
在排查解決了上述bug,我開始嘚瑟了,以為徹底解決了賬不平的問題。
一個月之后
結果一個月之后,運營同事又來找了,偶爾依舊會出現賬不平的問題。剛開始我還以為是不是搞錯了,歷史的賬不平導致現在最終的不平。但最終還是下定決心再排查一次。
第一天,把賬不平的賬戶的賬務流水、涉及到代碼、日志全部捋一遍。這期間還遇到了很多小困難,最終注意克服。
困難一:數據查不動
賬務記錄表數據太多,上千萬的數據,最初的設計者并沒有創建索引。這就要了老命了,根據篩選條件根本查不出數據來。
這里就用到SQL優化的兩個技能點:limit限制查詢條數和高效的分頁策略。
關于limit限制查詢條件這一點很明顯,不僅減少了結果集,而且在遇到符合條件的數據之后會立馬返回。
高效的分頁策略在列表頁在查詢數據經常遇到,為了避免一次性返回過多的數據影響接口性能,一般會對查詢接口做分頁處理。
在Mysql中分頁一般用的limit關鍵字:
- select id,name,age from user limit 10,20;
少量數據時,limit分頁沒啥問題。但如果表中數據量很多,就會出現性能問題。
比如分頁參數變成了:
- select id,name,age from user limit 1000000,20;
Mysql會查到1000020條數據,然后丟棄前面的1000000條,只查后面的20條數據,非常浪費資源。
優化sql:
- select id,name,age from user where id > 1000000 limit 20;
當然還可以使用between優化分頁:
- select id,name,age
- from user where id between 1000000 and 1000020;
值得慶幸的是那張表的ID是自增的,于是用了id大于的條件,只差了最近的交易記錄,才勉強把數據查詢出來。
困難二:日志過多
由于系統日志打的比較詳細,一個項目每天大概幾個G的日志。要在這中間查詢到有用的日志,也是一個調整。
排查問題時,先使用了grep 命令找到出問題交易的賬號日志:
- grep 123 info.log
當大概定位的到日志輸出時間了,再利用區間縮小日志范圍:
- grep '2021-11-17 19:23:23' info.log > temp.log
這里同樣使用grep命令查找對應時間區間的日志,并將查找到日志輸出到temp.log文件中,然后通過sz命令,下載到本地進行篩選分析。
這里大家可以善用grep命令。同時也要善用輸出到新文件,這樣比每次查幾個G的內容方便多了。當然更方便的就是把篩選之后的日志下載本地,再次比對分析。
其他
關于代碼篩選這塊,沒有什么訣竅,除了從頭到位的捋一捋,沒有別的好方法。不過這個過程善用IDE的搜索和“Find usages”功能即可。
日終收獲
經過上述排查,最終在臨下班時,定位到了問題的原因:一個線程將余額更新之后,另外一個線程將其覆蓋了。在賬務流水記錄中存在了兩筆緊鄰,且計算前余額一樣的記錄。
得出結果之后,再排查其他的同類問題就方便多了,比如可采用group by來進行快速篩選:
- select count(id) as num , balance from account group by balance having num > 1;
通過上述語句就可以快速查出有同樣計算前余額的記錄。當然,上述語句還可以添加條件和結果維度。
雖然找到的問題發生的地方,但并未完全找到問題的原因。
更深層次的Bug
本以為找到了問題發生的點,就能快速解決問題的,但的確小覷了這個Bug,又是一整天才排查出根本原因。
模擬高并發
找到出問題的代碼,看了實現邏輯,沒問題啊,也加了悲觀鎖,數據庫事務也沒失效,也沒有同Service的方法調用。怎么就會出現問題呢?
既然肉眼看不出來,那就用程序跑。于是,寫了一個單元測試,創建一個線程池,來調用對應加鎖方法。結果,依舊沒問題。
由于跑的是測試庫,生產庫用的是云服務,擔心是數據庫的差異,于是在Navicat驗證了悲觀鎖是否生效:
- START transaction ;
- select * from account where id = 1 for update;
然后在另外一個查詢窗口執行:
- select * from account where id = 1 for update;
發現,數據庫的鎖的確是生效的,在沒有執行commit操作之前,是查不到數據的。
僵局與希望
此時,完全陷入僵局。于是就開始大量搜索資料,多次閱讀代碼。
最終,在一篇寫得很水,但給了一個Hibernate javadoc文檔鏈接的文中,無意點了一下鏈接,獲得了巨大的啟發。
在javadoc看了一下session實現悲觀鎖的方法。項目中用了已經廢棄的get方法:
get
- @Deprecated
- Object get(Class clazz,
- Serializable id,
- LockMode lockMode)
**Deprecated.**LockMode parameter should be replaced with LockOptions
Return the persistent instance of the given entity class with the given identifier, or null if there is no such persistent instance. (If the instance is already associated with the session, return that instance. This method never returns an uninitialized instance.) Obtain the specified lock mode if the instance exists.
其中的“If the instance is already associated with the session, return that instance”讓我眼前一亮。難道是緩存在作祟?
上面的重點是:如果session中已經存在這么個對象實例,會直接返回這個實例。
感覺回去看代碼,還真是的,偽代碼如下:
- Account account = accountService.getAccount(type, userNo);
- if(account == null){
- //...
- }
- accountService.getAccountAndLock(account.getId());
- // ...
上述代碼首先值得肯定的有兩點:第一,在加鎖之前先查了一次對象,這樣能避免因為對象不存在,鎖住全表;第二,就是鎖一條數據庫記錄時盡量采用id,精確定位到具體的記錄,避免鎖住其他記錄或整張表。
那么,是不是因為前面的查詢導致后面getAccountAndLock方法的實效呢?再來驗證一下。
于是,在單元測試中添加了前面的查詢,再次執行。哈哈,Bug終于復現了!
為了進一步證實,在底層的公共方法中添加了clear操作:
- public T findAndLock(Class cls, String primaryKey) throws DataAccessException {
- Session session = getHibernateTemplate().getSessionFactory().getCurrentSession();
- // 添加驗證是否緩存問題
- session.clear();
- Object object = session.load(cls, primaryKey, LockOptions.UPGRADE);
- return (T) object;
- }
再次執行單元測試,可正常加鎖。至此,Bug定位完畢。
問題的解決
既然已經定位問題,解決起來就非常方便了。上面使用session.clear()只是為了驗證,真實生產使用這種方法影響太大,而且是事后處理。
解決方案:將基于Hibernate的普通查詢,改為基于原生SQL的查詢。因為前面的普通查詢只需要id,那么只用一條SQL查詢ID即可,如果id為空,則不存在;如果id非空,則再進行下一步處理。
至此,問題完美解決。
小結
在解決上述問題的過程中,看似只是很簡單的悲觀鎖,但在排查的過程中還用到和涉及到了大量的其他知識,比如@Transactional事務失效場景的排查、事務的隔離級別、Hibernate的多級緩存、Spring的事物管理、多線程、Linux操作、Navicat手動事務、SQL優化、單元測試、Javadoc查閱等。
所以,在解決問題之后,覺得十分有必要分享給大家。通過這個案例,你又學到了什么呢?