設計一套完整的日誌系統

劉小壯發表於2021-11-09

需求

日誌對於線上排查問題是非常重要的,很多問題其實是很偶現的,同樣的系統版本,同樣的裝置,可能就是使用者的復現,而開發通過相同的操作和裝置就是不復現。但是這個問題也不能一直不解決,所以可以通過日誌的方式排查問題。可能是後臺導致的問題,也可能是客戶端邏輯問題,在關鍵點記錄日誌可以快速定位問題。

假設我們的使用者量是一百萬日活,其中有1%的使用者使用出現問題,即使這個問題並不是崩潰,就是業務上或播放出現問題。那這部分使用者就是一萬的使用者,一萬的使用者數量是很龐大的。而且大多數使用者在遇到問題後,並不會主動去聯絡客服,而是轉到其他平臺上。

雖然我們現在有Kibana網路監控,但是隻能排查網路請求是否有問題,使用者是否在某個時間請求了伺服器,伺服器下發的資料是否正確,但是如果定位業務邏輯的問題,還是要客戶端記錄日誌。

現狀

我們專案中之前有日誌系統,但是從業務和技術的角度來說,存在兩個問題。現有的日誌系統從業務層角度,需要使用者手動匯出併發給客服,對使用者有不必要的打擾。而且大多數使用者並不會答應客服的請求,不會匯出日誌給客服。從技術的角度,現有的日誌系統程式碼很亂,而且效能很差,導致線上不敢持續記錄日誌,會導致播放器卡頓。

而且現有的日誌系統僅限於debug環境開啟主動記錄,線上是不開啟的,線上出問題後需要使用者手動開啟,並且記錄時長只有三分鐘。正是由於現在存在的諸多問題,所以大家對日誌的使用並不是很積極,線上排查問題就比較困難。

方案設計

思路

正是針對現在存在的問題,我準備做一套新的日誌系統,來替代現有的日誌系統。新的日誌系統定位很簡單,就是純粹的記錄業務日誌。Crash、埋點這些,我們都不記錄在裡面,這些可以當做以後的擴充套件。日誌系統就記錄三種日誌,業務日誌、網路日誌、播放器日誌。

日誌收集我們採用的主動回撈策略,在日誌平臺上填寫使用者的uid,通過uid對指定裝置下發回撈指令,回撈指令通過長連線的方式下發。客戶端收到回撈指令後,根據篩選條件對日誌進行篩選,隨後以天為單位寫入到不同的檔案中,壓縮後上傳到後端。

在日誌平臺可以根據指定的條件進行搜尋,並下載檔案檢視日誌。為了便於開發者檢視日誌,從資料庫取出的日誌都會寫成.txt形式,並上傳此檔案。

API設計

對於呼叫的API設計,應該足夠簡單,業務層使用時就像呼叫NSLog一樣。所以對於API的設計方案,我採用的是巨集定義的方式,呼叫方法和NSLog一樣,呼叫很簡單。

#if DEBUG
#define SVLogDebug(frmt, ...)   [[SVLogManager sharedInstance] mobileLogContent:(frmt), ##__VA_ARGS__]
#else
#define SVLogDebug(frmt, ...)   NSLog(frmt, ...)
#endif

日誌總共分為三種型別,業務日誌、播放器日誌、網路日誌,對於三種日誌分別對應著不同的巨集定義。不同的巨集定義,寫入資料庫的型別也不一樣,可以使用者日誌篩選。

  • 業務日誌:SVLogDebug
  • 播放器日誌:SVLogDebugPlayer
  • 網路日子:SVLogDebugQUIC

淘汰策略

不光是要往資料庫裡寫,還需要考慮淘汰策略。淘汰策略需要平衡記錄的日誌數量,以及時效性的問題,日誌數量儘量夠排查問題,並且還不會佔用過多的磁碟空間。所以,在日誌上傳之後會將已上傳日誌刪除掉,除此之外日誌淘汰策略有以下兩種。

  1. 日誌最多隻儲存三天,三天以前的日誌都會被刪掉。在應用啟動後進行檢查,並後臺執行緒執行這個過程。
  2. 日誌增加一個最大閾值,超過閾值的日誌部分,以時間為序,從前往後刪除。我們定義的閾值大小為200MB,一般不會超過這個大小。

記錄基礎資訊

