UBC SDK日志级别重复率优化实践
点击蓝字，关注我们
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日志管理、存储和发送的基本流程如下图所示：
02
2.1 定位难点及方法论
排查端日志重复问题存在着以下难点：
1.使用UBC的业务方众多，不同点位触发场景不同，出现的问题也不同，无法了感知所有业务的调用方式。
2.日志重复多是小概率的底层异常事件导致，与用户本地环境、系统版本、厂商密切相关，问题难以复现。
3.UBC SDK是数据的入口，牵一发而动全身，任何一个上报流程上的修改都可能造成已有数据的波动，影响业务统计。
因此，这类问题难以通过常用手段排查和优化，UBC在处理过程中逐渐形成了一套方法论：
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 数据库相关问题
立足打点的执行流程，要排查单条日志重复打包的问题，首先想到的就是排查批量日志打包阶段。
该环节逻辑分支较多，且实时与非实时打点执行策略有所不同：
非实时打点触发后先写缓存、再写数据库，达到上报时机后批量查询数据库并触发上报；
实时打点先写入文件触发上报上报，写文件失败才写入数据库，写文件时会查询数据库追加一批非实时打点。
最初分析重复数据中，实时打点较少，多为需要入库的非实时打点和流式打点。因此在重复问题排查的第一阶段，重点对数据库相关问题进行了排查。
打包过程是"将日志从数据库批量转移至文件"的过程，蓝色框所示环节细化如下图所示。
正常情况下，若写文件后删除数据库中已打包日志执行失败，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，但提交事务的结果未被处理，推断为该环节出现未处理的异常导致了事务回滚。
佐证归因
为确定异常原因，对SQL异常监控进行了细化，记录DatabaseHelper类中所有捕获到的异常堆栈。
捞取重复用户的异常监控数据，发现存在大量SQL异常。堆栈如下，db.endTransaction时出现了数据库损坏异常SQLiteDatabaseCorruptException，佐证了代码分析结果。
崩溃堆栈
SQLite官网对于数据库损坏问题也有说明：数据库读写过程中出现文件fsync失败、磁盘损坏、异常数据写入等问题，均有可能造成数据库损坏。
最终归因
数据库损坏可能导致部分日志可读但无法写。
事务提交前更新了删除数据的执行结果，按成功结果处理执行了上报，但由于数据库损坏导致事务回滚，数据未被成功删除。
每次上传成功后会检查数据库条数，超过阈值则会再次触发上传，单个包超限后停止写入，因此造成短时间内大量上报且包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文件真正写入磁盘后才返回结果。
SQLite官方文档中提到：NORMAL模式下，事务的提交在掉电或系统崩溃时可能会被回滚。
佐证归因
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单例时，就可能出现进程不安全的问题，如下图所示。
1.两个进程并发打包并操作数据库，一个进程在另一个进程删除数据前执行查询，则会导致同一批数据被写入两个文件。
2.删除操作执行的前后顺序会导致后一个执行删除的操作因数据不存在而返回删除条数为0，但不会抛出异常而终止上报。
多进程问题导致初始化两个UBC单例的原因有两类：IPC失败和进程判断失败，两种问题造成重复打包的表现和原因不同，下文一一进行介绍。
3.2.1 IPC失败导致多个UBC实例
(1)问题归因
数据特征
出现重复的用户，一批打点重复打包两次。
两次打包相隔时间较短（不到1s）。
打包触发条件中网络恢复、切后台出现次数较多。
重复的两条数据打包时进程id和进程名均不同。
原因推测
两个进程分别存在UBC实例，并发监听到系统事件，读取数据库打包。
进一步归因
经与多进程框架业务方沟通，梳理了出现两个UBC单例及重复打包的原因：
1.多进程框架从子进程IPC到主进程时如果发生错误，会在子进程触发IPC失败打点。
2.该打点调用了UBC已废弃的多进程打点旧接口，旧接口允许在子进程初始化一个UBC的单例，并添加对前后台切换及网络状况的监听。
3.前后台切换和网络恢复触发监听，造成两个UBC实例同时执行打包。
佐证归因
发生重复问题的两个包，其中一个均存在IPC失败点位，与分析结论一致。
(2)优化方案
针对该问题，经影响面评估，最终执行两步优化：
1.在子进程限制打包，前后台切换和网络恢复的触发时机，非主进程不执行打包流程；
2.优化多进程打点接口，非主进程下绕开UBC调度逻辑，避免初始化实例，直接将打点写入文件等待上报。
优化效果
优化该问题后，大盘重复率下降至千分之一以下，下降约0.04个百分点，约占优化前的33%。
3.2.3 进程判断失败导致多个UBC实例
(1)问题归因
数据特征
出现重复的用户，一批打点重复打包两次。
两次打包相隔时间较短（不到1s）。
打包触发条件中实时触发占多数，但存在两次均是非实时触发的情况，而正常情况下非实时打包至少应间隔1分钟以上。
两次打包其中的一个包存在子进程触发的打点（如小程序页面访问量），但无IPC失败打点。
原因推测
存在两个UBC实例，同时有打点A和B进入并触发打包，两个UBC实例并发，均查询到数据库中的打点C并打包上报。
进一步归因
结合数据表现和IPC失败问题优化结果，该问题并非IPC失败导致积压数据并发上报，而是由打点触发的多进程并发，因此主要的怀疑点为进程判断。
判断主进程时使用了多进程框架提供的方法，根据当前进程名是否等于包名判断是否为主进程，获取当前进程名的逻辑：
读取内存记录 → 从系统文件/proc/self/cmdline中获取 → 从ActivityManager中获取
若前几种方式都获取失败，则使用包名作为进程名
包名通常与主进程一致，若在子进程以包名作为进程名，则会导致判断错误，从而在子进程初始化另一个UBC单例，造成重复打包问题。
佐证归因
用户两次打包进程名相同、进程id不同，与代码分析结论一致。
(2)优化方案
UBC作为打点SDK，不宜过多关注进程判断逻辑，因此需推动多进程框架升级，增加进程名获取的途径：
Android API 28新增了获取进程名的方法Application.getProcessName()，无需反射和IPC，可作为进程名的冗余判断方式。
优化效果
进程判断失败造成的重复问题约占新版本重复打包长尾问题的20%
优化后进程判断方式后，一秒内重复打包两次的情况减少约一半，新版本日志重复问题仅由不支持该API的低版本设备造成。
3.3 打点机制相关
3.3.1 reallog
(1)问题归因
reallog是一种特殊的打点类型，在打点后不进行缓存，仅进行一次查询I/O操作，携带历史失败数据直接内存上报，上报失败后写入数据库。
这种机制是为保证数据极致的上报时效而设置的，但在异常情况下会造成reallog的重复打包：日志已上报成功并落盘，但服务端结果未及时返回，UBC按失败逻辑将日志存入数据库，并随下一个reallog打点触发时被查询并上报。
如上图所示，reallog类型的打点会独立打包上报，在url中携带reallog=1标识。利用此标识对重复数据进行验证，佐证了reallog造成的重复问题。
（2）优化方案
针对reallog问题的优化，可采用两种方案：日志重复转为包重复或reallog打点退化为实时打点。
方案评估：
reallog作为一种特殊的打点类型，无法通过日志中台配置，仅有极个别业务方使用，属于不符合中台规范的打点。
经过多轮时效性优化，目前普通实时打点的时效97分位值约0.5分钟，足够满足业务方需求。
对两种方案的成本和收益进行评估，且与相关业务方进行确认后，最终决定采用通过实验逐步下线reallog的方式进行优化，同时实现UBC点位类型收敛。
优化效果
reallog造成的新版本长尾重复问题约占10%左右。
下线reallog后双端均不再有该类型的重复，且对相关业务方使用无影响。
GEEK TALK
04
总结与展望
准确且高效地上报日志，是UBC SDK作为日志中台数据源头的初衷和目标。经过长期的努力，UBC在时效性、到达率上均有了极大的提升，本次针对重复上报的问题进行探索和优化，发现并解决了SDK打点过程中存在的各类问题和隐患，将日志重复率由千分之三降低至千分之一以下，为数据下游提供了更为可靠的数据。
同时，也为各类端打点问题排查积累了宝贵的经验，优化了本地日志、建设了更为细致的SDK执行流程监控，为将来快速发现和定位问题打下坚实的数据基础。
END
推荐阅读