UBC SDK日誌級別重複率最佳化實踐

陶然陶然發表於2023-11-16

來源：百度Geek說

作者 | wunan

導讀 
introduction
日誌中中臺每日傳輸的日誌PV量級可達千億級，在上報過程中減少冗餘日誌資料，能夠降低下游資料處理的難度和成本，提高資料的準確性和質量，更好地支援業務系統的執行和最佳化。本文介紹了UBC SDK對日誌重複打包的最佳化實踐，透過對資料庫、程式和打點機制進行最佳化，有效地將日誌級別重複率由千分之三降低至萬分位。

全文8525字，預計閱讀時間22分鐘。


GEEK TALK

01

引言

文章首先對日誌中臺的去重背景和UBC SDK的打點機制進行了介紹，然後說明了重複問題的定位難點和手段，最後重點圍繞重複問題的分析和解決實踐進行說明。

1.1 日誌中臺去重背景

日誌中臺聚焦端日誌全生命週期的能力建設，包括日誌資料採集、傳輸、管理以及查詢分析等功能，實現對打點資料的全生命週期管理，解決新老產品的日誌規範與統一等問題，提升平臺資源利用率，發揮日誌的最大應用價值。

為保證資料下游高效且準確地收到資料，日誌中臺在端到端資料傳輸的時效、可靠性上進行了長期的最佳化並取得了顯著效果，然而這些最佳化也使得資料重複問題逐漸凸現出來。

重複問題即同一條日誌被SDK上報至服務端不止一次。為降低服務端QPS，SDK會將多條日誌打包上報，因此重複問題可分為兩類：

1.包重複：SDK傳送了資料但未收到結果，服務端已落盤，但端上包未被刪除，包內日誌整體重複上報。

2.日誌重複：單條日誌被打入多個包，分別隨每個包上報至服務端。

日誌中臺服務端上線了流式去重方案，保證下游資料不存在包粒度重複。服務端透過包md5執行去重，但同一條日誌被打入不同包會導致md5不同，這類情況服務端無法識別。因此服務端去重的前提，是由SDK保證上報的日誌沒有重複打包的情況。

1.2 UBC SDK簡介

UBC（User Behavior Collection） SDK，即使用者行為收集SDK，負責端打點日誌的採集、封裝、上報等功能，記錄使用者行為資料並上傳至日誌中臺服務端，是日誌中臺資料傳輸鏈路的源頭。


1.2.1 打點型別

根據打點所表達的內容，可分為事件打點和流式打點，分別記錄單次行為和停留行為。

不同業務方對點位上報的時效有不同的需求，由慢到快可分為：非實時打點、實時打點、直髮打點和reallog打點，不同型別的打點執行流程存在差異。


1.2.2 打點機制

UBC SDK承載著廠內絕大部分資料的記錄和傳輸，雙端單日可上報千億條日誌，需要在不影響主執行緒執行的基礎上，又快又準地上報打點。為了實現這個目標，UBC採取了以下措施：

1.分階段非同步處理：為了保證打點上報的效率和穩定性，SDK內部將整個流程拆分為多個階段，交給任務執行緒和傳送執行緒非同步排程執行。

2.日誌和包持久化儲存：為了保證日誌不丟失，SDK會將日誌持久化到SQLite，傳送時將日誌持久化到檔案，重複嘗試傳送直至成功。

3.多種上報觸發時機：為了兼顧上報吞吐和時效，SDK會在不同的時機觸發日誌上報，如實時打點立即觸發、非實時打點達到上報週期觸發、前後臺切換或網路恢復時上報積壓資料等。

UBC SDK核心模組架構如下圖所示：

UBC SDK日誌級別重複率最佳化實踐

UBC日誌管理、儲存和傳送的基本流程如下圖所示：

UBC SDK日誌級別重複率最佳化實踐

GEEK TALK

02

定位手段

2.1 定位難點及方法論

排查端日誌重複問題存在著以下難點：

1.使用UBC的業務方眾多，不同點位觸發場景不同，出現的問題也不同，無法了感知所有業務的呼叫方式。

