Windows CE系統級日誌設計

我的經驗，可靠的產品不是設計出來的，而是通過持續的解決BUG逐步達到的，當然我不是說設計不重要，我是想強調在產品中提供一些能夠協助診斷問題的設施是非常有必要的。在這方面，最常見的手段顯然就是系統日誌了。嵌入式系統由定製的硬體平台、定製的驅動程式、定製的系統組件，以及定製的應用程式構成。這麼多定製的組件湊在一起，要在一個比較短的時間內把他們湊在一起，配合良好順利運行不容易。他們中的任何部分都有可能出問題，因此應用程式層級的日誌模組顯然不足以記錄足夠的資訊，我們需要系統級的解決方案。在Windows CE平台，最有用的日誌毫無疑問應該是CE內建的串口輸出的調試資訊，它的最大優點就是基本上CE平台的所有模組，從boot loader到OAL，從driver到application，都支援並且都能很容易的支援往串口輸出調試資訊。基本上你要讓我診斷一個windows CE問題，我首先想知道的就是你有沒有串口輸出的調試資訊，如果有，問題可能呢就解決了一半。但是在實際的使用中，要得到出問題時的串口輸出又是很困難的，這是因為：1，有些裝置可能根本就沒有提供串口；2，很少有人在使用裝置時還接著跟串口線到電腦上，並且開著HypterTerminal；3，有些錯誤不容易重現，即使你的裝置有串口輸出，你也有串口線，還有電腦可接，但是你已經沒法重現錯誤了。
這篇文章我想談談怎麼做一個系統級的日誌模組，可以把往串口輸出的所有調試資訊捕捉到記錄檔中。這聽起來好像不難做到，基本上你要做的是在BSP中重寫 OEMWriteDebugString()，把原本往串口輸出的字串重新導向到檔案中。沒錯，本質上說起來也就是這麼回事，但是要做到這一點，有很多技術上的問題必須要考慮到。主要的痛點有兩點：

1，記錄檔的儲存牽扯到檔案系統。這就帶來三個問題，一是檔案系統只有在kernel啟動後並且檔案系統相關的驅動程式載入以後才能訪問。在boot loader引導階段，以及kernel初始化階段，檔案系統是不能用的，日誌的儲存怎麼解決？二是對檔案的寫操作一般速度比較慢，對系統效能有嚴重影響。三是檔案存取依賴於檔案系統的驅動程式棧（包括檔案系統驅動、分區管理驅動、塊裝置驅動），還涉及到進程/線程間的環境切換，這相比起串口輸出來說複雜度提高了不止一個數量級，因此可靠性大大降低。

2，系統中的任何模組在任何狀態下都可能輸出調試資訊。什麼意思？這意味著：一，你要非常小心，不能讓一個模組的輸出block掉另一個模組的輸出，輸出時的同步鎖是必須的，但是鎖定狀態下的代碼必須非常可靠且快速。二，有些輸出非常特別，比如說從中斷處理常式輸出的調試資訊，此時所有硬體中斷以及線程調度器都處于禁止狀態，也就是說所有可能引起阻塞的API都不能用。比如你可能想在 OEMWriteDebugString()中把字串緩衝在記憶體中，然後用SetEvent去觸發等待在這個event上的某個線程把它寫進記錄檔，在這裡SetEvent就會把系統掛起－因為此時線程調度器沒法工作。

下面說說設計要點：
1，日誌模組提供給其他模組輸出資訊的介面實現（即OEMWriteDebugString的實現）的可靠性和效能非常重要。因為系統中的所有模組都跟它有依賴關係。在有即時要求的系統中，這個介面也必須滿足即時性。這是說，這個介面從調用到返回，其調用過程所需時間在理論上要有明確的上限。但是對於檔案系統來說，這三點都很難滿足。因此緩衝日誌是必須的，基本想法是在OEMWriteDebugString不涉及任何跟檔案有關的操作，只是把日誌緩衝在記憶體中，真正的寫記錄檔操作由單獨的線程完成。這跟CE的中斷處理手法很像，分為ISR和IST兩部分：OEMWriteDebugString是ISR，寫記錄檔線程是IST。這同時也解決了如何隱藏檔系統可用之前的日誌輸出問題。

