Android動態日誌系統Holmes

03-04

背景

美團點評公司是全球領先的一站式生活服務平台，為6億多消費者和超過450萬優質商戶提供連接線上線下的電子商務網路。美團點評的業務覆蓋了超過200個豐富品類和2800個城區縣網路，在餐飲、外賣、酒店旅遊、麗人、家庭、休閑娛樂等領域具有領先的市場地位。

平台大，責任也大。在移動端，如何快速定位並解決線上問題提高用戶體驗給我們帶來了極大挑戰。線上偶爾會發生某一個頁面打不開、新活動搶單按鈕點擊沒響應、登錄不了、不能下單等現象，由於Android碎片化、網路環境、機型ROM、操作系統版本、本地環境複雜多樣，這些個性化的使用場景很難在本地復現，加上問題反饋的時候描述的往往都比較模糊，快速定位並解決問題難度不小。為此，我們開發了動態日誌系統Holmes，希望它能像大偵探福爾摩斯那樣幫我們順著線上bug的蛛絲馬跡，發現背後真相。

現有的解決辦法

發臨時包用戶安裝
QA嘗試去復現問題
在線debug調試工具
預先手動埋點回撈

現有辦法的弊端

臨時發包：用戶配合過程繁瑣，而且解決問題時間很長
QA復現：嘗試已有機型發現個性化場景很難復現
在線debug：網路環境不穩定，代碼混淆調試成本很高，佔用用戶過多時間用戶難以接受
手動埋點：覆蓋範圍有限，無法提前預知，而且由於業務量大、多地區協作開發、業務類型多等造成很難統一埋點方案，並且在排查問題時大量的手動埋點會產生很多冗餘的上報數據，尋找一條有用的埋點信息猶如大海撈針

目標訴求

快速拿到線上日誌
不需要大量埋點甚至不埋點
精準的問題現場日誌

實現

針對難定位的線上問題，動態日誌提供了一套快速定位問題的方案。預先在用戶手機自動產生方法執行的日誌信息，當需要排查用戶問題時，通過信令下發精準回撈用戶日誌，再現用戶操作路徑；動態日誌系統也支持動態下發代碼，從而實現動態分析運行時對象快照、動態增加埋點等功能，能夠分析複雜使用場景下的用戶問題。

自動埋點

自動埋點是線上App自動產生日誌，怎麼樣自動產生日誌呢？我們對方法進行了插樁來記錄方法執行路徑（調用堆棧），在方法的開頭插入一段樁代碼，當方法運行的時候就會記錄方法簽名、進程、線程、時間等形成一條完整的執行信息（這裡我們叫TraceLog），將TraceLog存入DB等待信令下發回撈數據。

public void onCreate(Bundle bundle) {

//插樁代碼 if (Holmes.isEnable(....)) {

Holmes.invoke(....);

return;

}

super.onCreate(bundle);

setContentView(R.layout.main);

}

歷史數據

Tracelog形成的是代碼的歷史執行路徑，一旦線上出現問題就可以回撈用戶歷史數據來排查問題，並且Tracelog有以下幾個優點：

Tracelog是自動產生的無需開發者手動埋點
插樁覆蓋了所有的業務代碼，而且這裡Tracelog不受Proguard內聯方法的限制，插樁在Proguard之前所以方法被內聯之後樁代碼也會被內聯，這樣就會記錄下來對照原始代碼的完整執行路徑信息
回撈日誌可以基於一個方法為中心點向前或者向後採集日誌（例如：點擊下單按鈕無響應只需要回撈點擊下單按鈕事件之後的代碼執行路徑來分析問題），這樣可以避免上報一堆無用日誌，減少我們排查問題的時間和降低複雜度

Tracelog工作的流程

方法運行產生方法調用日誌首先會經過checker進行檢測，checker包含線程檢測和方法檢測（減少信息干擾），線程檢測主要過濾類似於定時任務這種一直在不斷的產生日誌的線程，方法檢測會在一定時間內檢測方法調用的頻率，過濾掉頻繁調用的方法，方法如果不會被過濾就會進行非同步處理，其次向對象池獲取一個Tracelog對象，Tracelog對象進入生產隊列組裝時間、線程、序列號等信息，完成後進入消費隊列，最後消費隊列到達固定數量之後批量處理存入DB。

Tracelog數據展示