2.日誌重複多是小機率的底層異常事件導致，與使用者本地環境、系統版本、廠商密切相關，問題難以復現。

3.UBC SDK是資料的入口，牽一髮而動全身，任何一個上報流程上的修改都可能造成已有資料的波動，影響業務統計。

因此，這類問題難以透過常用手段排查和最佳化，UBC在處理過程中逐漸形成了一套方法論：

UBC SDK日誌級別重複率最佳化實踐

2.2 定位工具

2.2.1 線上日誌標識

線上日誌是監控包括重複率在內的指標最直接的途徑，然而在千億級的資料中尋找出重複打包的日誌猶如大海撈針。

因此在定位重複問題時，各類標識是至關重要的，它們可以用於識別和關聯不同的日誌條目，從而幫助確定哪些問題是重複的。透過資料統計和監控報警，可以在T+1的時效發現問題，並直接透過參與統計的原始資料分析問題。

要發現存在重複的日誌，首先需要唯一地確定一條日誌。

日誌uuid：UUID（Universally Unique Identifier）是一個128位的字串，可以確保在全域性範圍內唯一標識一個物件或事件，即實現在同一裝置下唯一標識一條日誌，用於日誌記錄和追蹤。改都可能造成已有資料的波動，影響業務統計。

透過日誌uuid可發現重複上報至TC-Box的日誌，但要確定是包重複還是日誌重複，需要結合打包資訊判斷，包的標識資訊主要有兩個：

1.包md5：MD5（Message Digest Algorithm 5）是一種廣泛使用的密碼雜湊函式，可以接收任何長度的資料並生成一個固定長度的雜湊值。UBC透過包內容計算生成md5值，作為包的標識。

2.包createtime：毫秒級打包時間戳。由於包內容相同時md5值也相同，若同一批資料一起被多次打包，則無法透過md5識別，因此需使用md5+createtime作為重複打包的識別標識。

除標識資訊外，還需其他資訊輔助進行判斷，如：

1.timestamp：打點時的時間戳，可結合出現重複的打點前後日誌推斷使用者操作。

2.appv：打點時的app版本號，評估最佳化效果時，需減少舊版本延遲上報的干擾。

3.process：執行打包的程式ID和程式名，多個程式同時存在UBC例項時，可能會由於程式不安全造成重複。

4.trigger：打包觸發時機，正常情況下不同的上報時機有不同頻次，上報時機出現頻次異常也可輔助定位問題。

5.db_sync：SQLite同步模式，可用於輔助驗證使用者資料庫回寫方式導致的異常。


2.2.2 異常監控

UBC執行過程中可能會出現各類異常，為及時感知這些異常，UBC需透過上報打點的方式進行監控。

不同型別的異常監控打點會攜帶打點特殊環節執行情況、異常堆疊等內容，輔助重複問題排查、異常量級統計和修復效果分析。

為避免異常情況導致UBC的正常流程無法執行，監控會繞開UBC儲存，透過旁路進行儲存和上報。


2.2.3 業務打點

UBC作為服務層的SDK，與業務解耦，因此只能對SDK自身行為進行監控，無法直接獲取使用者的操作路徑和裝置資訊。

業務方的打點發生在使用者操作的各種場景下，可以輔助還原使用者的行為。例如，透過手百啟動相關點位，判斷使用者前後臺切換和冷啟動行為；透過閃屏展現打點，獲取使用者電量以判斷使用者裝置是否存在斷電重啟；透過其他打點記錄的各類網路狀態、磁碟等資訊。


GEEK TALK

03

重複問題歸因及解決

3.1 資料庫相關問題

立足打點的執行流程，要排查單條日誌重複打包的問題，首先想到的就是排查批次日誌打包階段。

UBC SDK日誌級別重複率最佳化實踐

該環節邏輯分支較多，且實時與非實時打點執行策略有所不同：

  • 非實時打點觸發後先寫快取、再寫資料庫，達到上報時機後批次查詢資料庫並觸發上報；

  • 實時打點先寫入檔案觸發上報上報，寫檔案失敗才寫入資料庫，寫檔案時會查詢資料庫追加一批非實時打點。