在排查問題時一些關鍵資訊也很重要,例如使用者當時的網路環境,以及一些配置項,這些因素對程式碼的執行都會有一些影響。對於這個問題,我們也會記錄一些使用者的配置資訊及網路環境,方便排查問題,但不會涉及使用者經緯度等隱私資訊。

資料庫

舊方案

之前的日誌方案是通過DDLog實現的,這種方案有很嚴重的效能問題。其寫入日誌的方式,是通過NSData來實現的,在沙盒建立一個txt檔案,通過一個控制程式碼來向本地寫檔案,每次寫完之後把控制程式碼seek到檔案末尾,下次直接在檔案末尾繼續寫入日誌。日誌是以NSData的方式進行處理的,相當於一直在頻繁的進行本地檔案寫入操作,還要在記憶體中維持一個或者多個控制程式碼物件。

這種方式還有個問題在於,因為是直接進行二進位制寫入,在本地儲存的是txt檔案。這種方式是沒有辦法做篩選之類的操作的,擴充套件性很差,所以新的日誌方案我們打算採用資料庫來實現。

方案選擇

我對比了一下iOS平臺主流的資料庫,發現WCDB是綜合效能最好的,某些方面比FMDB都要好,而且由於是C++實現的程式碼,所以從程式碼執行的層面來講,也不會有OC的訊息傳送和轉發的額外消耗。

根據WCDB官網的統計資料,WCDBFMDB進行對比,FMDB是對SQLite進行簡單封裝的框架,和直接用SQLite差別不是很大。而WCDB則在sqlcipher的基礎上進行的深度優化,綜合效能比FMDB要高,以下是效能對比,資料來自WCDB官方文件。

單次讀操作WCDB要比FMDB5%左右,在for迴圈內一直讀。

15906481049447.jpg

單次寫操作WCDB要比FMDB28%,一個for迴圈一直寫。

15906481114970.jpg

批量寫操作比較明顯,WCDB要比FMDB180%,一個批量任務寫入一批資料。

15906481277664.jpg

從資料可以看出,WCDB在寫操作這塊效能要比FMDB要快很多,而本地日誌最頻繁的就是寫操作,所以這正好符合我們的需求,所以選擇WCDB作為新的資料庫方案是最合適的。而且專案中曝光模組已經用過WCDB,證明這個方案是可行並且效能很好的。

表設計

我們資料庫的表設計很簡單,就下面四個欄位,不同型別的日誌用type做區分。如果想增加新的日誌型別,也可以在專案中擴充套件。因為使用的是資料庫,所以擴充套件性很好。

  • index:主鍵,用來做索引。
  • content:日誌內容,記錄日誌內容。
  • createTime:建立時間,日誌入庫的時間。
  • type:日誌型別,用來區分三種型別。

資料庫優化

我們是視訊類應用,會涉及播放、下載、上傳等主要功能,這些功能都會大量記錄日誌,來方便排查線上問題。所以,避免資料庫太大就成了我在設計日誌系統時,比較看重的一點。

根據日誌規模,我對播放、下載、上傳三個模組進行了大量測試,播放一天兩夜、下載40集電視劇、上傳多個高清視訊,累計記錄的日誌數量大概五萬多條。我發現資料庫資料夾已經到200MB+的大小,這個大小已經是比較大的,所以需要對資料庫進行優化。

我觀察了一下資料庫資料夾,有三個檔案,dbshmwal,主要是資料庫的日誌檔案太大,db檔案反而並不大。所以需要呼叫sqlite3_wal_checkpointwal內容寫入到資料庫中,這樣可以減少walshm檔案的大小。但WCDB並沒有提供直接checkpoint的方法,所以經過調研發現,執行database的關閉操作時,可以觸發checkpoint

我在應用程式退出時,監聽了terminal通知,並且把處理實際儘量靠後。這樣可以保證日誌不被遺漏,而且還可以在程式退出時關閉資料庫。經過驗證,優化後的資料庫磁碟佔用很小。143,987條資料庫,資料庫檔案大小為34.8MB,壓縮後的日誌大小為1.4MB,解壓後的日誌大小為13.6MB

wal模式

這裡順帶講一下wal模式,以方便對資料庫有更深入的瞭解。SQLite3.7版本加入了wal模式,但預設是不開啟的,iOS版的WCDBwal模式自動開啟,並且做了一些優化。