日誌回撈到Trace平台上按時間順序排列展示結果：

問題總結

我們的平台部署實施了幾個版本，總結了很多的案例。經過實戰的考驗發現多數的場景下用戶回撈Tracelog分析問題只能把問題的範圍不斷的縮小，但是很多的問題確定了是某一個方法的異常，這個時候是需要知道方法的執行信息比如：入參、當前對象欄位、返回值等信息來確定代碼的執行邏輯，只有Tracelog在這裡的感覺就好比只差臨門一腳了，怎麼才能獲取方法運行時產生的內存快照呢？這正是體現動態日誌的動態性能力。

動態下發

對目標用戶下發信令，動態執行一段代碼並將結果上報，我們利用Lua腳本在方法運行的時候去獲取對象的快照信息。為什麼選擇Lua？Lua運行時庫非常小並且可以調用Java代碼而且語言精簡易懂。動態執行Lua有三個重要的時機：立即執行、方法前執行、方法後執行。

立即執行：接受到信令之後就會立馬去執行並上報結果
方法前執行：在某一個方法執行之前執行Lua腳本，動態獲取入參、對象欄位等信息
方法後執行：在某一個方法執行之後執行Lua腳本，動態獲取返回值、入參變化、對象欄位變化等信息

在方法後執行Lua腳本遇到了一些問題，我們只在方法前插樁，如果在方法後也插樁這樣能解決在方法後執行的問題，但是這樣增加代碼體積和影響proguard內聯方法數，如何解決這個問題如下：

我們利用反射執行當前方法，當進入方法前面的插樁代碼不會直接執行本方法的方法體會在樁代碼里通過反射調用自己，這樣就做到了一個動態AOP的功能就可以在方法之後執行腳本，同樣這種方法也存在一個問題，就是會出現死循環，解決這個問題的辦法只需要在執行反射的時候標記是反射調用進來的就可以避免死循環的問題。

我們還可以讓腳本做些什麼呢？除了可以獲取對象的快照信息外，還增加了DB查詢、上報普通文本、ShardPreferences查詢、獲取Context對象、查詢許可權、追加埋點到本地、上傳文件等綜合能力，而且Lua腳本的功能遠不僅如此，可以利用Lua腳本調用Java的方法來模擬代碼邏輯，從而實現更深層次的動態能力。

動態下發數據展示

對象數據：

許可權信息：

DB數據：

技術挑戰

動態日誌在開發的過程當中遇到了很多的技術難點，我們在實施方案的時候遇到很多的問題，下面來回顧一下問題及解決方案。

數據量大的問題

主線程卡頓

由於同時會有多個線程產生日誌，所以要考慮到線程同步安全的問題。使用synchronized或者lock可以保證同步安全問題，但是同時也帶來多線程之間鎖互斥的問題，造成主線程等待並卡頓，這裡使用CAS技術方案來實現自定義數據結構，保證線程同步安全的情況下並解決了多線程之間鎖互斥的問題。
由於數據產生太多，所以在存儲DB的時候就會產生大量的IO，導致CPU佔用時間過長從而影響其他線程使用CPU的時間。針對這個問題，首先是採取線程過濾和方法過濾來減少產生無用的日誌，並且降低處理線程的級別不與主線程爭搶CPU時間，然後對數據進行批量處理來減少IO的頻率，並在資料庫操作上將原來的Delete+insert的操作改為update+insert。Tracelog固定存儲30萬條數據（大約美團App使用6次以上的記錄），如果滿30萬就刪除早期的一部分數據再寫入新的數據。操作越久，delete操作越多，CPU資源佔比越大。經過資料庫操作的實際對比發現，直接改為滿30萬之後使用update來更新數據效率會更高一些（這裡就不做太多的詳細說明）。我們的優化成果從起初的CPU佔比40%多降低到了20%左右再降到10%以內，這是在中低端的機器上測試的結果。

創建對象過多導致頻繁GC

日誌產生就會生成一個Tracelog對象，大量的日誌會造成頻繁的GC，針對這個問題我們使用了對象池來使對象復用，從而減少創建對象減低GC頻率，對象池是類似於android.os.Message.obtain()的工作原理。

干擾日誌太多影響分析問題