UBC SDK日誌級別重複率最佳化實踐

最初分析重複資料中，實時打點較少，多為需要入庫的非實時打點和流式打點。因此在重複問題排查的第一階段，重點對資料庫相關問題進行了排查。

打包過程是"將日誌從資料庫批次轉移至檔案"的過程，藍色框所示環節細化如下圖所示。

UBC SDK日誌級別重複率最佳化實踐

正常情況下，若寫檔案後刪除資料庫中已打包日誌執行失敗，SDK會終止上報流程並刪除已生成的檔案，中斷髮送流程避免重複打包。

該環節設計的初衷，即解決上報時直接讀資料庫導致重複傳送的問題，但如果在此過程中存在SDK無感知的異常，則會直接導致當前檔案成功傳送，而日誌未刪除，這批日誌在下次上報時會再次被查詢打包，造成重複。


3.1.1 資料庫損壞 

按照2.1節提到的定位問題方法論，對出現重複的使用者按照資料特徵歸類，對重複原因進行逐一歸因，定位到佔比較大的重複問題為資料庫損壞。


(1)問題歸因

資料特徵

  • 使用者單日上報的PV量級巨大，嚴重的達百萬級別（大盤上報PV單人單日平均約2000條左右）。

  • 使用者上報的大部分為重複日誌，同一日誌會被重複打包多次。

  • 多次打包間隔時間很短，未經歷冷啟動。

  • 大部分重複包的md5相同，但createtime不同，且觸發條件為條數超限。

原因推測

刪除已打包日誌事務返回成功結果並執行上報，但實際刪除結果為失敗。

進一步分析

對刪除已上報資料的程式碼進行review，初步排除了一些影響因素：

  • 整個邏輯加了同步鎖，可排除其他執行緒的影響。

  • SQL執行異常會被捕獲並返回失敗，刪除當前檔案且不上報。

  • 監控了delete方法刪除條數與預期不符的情況，但問題量級很小，對重複率影響不大。

進一步分析程式碼的兩層try-catch，發現了問題所在：

  • 裡層try-catch：執行多條SQL，成功後設定事務成功標識，並將結果標識設為true。

  • 外層try-catch：提交事務並統計刪除結果。

進入外層時，標識位已設定為true，但提交事務的結果未被處理，推斷為該環節出現未處理的異常導致了事務回滾。

UBC SDK日誌級別重複率最佳化實踐

佐證歸因

  • 為確定異常原因，對SQL異常監控進行了細化，記錄DatabaseHelper類中所有捕獲到的異常堆疊。

  • 撈取重複使用者的異常監控資料，發現存在大量SQL異常。堆疊如下，db.endTransaction時出現了資料庫損壞異常SQLiteDatabaseCorruptException，佐證了程式碼分析結果。

    UBC SDK日誌級別重複率最佳化實踐

崩潰堆疊

  • SQLite官網對於資料庫損壞問題也有說明：資料庫讀寫過程中出現檔案fsync失敗、磁碟損壞、異常資料寫入等問題，均有可能造成資料庫損壞。

    UBC SDK日誌級別重複率最佳化實踐

最終歸因

  • 資料庫損壞可能導致部分日誌可讀但無法寫。

  • 事務提交前更新了刪除資料的執行結果，按成功結果處理執行了上報，但由於資料庫損壞導致事務回滾，資料未被成功刪除。

  • 每次上傳成功後會檢查資料庫條數，超過閾值則會再次觸發上傳，單個包超限後停止寫入，因此造成短時間內大量上報且包md5相同。


(2)最佳化方案

針對該問題，雙端均需進行兩步最佳化：

1.修正資料庫事務執行結果，若事務提交發生異常則重置結果；

2.資料庫損壞時進行重建，刪除資料庫檔案及其附加的-journal，-shm，-wal檔案，資料庫再次開啟時會重新建立資料庫檔案。

風險評估

1.UBC上報時效較高，大部分資料均能在1min內完成上報並從資料庫清除，因此資料庫中通常只會保留幾條資料，直接刪除損失的資料在可接受範圍。

