對於由多個模塊協同工作的軟件來說，程序處理的時序是非常重要的。當消息處理的順序出現混亂時，程序就會出現異常。
本文基於作者的實際項目經驗，對軟件模塊之間的時序問題進行了詳細的分析，為相關軟件問題的分析及解決提供了有益的參考。
一、問題描述
在某軟件版本中，有兩個模塊(模塊A與模塊B)之間要進行通信。通信鏈路建立起來之後，模塊A向模塊B發消息，消息中攜帶了用戶號碼及序列號。在消息發送成功之後，模塊A按照序列號將用戶號碼存放到一個全局變量中。
模塊B在接收到模塊A發的消息之後，解析出用戶號碼，並進行相關的處理。在處理完成之後，模塊B將用戶號碼及序列號原樣返回給模塊A。模塊A先根據接收到的序列號來查找原發送的用戶號碼，並與接收到的模塊B返回的用戶號碼進行比較。若用戶號碼相同，則進行後續處理。
模塊A與模塊B之間的通信如圖1所示。
圖1 模塊A與模塊B之間的通信
在該軟件版本進行自測的過程中，發現模塊A發送的用戶號碼與模塊B返回的用戶號碼不能匹配，故後續流程無法繼續。
查看模塊A的日志，打印的發送的用戶號碼和接收的用戶號碼是一樣的，序列號也是相同的，但在用strncmp函數(用戶號碼變量為字符串類型)進行比較時就出現了問題。
二、模塊A的程序執行流程
由於用戶號碼的比較是在模塊A中完成的，因此這裡主要關注模塊A的程序執行流程。
模塊A的程序執行流程如圖2所示：
圖2 模塊A的程序執行流程
從圖2可以看出，在模塊A與模塊B的消息交互過程中，時序顯得非常的重要。如果消息的處理順序沒有定義好，就會出現模塊A程序異常終止的情況。
三、問題原因初步分析
為了確定發送的用戶號碼和接收的用戶號碼是否真的不一樣，我們在對兩個號碼進行比較的程序語句之前加了詳細的日志，想要打印出發送的用戶號碼、序列號和接收的用戶號碼、序列號。
日志加好之後，我們重新運行了程序，發現接收的用戶號碼和序列號是正確的，而發送的用戶號碼和序列號打印出來的是空值。
怎麼會這樣呢？難道在發送的時候沒有將用戶號碼和序列號拷貝到全局變量中去？
我們又在拷貝發送用戶號碼和序列號的程序語句之後加了日志，想要打印出發送的用戶號碼和序列號的值。重新運行程序之後，發現發送的用戶號碼和序列號是正確的，看來拷貝還是成功了的。
通過以上的分析，可以基本確定拷貝和解析都沒有問題，看來可能是處理時序導致了用戶號碼不能匹配的問題。
四、問題定位
我們又將日志詳細地查看了一遍，發現了一個奇怪的現象，那就是日志中打印出的接收模塊B返回消息的時間要比拷貝用戶號碼及序列號的時間早。
為什麼呢？我們對照查看了一下代碼，發現在將消息發送到模塊B之後，模塊A休眠了一段時間之後再進行消息的拷貝。而模塊B在極短的時間之內就返回了消息，此時模塊A還處在休眠期，沒有來得及將消息拷貝到全局變量中。
難道就是模塊A休眠時間惹的禍？為了驗證我們的猜想，我們直接將執行休眠的代碼注釋掉了來進行測試。程序重新運行之後，再查看日志，發現一切正常了，沒有打印出模塊A發送的用戶號碼與模塊B返回的用戶號碼不能匹配的信息，而且模塊A的後續流程也都執行到了。看來真是這個休眠時間闖禍了。
確實是這樣的，模塊B返回消息的時間極短，這樣當在與全局變量中的用戶號碼進行比較時，其實是一個字符串類型的用戶號碼在與一個空值進行比較，當然會出現問題。這也與發送的用戶號碼和序列號打印出來的是空值的事實相吻合。
既然真相已經大白，我們就著手修改代碼，將模塊A中按照序列號拷貝用戶號碼到一個全局變量的代碼放到了發送消息到模塊B的代碼之前，保留模塊A休眠的代碼。重新對修改後的程序進行了測試，一切就OK了。
五、總結
在本次時序問題的過程排查中，主要依靠程序日志來定位問題。
通過本次問題排查，我們總結出的經驗有以下幾個：
(1) 詳盡的日志有助於問題的定位。為了更清楚地了解問題出現的位置，我們可以在程序的關鍵語句處添加上一些測試日志，供分析所用。
(2) 在消息處理順序很重要的程序中，一定要理清程序執行的前後關系，防止流程“越位”的情況發生。
(3) 在排查問題的過程中，不要放過任何一個蛛絲馬跡，要及時驗證自己的想法，多對程序進行測試。
是程序就會有bug，因此，我們不要對程序中出現的問題耿耿於懷，要掌握排查問題的方法，這樣才能夠做到“以不變應萬變”。通過解決不同的問題，我們才能得到鍛煉，我們的開發能力才會得到提高。