wal檔案負責優化多執行緒下的併發操作,如果沒有wal檔案,在傳統的delete模式下,資料庫的讀寫操作是互斥的,為了防止寫到一半的資料被讀到,會等到寫操作執行完成後,再執行讀操作。而wal檔案就是為了解決併發讀寫的情況,shm檔案是對wal檔案進行索引的。

SQLite比較常用的deletewal兩種模式,這兩種模式各有優勢。delete是直接讀寫db-page,讀寫操作的都是同一份檔案,所以讀寫是互斥的,不支援併發操作。而walappend新的db-page,這樣寫入速度比較快,而且可以支援併發操作,在寫入的同時不讀取正在操作的db-page即可。

由於delete模式操作的db-page是離散的,所以在執行批量寫操作時,delete模式的效能會差很多,這也就是為什麼WCDB的批量寫入效能比較好的原因。而wal模式讀操作會讀取dbwal兩個檔案,這樣會一定程度影響讀資料的效能,所以wal的查詢效能相對delete模式要差。

使用wal模式需要控制wal檔案的db-page數量,如果page數量太大,會導致檔案大小不受控制。wal檔案並不是一直增加的,根據SQLite的設計,通過checkpoint操作可以將wal檔案合併到db檔案中。但同步的時機會導致查詢操作被阻塞,所以不能頻繁執行checkpoint。在WCDB中設定了一個1000的閾值,當page達到1000後才會執行一次checkpoint

這個1000是微信團隊的一個經驗值,太大會影響讀寫效能,而且佔用過多的磁碟空間。太小會頻繁執行checkpoint,導致讀寫受阻。

# define SQLITE_DEFAULT_WAL_AUTOCHECKPOINT  1000

sqlite3_wal_autocheckpoint(db, SQLITE_DEFAULT_WAL_AUTOCHECKPOINT);

int sqlite3_wal_autocheckpoint(sqlite3 *db, int nFrame){
#ifdef SQLITE_OMIT_WAL
  UNUSED_PARAMETER(db);
  UNUSED_PARAMETER(nFrame);
#else
#ifdef SQLITE_ENABLE_API_ARMOR
  if( !sqlite3SafetyCheckOk(db) ) return SQLITE_MISUSE_BKPT;
#endif
  if( nFrame>0 ){
    sqlite3_wal_hook(db, sqlite3WalDefaultHook, SQLITE_INT_TO_PTR(nFrame));
  }else{
    sqlite3_wal_hook(db, 0, 0);
  }
#endif
  return SQLITE_OK;
}

也可以設定日誌檔案的大小限制,預設是-1,也就是沒限制,journalSizeLimit的意思是,超出的部分會被覆寫。儘量不要修改這個檔案,可能會導致wal檔案損壞。

i64 sqlite3PagerJournalSizeLimit(Pager *pPager, i64 iLimit){
  if( iLimit>=-1 ){
    pPager->journalSizeLimit = iLimit;
    sqlite3WalLimit(pPager->pWal, iLimit);
  }
  return pPager->journalSizeLimit;
}

下發指令

日誌平臺

日誌上報應該做到使用者無感知,不需要使用者主動配合即可進行日誌的自動上傳。而且並不是所有的使用者日誌都需要上報,只有出問題的使用者日誌才是我們需要的,這樣也可以避免服務端的儲存資源浪費。對於這些問題,我們開發了日誌平臺,通過下發上傳指令的方式告知客戶端上傳日誌。

037C8667-914E-43A7-8B6D-7B6EDD80E3A5.png

我們的日誌平臺做的比較簡單,輸入uid對指定的使用者下發上傳指令,客戶端上傳日誌之後,也可以通過uid進行查詢。如上圖,下發指令時可以選擇下面的日誌型別和時間區間,客戶端收到指令後會根據這些引數做篩選,如果沒選擇則是預設引數。搜尋時也可以使用這三個引數。

日誌平臺對應一個服務,點選按鈕下發上傳指令時,服務會給長連線通道下發一個jsonjson中包含上面的引數,以後也可以用來擴充套件其他欄位。上傳日誌是以天為單位的,所以在這裡可以根據天為單位進行搜尋,點選下載可以直接預覽日誌內容。

長連線通道

指令下發這塊我們利用了現有的長連線,當使用者反饋問題後,我們會記錄下使用者的uid,如果技術需要日誌進行排查問題時,我們會通過日誌平臺下發指令。