2.檔案刪除重建操作不宜頻繁執行，需對資料庫修復頻次進行限制，並針對每次修復操作和結果進行統計。

3.資料庫重建風險較大，因此採用AB實驗定向下發的方式，確認有效且無其他影響後再逐步放量。

最佳化效果

1.實驗初期，為存在大量重複上報的使用者定向下發實驗開關，均成功修復且修復後重復率歸0。

2.實驗推全後，根據監控統計每日可成功修復這類資料庫損壞40+個，不再有大量重複問題出現。

3.最佳化資料庫損壞問題後，大盤重複率下降至千分之二以下，下降約0.07個百分點，約佔最佳化前的35%。


3.1.2 WAL檔案寫入失敗

(1)問題歸因

資料特徵

  • 出現重複的使用者，一批打點均重複打包兩次。

  • 兩次打包中有冷啟動，且相隔時間較長。

  • 後一次打包為冷啟後首個包，打包觸發條件為實時上報或網路恢復上報。

原因推測

使用者裝置出現系統級崩潰導致資料庫操作執行成功，但回寫失敗。

進一步分析

  • 從Android 9.0開始，預設開啟了SQLite的WAL（Write-Ahead Logging）模式。在WAL模式下，SQLite會將修改操作記錄在WAL檔案中，在系統空閒時或事務提交時，執行checkpoint操作，再由WAL檔案回寫入磁碟的資料庫檔案中。SQLite使用此機制來避免頻繁的磁碟寫入操作，提高資料庫的寫入效能和併發性。

  • 修改操作寫入WAL檔案、WAL檔案回寫入資料庫檔案時，都會經歷先寫入磁碟緩衝區、再執行fsync操作flush到磁碟的過程。而系統異常後事務是否能被恢復，關鍵在於WAL檔案是否成功執行了fsync。

  • 常用的WAL同步模式主要有兩種：PRAGMA schema.synchronous = NORMAL | FULL，二者區別在於NORMAL在寫WAL檔案時會在fsync執行前就返回提交結果，而FULL模式會在WAL檔案真正寫入磁碟後才返回結果。

UBC SDK日誌級別重複率最佳化實踐

  • SQLite官方文件中提到：NORMAL模式下，事務的提交在掉電或系統崩潰時可能會被回滾。

UBC SDK日誌級別重複率最佳化實踐

佐證歸因

1.啟動相關打點記錄了使用者電量，部分使用者前一次打包時電量低於10%，第二次打包時電量恢復，說明期間出現了掉電問題。

2.將資料庫同步模式資訊攜帶上報，經驗證，發生此類重複問題的使用者資料庫模式均為NORMAL。

最終歸因

1.使用者裝置的SQLite使用了WAL的NORMAL模式，在刪除事務寫入WAL磁碟緩衝區後、緩衝區被同步到磁碟前，發生了掉電或系統崩潰。

2.事務被判斷為成功而執行了上報，但未寫入WAL檔案，因此磁碟檔案中資料未被刪除，且系統恢復後也無法重新執行刪除，已上報的資料仍存在。


(2)最佳化方案

根據重複原因，可推匯出該問題的解決方案，即在資料庫操作完成後儘可能快地保證操作被寫入磁碟，有三種執行方式：(1) 關閉WAL模式；(2) 同步模式設為FULL；(3) 手動執行checkpoint。

Android端透過多個方案對比和測試，最終得到折衷的方案：僅保證『刪除已打包資料』這一資料庫事務的可靠性，在同步模式為NORMAL時，刪除資料後手動觸發checkpoint，觸發WAL檔案寫入DB檔案，保證SQLite至少完成了WAL檔案的fsync操作。執行checkpoint耗時與執行事務耗時基本持平，效能劣化在可接受範圍。

iOS端在WAL模式下要保證事務完整寫入，除設定同步模式為NORMAL外，還需要額外開啟fullfsync選項，以嚴格保證寫入順序跟提交順序一致。經測試評估，效能劣化大於重複率最佳化收益，最終選擇不進行此最佳化。

