系列文章《客户端可观测性进阶实战》第 3 篇
推荐阅读时间:10 分钟
前言
前两篇讲了 Trace 和 Metric。Trace 还原时间线,Metric 反映全局趋势,但线上排障时最常用的还是 Log。用户反馈一个问题,你打开后台面板,第一件事就是搜日志。
问题是,大多数团队的日志体系是这样的:几十个模块各打各的,格式不统一,没有关联 ID,搜索时只能靠肉眼一页页翻。一个 ANR 问题的定位可能要从 20 万条日志里捞线索,耗时半天。
这篇收尾,讲三个话题:
结构化日志怎么设计,怎么分级
Trace ID 如何把 Log、Metric、Trace 三支柱打通
一个线上 ANR 的完整定位过程
一、结构化日志设计
1.1 为什么不能用纯文本日志
纯文本日志最大的问题是不可查询。你打了一条 Log.d("Net", "request failed: timeout, url=/api/user/profile, retry=3"),搜索时只能做模糊匹配。如果要统计"所有 timeout 的请求按 URL 聚合",纯文本做不到。
结构化日志的核心思路:每条日志是一个 JSON 对象,字段固定,值可枚举。服务端收到后可以直接做聚合查询。
data class StructuredLog(
val timestamp: Long,
val level: LogLevel,
val module: String, // 来源模块
val event: String, // 事件名,枚举值
val traceId: String?, // 关联 Trace ID
val message: String, // 人类可读描述
val fields: Map<String, String>, // 结构化附加字段
val throwable: Throwable? // 异常信息
)
1.2 日志级别体系
很多团队的日志级别形同虚设——全用 Log.d,或者全用 Log.e。一个可用的级别体系应该和线上策略绑定:
关键点:VERBOSE 在线上完全不采集。端侧日志缓冲区有限,如果全量采集 VERBOSE 级别,真正有价值的 ERROR 会被淹没。
1.3 日志采集器实现
一个生产可用的结构化日志采集器:
class StructuredLogger(
private val buffer: LogBuffer,
private val config: LogConfig
) {
fun log(
level: LogLevel,
module: String,
event: String,
message: String = "",
fields: Map<String, String> = emptyMap(),
throwable: Throwable? = null
) {
// 级别过滤
if (level.priority < config.minLevel(module).priority) return
val entry = StructuredLog(
timestamp = System.currentTimeMillis(),
level = level,
module = module,
event = event,
traceId = TraceContextHolder.currentTraceId(),
message = message,
fields = sanitizeFields(fields),
throwable = throwable
)
buffer.add(entry)
// ERROR 级别立即上报
if (level == LogLevel.ERROR) {
buffer.flush()
}
}
private fun sanitizeFields(fields: Map<String, String>): Map<String, String> {
val sanitized = LinkedHashMap<String, String>(fields.size)
for ((key, value) in fields) {
// 脱敏:移除可能包含用户信息的字段
if (key in config.sensitiveKeys) {
sanitized[key] = "***"
} else {
sanitized[key] = value
}
}
return sanitized
}
}
sanitizeFields 负责脱敏。哪些字段需要脱敏通过远程配置下发,可以根据隐私政策调整。常见的敏感 key 包括 phone、idCard、token、password 等。
1.4 日志缓冲与上报
日志缓冲区和 Metric 的聚合桶思路类似,但有两个特殊点:
ERROR 级别需要立即上报,不能等时间窗口
日志不能在崩溃时丢失——如果 App 崩溃了,最后几条日志是定位问题的关键
class LogBuffer(
private val maxEntries: Int = 2000,
private val flushIntervalMs: Long = 60_000L
) {
// 环形缓冲区,保留最近 N 条日志
private val ringBuffer = ArrayDeque<StructuredLog>(maxEntries)
private val lock = ReentrantLock()
fun add(entry: StructuredLog) {
lock.withLock {
if (ringBuffer.size >= maxEntries) {
ringBuffer.removeFirst()
}
ringBuffer.addLast(entry)
}
}
fun snapshot(): List<StructuredLog> {
lock.withLock {
return ringBuffer.toList()
}
}
// 崩溃时调用:把缓冲区内容写入文件
fun crashFlush() {
val entries = snapshot()
val json = entries.joinToString("\n") { it.toJson() }
// 写入 crash-specific 日志文件
crashLogWriter.write(json)
}
}
在 Thread.UncaughtExceptionHandler 里调用 crashFlush,保证崩溃前的日志不会丢:
class CrashHandler(private val logBuffer: LogBuffer) : Thread.UncaughtExceptionHandler {
private val defaultHandler = Thread.getDefaultUncaughtExceptionHandler()
override fun uncaughtException(t: Thread, e: Throwable) {
// 先把日志落盘
logBuffer.crashFlush()
// 再上报崩溃
CrashReporter.report(e, logBuffer.snapshot().takeLast(100))
// 交给默认处理器
defaultHandler?.uncaughtException(t, e)
}
}
二、三支柱关联打通
2.1 Trace ID 是纽带
上一篇讲了 Trace ID 的生成和传递。这里的关键是让 Trace ID 出现在所有三支柱的数据里:
用户操作 → 生成 Trace ID
├── Trace slice 带 Trace ID
├── Metric record 带 Trace ID
└── Log entry 带 Trace ID
这样排查问题时,用一个 Trace ID 可以同时拉出 trace 时间线、metric 指标快照和日志明细。三支柱从独立的数据孤岛变成可关联的整体。
2.2 Log 关联 Trace
在 StructuredLogger 的实现里,每条日志自动从 TraceContextHolder 取当前 Trace ID:
object TraceContextHolder {
private val threadLocal = ThreadLocal<String?>()
fun setTraceId(id: String?) {
threadLocal.set(id)
}
fun currentTraceId(): String? = threadLocal.get()
fun clear() {
threadLocal.remove()
}
}
在业务入口设置 Trace ID:
fun onUserAction(action: UserAction) {
val traceId = TraceIdGenerator.generate()
TraceContextHolder.setTraceId(traceId)
logger.log(LogLevel.INFO, "user", "action_start",
message = "user triggered ${action.name}",
fields = mapOf("action" to action.name)
)
TraceUtil.traceSync("UserAction:${action.name}") {
actionHandler.handle(action)
}
TraceContextHolder.clear()
}
所有在这期间产生的日志和 Trace 都带同一个 Trace ID。
2.3 Metric 关联 Trace
Metric 的 tags 里也带上 Trace ID,这样从指标看板发现异常后,可以下钻到具体的 trace:
fun recordTimingWithTrace(name: String, durationMs: Long, tags: Map<String, String>) {
val traceId = TraceContextHolder.currentTraceId()
val fullTags = if (traceId != null) {
tags + ("trace_id" to traceId)
} else {
tags
}
metricCollector.recordTiming(name, durationMs, fullTags)
}
2.4 查询联动
三支柱打通后,排查一个问题的标准流程变成:
看 Metric 看板,发现某指标突增(如冷启动 P99 涨了 1 秒)
查 Metric 数据,取出突增时间窗口的异常 Trace ID 列表
用 Trace ID 查日志,看那个时间窗口的日志明细
用 Trace ID 拉 Perfetto trace(如果该设备有采样),看时间线
定位到具体原因,修复
以前是"翻日志"——在 20 万条日志里找线索。现在是"查 ID"——一个 Trace ID 串联所有数据。
三、线上问题定位实战
3.1 案例背景
某天下午,线上监控告警:Android 端 ANR 率从 0.02% 突增到 0.15%。同时收到用户反馈:“首页打开后白屏几秒,然后弹无响应弹窗。”
3.2 第一步:Metric 看板定位范围
打开 ANR 看板,按维度分桶:
结论:v3.2.1 版本 + Xiaomi 12 机型 + 首页场景是重灾区。
3.3 第二步:Trace ID 查日志
从 ANR 上报里取出几个 Xiaomi 12 上的 ANR trace ID。用其中一个查日志:
SELECT * FROM logs
WHERE trace_id = '18f3a2b4-1c2d-4e3f'
ORDER BY timestamp ASC
返回结果里关键几条:
14:32:01.234 INFO home page_init 用户进入首页
14:32:01.567 INFO net request_start 请求首页推荐列表
14:32:01.568 INFO net request_start 请求首页 Banner
14:32:01.569 INFO db query_start 查询本地缓存
14:32:04.231 WARN db query_timeout 缓存查询超时 2600ms
14:32:04.232 ERROR net request_error 推荐列表请求失败: timeout
14:32:05.100 ANR system anr_detected 主线程阻塞超过 5s
时间线很清楚:14:32:01 发起请求和 DB 查询,14:32:04 DB 查询超时 2.6 秒,14:32:05 触发 ANR。
3.4 第三步:Trace 看时间线
如果该设备恰好命中 Trace 采样(0.1%),可以拉到 Perfetto trace。在 trace 里搜索这个 Trace ID 对应的 slice:
Home:loadData (3800ms)
├── Net:recommend (3200ms) ← 推荐列表请求,超时
│ ├── DNS (45ms)
│ ├── TCP connect (120ms)
│ └── request wait (3035ms) ← 服务端或网络层慢
└── DB:cache:query (2600ms) ← DB 查询也很慢
└── SQLite query (2600ms)
两条线索并行出现:网络请求超时 3 秒,同时 DB 查询耗时 2.6 秒。两者在主线程串行执行,总耗时接近 4 秒。
3.5 第四步:根因定位
查 DB 查询的代码,发现首页的本地缓存查询用了 Room,但没加索引:
@Query("SELECT * FROM home_cache WHERE page_type = :pageType ORDER BY update_time DESC")
fun queryCache(pageType: String): HomeCache?
page_type 字段没有建索引。数据量小时查询很快,但 Xiaomi 12 上的缓存表有 12 万条记录(用户是重度用户),全表扫描需要 2.6 秒。
网络请求超时是因为 DNS 解析到了一个慢节点。但这不是根因——正常情况下即使网络慢,DB 查询应该先返回数据让用户看到内容,网络请求在后台刷新。问题是 DB 查询也卡在主线程,导致两者串行阻塞。
3.6 第五步:修复
两处修复:
DB 查询加索引:
@Entity(tableName = "home_cache", indices = [Index("page_type")])
data class HomeCache(
@PrimaryKey val id: Long,
val page_type: String,
val update_time: Long,
val data: String
)
网络请求移到 IO 线程,DB 查询用
Flow异步返回:
fun loadHomeData(): Flow<HomeData> = flow {
// 先从 DB 读,快速展示
val cache = withContext(Dispatchers.IO) {
cacheDao.queryCache("home")
}
if (cache != null) {
emit(HomeData.fromCache(cache))
}
// 后台请求网络,拿到后更新
val fresh = withContext(Dispatchers.IO) {
api.fetchHomeRecommend()
}
emit(fresh)
cacheDao.insert(HomeCache.from(fresh))
}.flowOn(Dispatchers.IO)
修复后,ANR 率回到 0.02%。整个定位过程从告警到修复不到 2 小时。
四、平台化建议
4.1 三支柱统一入口
三个支柱最终应该收敛到一个查询入口。用户输入一个 Trace ID,平台同时返回:
4.2 自动归因
下一步是自动归因。当 Metric 告警触发后,平台自动做:
取告警窗口的异常 Trace ID 列表
对异常 Trace 做聚类,找出共同模式(如"都卡在 DB 查询")
和历史正常 Trace 对比,定位差异 slice
自动生成归因报告,推送到告警群
这个流程目前需要人工分析,但基础设施(统一 Trace ID + 结构化日志 + Metric 关联)是自动化的前提。
小结
三篇文章构成了客户端可观测性进阶的完整图景:
第一篇 Trace:还原时间线,定位"什么导致什么"
第二篇 Metric:量化全局趋势,发现"多少次、多久"
第三篇 Log:记录细节,配合 Trace ID 实现三支柱关联
三支柱不是三个独立工具,而是通过 Trace ID 打通的统一体系。建设顺序上,建议先做 Log(成本最低、收益最直接),再做 Metric(需要服务端配合),最后做 Trace(需要 Perfetto 采集和采样策略)。
线上问题定位的效率,取决于这三条线的关联程度。一个 Trace ID 串联全部数据,从"翻日志"变成"查 ID",这才是可观测性体系的价值。
参考阅读
本系列第 1 篇:Trace 体系深度实战
本系列第 2 篇:Metric 指标采集与监控看板
OpenTelemetry 规范:https://opentelemetry.io/docs/specs/