我們已經過濾掉了大部分的干擾日誌，但還是會有一些代碼執行比較頻繁的方法會產生干擾日誌。例如：自定義View庫、日誌類型的庫、監控類型的庫等，這些方法的日誌會影響我們DB的存儲空間，造成保留不了太多的正常方法執行路徑，這種情況下很有可能會出現開發這關心的日誌其實已經被衝掉了。怎麼解決這個問題那？在插樁的時候可讓開發者配置一些過濾或者識別的規則來認定是否要處理這個方法，在插樁的方法上增加一個二進位的參數，然後根據配置的規則會在相應的位上設置成0或者1，方法執行的時候只需要一個異或操作就能知道是否需要記錄這個方法，這樣增加的識別判斷幾乎對原來的方法執行耗時不會產生任何影響，使用這種方案產生的日誌就是開發者所期望的日誌，經過幾番測試之後我們的日誌也能保留住用戶6次以上的完整行為，而且CPU的佔用時間也降低到了5%以內。

性能影響

對每一個方法進行插樁記錄日誌，會對代碼會造成方法耗時的影響嗎？最終我們在中低端機型上分別測試了方法的耗時和CPU的使用佔比。

方法耗時影響的測試，100萬次耗時平均值在55~65ms之間，方法執行一次的耗時就微乎其微了
CPU的耗時測試在5%以內，如下圖所示：

內存的使用測試在56kB左右，如下圖：

對象快照

在方法運行時獲取對象快照保留現場日誌，提取對象快照就需要對一個對象進行深度clone（為了防止在還沒有完整記錄下來信息之前對象已經被改變，影響最終判斷代碼執行的結果），在Java中clone對象有以下幾種方法：

實現一個clone介面
實現一個序列化介面
使用Gson序列化

clone介面和序列化介面都有同樣的一個問題，有可能這個對象沒有實現相應的介面，這樣是無法進行深度clone的，而且實現clone介面也做不到深度clone，Java序列化有IO問題執行效率很低。最後可能只有Gson序列化這個方法還可行，但是Gson也有很多的坑，如果一個對象中有和父類一樣的欄位，那麼Gson在做序列的時候把父類的欄位覆蓋掉；如果兩個對象有相互引用的場景，那麼在Gson序列化的時候直接會死循環。

怎麼解決以上的這些問題呢？最後我們參照一些開源庫的方案和Java系統的一些API，開發出了一個深度clone的庫，再加上自己定義數據對象和使用Gson來解決對象快照的問題。深度clone實現主要利用了Java系統API，先創建出來一個目標對象的空殼對象，然後利用反射將原對象上的所有欄位都複製到這個空殼對象上，最後這個空殼對象會形成跟原有對象完全一樣的東西，同時對Android增加的一些類型進行了特殊處理，在提高速度上對基本類型、集合、map等系統自帶類型做了快速處理，clone完成的對象直接進行快照處理。

總結

動態日誌對業務開發零成本，對用戶使用無打擾。在排查線上問題時，方法執行路徑可能直接就會反映出問題的原因，至少也能縮小問題代碼的範圍，最終鎖定到某一個方法，這時再使用動態下發Lua腳本，最終確定問題代碼的位置。動態日誌的動態下發功能也可以做為一種基礎的能力，提供給其他需要動態執行代碼或動態獲取數據的基礎庫，例如：遇到一些難解決的崩潰場景，除了正常的棧信息外，同時也可以根據不同的崩潰類型，動態採集一些其他的輔助信息來幫助排查問題。

作者介紹

少飛，美團點評高級工程師，2015年加入美團點評，先後負責用戶行為日誌SDK、性能監控SDK、動態日誌、業務異常監控

陳潼，美團點評資深工程師，2015年加入美團點評，先後負責代碼靜態檢查、網路層優化、動態日誌等基礎設施開發工作

利峰，美團點評高級工程師，2017年加入美團點評，目前主要負責動態日誌性能優化相關工作

招聘

美團平台客戶端技術團隊長期招聘技術專家，有興趣的同學可以發送簡歷到：fangjintao#http://meituan.com。詳情請點擊：詳細JD

回答「思考題」、發現文章有錯誤、對內容有疑問，都可以來微信公眾號（美團點評技術團隊）後台給我們留言。我們每周會挑選出一位「優秀回答者」，贈送一份精美的小禮品。快來掃碼關注我們吧！

http://weixin.qq.com/r/9HVSSg3EOFBHrUkp9yDm (二維碼自動識別)