2，緩衝如何分配及訪問？簡單的做法是在記憶體中保留一塊固定地區，在boot loader階段可以直接存取。在kernel階段，這塊記憶體不歸核心的記憶體子系統管理，logging ISR（即OEMWriteDebugString）可以直接存取，IST中可用SetKMode API(CE5)進入核心態訪問，在CE6中IST運行在核心態，也可以直接存取。如果使用其他方法，比如動態記憶體分配，你要考慮在kernel階段如何讀取boot loader階段輸出的日誌，還有在IST中如何訪問這塊緩衝，特別要當心address aliasing的問題。
3，Time stamp如何取。time stamp對於日誌系統來說是非常必要的，一般的應用程式層級的日誌模組的time stamp可以用GetSystemTime之類的windows API來拿。但是這裡顯然不能用，因為，在boot loader階段它根本不存在，在kernel階段，ISR調它可能引起系統掛起，在IST中調用雖然沒問題，但為時已晚。我的做法是用 GetTickCount記錄時間，因為tick count機制一般由CPU實現，簡單可靠而且快速。在IST中，用GetSystemTime取得目前時間同時取得當前tick count，和日誌產生時記錄的tick count相比較，就可得到真正的時間戳記。

4，Logging ISR如何通知IST處理日誌資訊。簡單的想法是在IST中等待一個event，在ISR中用SetEvent觸發。問題是，如前所述，處理來自中斷調用常式的日誌時調用SetEvent會導致系統掛起。我的解決方案是給日誌模組分配一個邏輯中斷號，在OEMWriteDebugString中用 NKSetInterruptEvent觸發中斷，在IST中的處理（Hook中斷，等待中斷觸發等）跟CE標準的IST實現一樣。
5，OEMWriteDebugString 的實現。這是整個日誌模組最關鍵的部分。它的實現必須滿足：高可靠性（任何情況下都不能導致調用它的線程或中斷處理常式掛起）、高效能（時間開銷必須儘可能小）、即時性（有明確的時間上限）、完全可重新進入（允許多個模組同時調用）。

6， 如何同步對緩衝的訪問。在boot loader階段，除非你開啟了硬體中斷而且在中斷響應代碼中輸出日誌資訊，否則不需要同步，因為boot loader本身是單任務系統，不存在對緩衝的並發訪問問題。在kernel運行階段情況就不同了，windows ce的kernel是一個多任務系統，任何模組在任意時刻都可能調用OEMWriteDebugString輸出資訊（寫訪問），logging IST在任意時刻都可能從緩衝中讀取資訊（讀訪問），因此日誌模組是一個multi-writer，single-reader的系統，對緩衝的訪問必須進行同步。有哪些方法可以選擇？

方法A，眾所周知，在應用程式層級的開發中典型的做法是使用mutex、event等核心對象來同步writer和reader。問題在於我們的writer很特殊（即OEMWriteDebugString），它的調用者不光包括普通的線程，還包括中斷響應常式（ISR）和異常處理常式（Data/Prefetch Abort Handler），在處理這些特殊的常式時CPU是不允許切換到其他上下文執行的。另外，即使只是在普通的線程上下文環境下使用這些核心對象進行同步，也可能引起死結。比如你有一個應用程式，它依賴於一個DLL，這個DLL在載入時在DllMain會輸出一些調試資訊（通過RETAILMSG或 OutputDebugString），提示它被載入了。這種情況很常見吧，但是你可能意識不到這就會引起死結。問題出在DllMain是在一個進程層級（process wide）的鎖保護下執行的，換句話說DllMain被調用時該進程中的所有其他線程都處於阻塞狀態，如果這其中的某個線程在被掛起前正好也輸出了一行調試資訊，獲得了OEMWriteDebugString的寫訪問鎖，就會導致死結，這是因為DllMain獲得的Loader lock阻塞了該進程的其他線程，而在他輸出調試資訊時需要擷取的OEMWriteDebugString的writer lock被該進程的其他線程擷取，而這個線程永遠沒有機會被喚醒了－這是典型的lock order inversion。關於DLL的載入鎖，請看微軟的白皮書：Best Practices for Creating DLLs。簡單地說，常規的核心對象方法是行不通的。

方法B，關鍵的麻煩在於OEMWriteDebugString的實現需要同步又不能引入阻塞操作，可以考慮把它放到SysCall的保護下執行，代價是在 OEMWriteDebugString執行時，中斷不能響應，線程調度器也不能工作，這會影響整個系統的中斷響應效能和線程調度效能，從而影響了系統的即時性。