指令會傳送到公共的長連線服務後臺,服務會通過長連線通道下發指令,如果指令下發到客戶端之後,客戶端會回覆一個ack訊息回覆,告知通道已經收到指令,通道會將這條指令從佇列中移除。如果此時使用者未開啟App,則這條指令會在下次使用者開啟App,和長連線通道建立連線時重新下發。

未完成的上傳指令會在佇列中,但最多不超過三天,因為超過三天的指令就已經失去其時效性,問題當時可能已經通過其他途徑解決。

靜默push

使用者如果開啟App時,日誌指令的下發可以通過長連線通道下發。還有一種場景,也是最多的一種場景,使用者未開啟App怎麼解決日誌上報的問題,這塊我們還在探索中。

當時也調研了美團的日誌回撈,美團的方案中包含了靜默push的策略,但是經過我們調研之後,發現靜默push基本意義不大,只能覆蓋一些很小的場景。例如使用者App被系統kill掉,或者在後臺被掛起等,這種場景對於我們來說並不多見。另外和push組的人也溝通了一下,push組反饋說靜默push的到達率有些問題,所以就沒采用靜默push的策略。

日誌上傳

分片上傳

進行方案設計的時候,由於後端不支援直接展示日誌,只能以檔案的方式下載下來。所以當時和後端約定的是以天為單位上傳日誌檔案,例如回撈的時間點是,開始時間4月21日19:00,結束時間4月23日21:00。對於這種情況會被分割為三個檔案,即每天為一個檔案,第一天的檔案只包含19:00開始的日誌,最後一天的檔案只包含到21:00的日誌。

這種方案也是分片上傳的一種策略,上傳時以每個日誌檔案壓縮一個zip檔案後上傳。這樣一方面是保證上傳成功率,檔案太大會導致成功率下降,另一方面是為了做檔案分割。經過觀察,每個檔案壓縮成zip後,檔案大小可以控制在500kb以內,500kb這個是我們之前做視訊切片上傳時的一個經驗值,這個經驗值是上傳成功率和分片數量的一個平衡點。

日誌命名使用時間戳為組合,時間單位應該精確到分鐘,以方便服務端做時間篩選操作。上傳以表單的方式進行提交,上傳完成後會刪除對應的本地日誌。如果上傳失敗則使用重試策略,每個分片最多上傳三次,如果三次都上傳失敗,則這次上傳失敗,在其他時機再重新上傳。

安全性

為了保證日誌的資料安全性,日誌上傳的請求我們通過https進行傳輸,但這還是不夠的,https依然可以通過其他方式獲取到SSL管道的明文資訊。所以對於傳輸的內容,也需要進行加密,選擇加密策略時,考慮到效能問題,加密方式採用的對稱加密策略。

但對稱加密的祕鑰是通過非對稱加密的方式下發的,並且每個上傳指令對應一個唯一的祕鑰。客戶端先對檔案進行壓縮,對壓縮後的檔案進行加密,加密後分片再上傳。服務端收到加密檔案後,通過祕鑰解密得到zip並解壓縮。

主動上報

新的日誌系統上線後,我們發現回撈成功率只有40%,因為有的使用者反饋問題後就失去聯絡,或者反饋問題後一直沒有開啟App。對於這個問題,我分析使用者反饋問題的途徑主要有兩大類,一種是使用者從系統設定裡進去反饋問題,並且和客服溝通後,技術介入排查問題。另一種是使用者發生問題後,通過反饋群、App Store評論區、運營等渠道反饋的問題。

這兩種方式都適用於日誌回撈,但第一種由於有特定的觸發條件,也就是使用者點選進入反饋介面。所以,對於這種場景反饋問題的使用者,我們增加了主動上報的方式。即使用者點選反饋時,主動上報以當前時間為結束點,三天內的日誌。這樣可以把日誌上報的成功率提升到90%左右,成功率上來後也會推動更多人接入日誌模組,方便排查線上問題。

手動匯出

日誌上傳的方式還包含手動匯出,手動匯出就是通過某種方式進入除錯頁面,在除錯頁面選擇對應的日誌分享,並且調起系統分享皮膚,通過對應的渠道分享出去。在新的日誌系統之前,就是通過這種方式讓使用者手動匯出日誌給客服的,可想而知對使用者的打擾有多嚴重吧。

現在手動匯出的方式依然存在,但只用於debug階段測試和開發同學,手動匯出日誌來排查問題,線上是不需要使用者手動操作的。

dsasdlalfjsdafas.png

相關文章