最佳化效果

  • WAL寫入失敗問題約佔新版本長尾重複問題的70%。

  • 根據Android端實驗資料，單小時內，實驗組相比對照組減少200+次重複打包。

3.2 程式相關

在最佳化資料庫損壞造成的重複打包問題後，查詢大盤資料，發現Android端仍存在日誌重複打入兩個包、且間隔時間很短的問題，且使用者無資料庫異常資訊。

這種短時間內同時觸發打包的問題，自然地會想到另一個問題：UBC執行緒是否安全。然而，如1.2.2節所示，UBC內部僅存在兩個佇列，讀資料庫和打包均為單執行緒操作，理論上不會出現執行緒併發問題。

因此，我們將目光轉向了Android端的程式安全問題：

1.百度APP除主程式外，還存在小程式、媒體等多個子程式，不同程式均會呼叫打點API。

2.為保證啟動速度，UBC採用了懶載入的初始化方式，當前程式無UBC例項時才會初始化一個UBC單例。

3.若業務方在非主程式呼叫API，UBC會IPC到主執行緒執行，以此來保證生命週期內只有主程式存在一個UBC單例。若該過程出現問題，可能會導致在子程式中初始化另一個UBC例項。

兩個程式同時存在UBC單例時，就可能出現程式不安全的問題，如下圖所示。

UBC SDK日誌級別重複率最佳化實踐

1.兩個程式併發打包並運算元據庫，一個程式在另一個程式刪除資料前執行查詢，則會導致同一批資料被寫入兩個檔案。

2.刪除操作執行的前後順序會導致後一個執行刪除的操作因資料不存在而返回刪除條數為0，但不會丟擲異常而終止上報。

多程式問題導致初始化兩個UBC單例的原因有兩類：IPC失敗和程式判斷失敗，兩種問題造成重複打包的表現和原因不同，下文一一進行介紹。


3.2.1 IPC失敗導致多個UBC例項

(1)問題歸因

資料特徵

  • 出現重複的使用者，一批打點重複打包兩次。

  • 兩次打包相隔時間較短（不到1s）。

  • 打包觸發條件中網路恢復、切後臺出現次數較多。

  • 重複的兩條資料打包時程式id和程式名均不同。

原因推測

兩個程式分別存在UBC例項，併發監聽到系統事件，讀取資料庫打包。

進一步歸因

經與多程式框架業務方溝通，梳理了出現兩個UBC單例及重複打包的原因：

1.多程式框架從子程式IPC到主程式時如果發生錯誤，會在子程式觸發IPC失敗打點。

2.該打點呼叫了UBC已廢棄的多程式打點舊介面，舊介面允許在子程式初始化一個UBC的單例，並新增對前後臺切換及網路狀況的監聽。

3.前後臺切換和網路恢復觸發監聽，造成兩個UBC例項同時執行打包。

UBC SDK日誌級別重複率最佳化實踐

佐證歸因

發生重複問題的兩個包，其中一個均存在IPC失敗點位，與分析結論一致。


(2)最佳化方案

針對該問題，經影響面評估，最終執行兩步最佳化：

1.在子程式限制打包，前後臺切換和網路恢復的觸發時機，非主程式不執行打包流程；

2.最佳化多程式打點介面，非主程式下繞開UBC排程邏輯，避免初始化例項，直接將打點寫入檔案等待上報。

最佳化效果

最佳化該問題後，大盤重複率下降至千分之一以下，下降約0.04個百分點，約佔最佳化前的33%。


3.2.3 程式判斷失敗導致多個UBC例項

(1)問題歸因

資料特徵

  • 出現重複的使用者，一批打點重複打包兩次。

  • 兩次打包相隔時間較短（不到1s）。

  • 打包觸發條件中實時觸發佔多數，但存在兩次均是非實時觸發的情況，而正常情況下非實時打包至少應間隔1分鐘以上。

  • 兩次打包其中的一個包存在子程式觸發的打點（如小程式頁面訪問量），但無IPC失敗打點。

原因推測