方法C，也可以考慮把緩衝按writer分塊，比如等分成1000塊，每個writer佔一塊。也就是說，系統中同時啟動並執行線程，加上ISR，Data Abort Handler, Prefectch Abort Handler等數目不能超過1000，這樣writer在寫訪問時就不會互相影響。缺點是同一個writer上一次輸出的資訊被reader處理之前，無法輸出下一個資訊。更糟的是，這種設計間接引入了輸出介面對檔案系統的依賴，會嚴重降低系統的可靠性，也不可行。

方法D，這是我實際採用的方法。雖然常規的基於核心對象的鎖無法使用，幸運的是我們還有一種簡單的鎖可用又不會導致阻塞，那就是Interlocked型 API（InterlockedExchange，InterlockedIncrement等等）。雖然Interlocked型API只能保證對32 位簡單數值型變數的操作的原子性，不能保證程式碼片段執行的原子性。但是它有更重要的優點，它非常簡單、可靠、高效，而且不會引起阻塞（Interlocked型API的實現如何在保證操作的原子性的同時又不阻塞其他線程是一個值得一提的話題，後面有機會再單獨介紹）。如何利用這些 API實現我們需要的multi-writer/single-reader模型？我的想法是，由於日誌是按時間順序進來的，可把緩衝塊構造成一個 FIFO的環形隊列。給每條日誌的空間如何分配？簡單的做法是可以事先把這塊緩衝等分成N小塊，每條資訊將佔據一塊。這樣做的優點是處理起來邏輯簡單而且快速，給日誌資訊分配空間可以簡化成申請一個空閑塊的索引（用Interlocked API保證申請索引操作的原子性），真正的緩衝日誌操作不需要加鎖。由於資訊塊是等分的，需要鎖定的申請索引操作和日誌資訊的長度無關，因此是O(1)的效率。又由於日誌儲存在隊列中，已指派塊和空閑塊只需用兩個索引值（第一個已指派塊的索引和最後一個已指派塊的索引）就可界定，處理起來非常簡單。缺點是過長的資訊不得不被截斷，這個問題可以通過適當的設定塊的大小，以及在介面規範中明確指出日誌的最大長度來緩解，因為日誌的主要目的是讓使用者瞭解系統運行時的狀態，如果有必要，可以通過重新組織輸出資訊來減小長度。

7，確定緩衝和塊的大小。這可能需要你對自己的系統做一個觀測，看看正常情況下日誌輸出量有多大，然後再加一些緩衝。每個塊需要多大空間？正常的日誌一行差不多是幾十個字元，很少有超過100個字元的，因此256位元組應該是足夠的，如果系統記憶體比較小，128位元組應該也夠了。假如同時儲存1000條日誌，那麼總緩衝大約為256K。

8，日誌的輔助資訊。在日誌產生的同時，記錄下它的產生時間和線程ID/TEB等資訊對診斷問題也是很有協助。比如在《如 何診斷Windows CE的應用程式崩潰》一文中提到的，應用程式崩潰時CE核心會輸出相關的崩潰資訊（Data Abort/Prefetch Abort等），其中包含了崩潰線程的TEB值，如果該線程之前還有過一些日誌輸出，就可以很容易的把崩潰線程和原始碼對應起來。
9，日誌產生速度太快，reader來不及處理導致緩衝溢出怎麼辦？顯然你只能丟掉一些日誌，問題是丟掉最新的還是最老的？我傾向於丟掉最新的，因為一般來說只要緩衝足夠大，這種情況很少發生，出現這種情況一般是某個線程進入死迴圈，在裡面不停地輸出資訊，因此重要的是保留死迴圈出現時的日誌，而不是這些死迴圈中發出的垃圾日誌。

10，OEMWriteDebugString的效能如何？先來估算一下OEMWriteDebugString往串口輸出的效率。假設串口設定為11520傳輸速率，8位元據位，1位停止位，無同位，則傳輸速率＝115200/9/1000=12.8 byte/ms，傳輸一個位元組所花時間為：10^6/12800=78 us/byte。這是理論上的算出的最大值，實際情況中還有OEMWriteDebugString的調用開銷，在我的系統中（CPU主頻為 520MHz，CPU系統匯流排為208MHz，外部匯流排（SDRAM)為104MHz），實際測值為93 us/byte。在OEMWriteDebugString中禁止往串口輸出，可以測得OEMWriteDebugString的調用開銷，大約為5 us，也就是說用RETAILMSG輸出一行日誌，所花時間大約為5~6微秒。這是一個相當高效的介面了，如果你的CPU支援微秒級計時器，你可以用它診斷一些高速模組，比如網路介面晶片的資料轉送問題。