存在兩個UBC例項，同時有打點A和B進入並觸發打包，兩個UBC例項併發，均查詢到資料庫中的打點C並打包上報。

進一步歸因

  • 結合資料表現和IPC失敗問題最佳化結果，該問題並非IPC失敗導致積壓資料併發上報，而是由打點觸發的多程式併發，因此主要的懷疑點為程式判斷。

UBC SDK日誌級別重複率最佳化實踐

  • 判斷主程式時使用了多程式框架提供的方法，根據當前程式名是否等於包名判斷是否為主程式，獲取當前程式名的邏輯：

    • 讀取記憶體記錄 → 從系統檔案/proc/self/cmdline中獲取 → 從ActivityManager中獲取

    • 若前幾種方式都獲取失敗，則使用包名作為程式名

  • 包名通常與主程式一致，若在子程式以包名作為程式名，則會導致判斷錯誤，從而在子程式初始化另一個UBC單例，造成重複打包問題。

佐證歸因

使用者兩次打包程式名相同、程式id不同，與程式碼分析結論一致。


(2)最佳化方案

UBC作為打點SDK，不宜過多關注程式判斷邏輯，因此需推動多程式框架升級，增加程式名獲取的途徑：

Android API 28新增了獲取程式名的方法Application.getProcessName()，無需反射和IPC，可作為程式名的冗餘判斷方式。

UBC SDK日誌級別重複率最佳化實踐

最佳化效果

  • 程式判斷失敗造成的重複問題約佔新版本重複打包長尾問題的20%

  • 最佳化後程式判斷方式後，一秒內重複打包兩次的情況減少約一半，新版本日誌重複問題僅由不支援該API的低版本裝置造成。

3.3 打點機制相關

3.3.1 reallog

(1)問題歸因

reallog是一種特殊的打點型別，在打點後不進行快取，僅進行一次查詢I/O操作，攜帶歷史失敗資料直接記憶體上報，上報失敗後寫入資料庫。

這種機制是為保證資料極致的上報時效而設定的，但在異常情況下會造成reallog的重複打包：日誌已上報成功並落盤，但服務端結果未及時返回，UBC按失敗邏輯將日誌存入資料庫，並隨下一個reallog打點觸發時被查詢並上報。

UBC SDK日誌級別重複率最佳化實踐

如上圖所示，reallog型別的打點會獨立打包上報，在url中攜帶reallog=1標識。利用此標識對重複資料進行驗證，佐證了reallog造成的重複問題。


（2）最佳化方案

針對reallog問題的最佳化，可採用兩種方案：日誌重複轉為包重複或reallog打點退化為實時打點。

UBC SDK日誌級別重複率最佳化實踐

方案評估：

  • reallog作為一種特殊的打點型別，無法透過日誌中臺配置，僅有極個別業務方使用，屬於不符合中臺規範的打點。

  • 經過多輪時效性最佳化，目前普通實時打點的時效97分位值約0.5分鐘，足夠滿足業務方需求。

對兩種方案的成本和收益進行評估，且與相關業務方進行確認後，最終決定採用透過實驗逐步下線reallog的方式進行最佳化，同時實現UBC點位型別收斂。

最佳化效果

  • reallog造成的新版本長尾重複問題約佔10%左右。

  • 下線reallog後雙端均不再有該型別的重複，且對相關業務方使用無影響。


GEEK TALK

04

總結與展望

準確且高效地上報日誌，是UBC SDK作為日誌中臺資料來源頭的初衷和目標。經過長期的努力，UBC在時效性、到達率上均有了極大的提升，本次針對重複上報的問題進行探索和最佳化，發現並解決了SDK打點過程中存在的各類問題和隱患，將日誌重複率由千分之三降低至千分之一以下，為資料下游提供了更為可靠的資料。

同時，也為各類端打點問題排查積累了寶貴的經驗，最佳化了本地日誌、建設了更為細緻的SDK執行流程監控，為將來快速發現和定位問題打下堅實的資料基礎。

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/70027824/viewspace-2995118/，如需轉載，請註明出處，否則將追究法律責任。

相關文章