[iOS][日志/功耗] 高频日志逐条打开写入文件，sleep 回调同步等待日志队列

[wangwei354]

环境

• 客户端测试版本：1.0.4
• 平台：iOS
• 场景：VPN 保持连接，设备夜间闲置
• 观测日期：2026-09-09（北京时间，UTC+8）
• 日志记录：开启

本次没有确认 1.0.4 安装包与当前公开源码的精确提交映射。下方源码链接用于说明与设备日志吻合的当前实现路径：Hako-Client b05832246fcac69d13ff16df871a8d53fd394c10，配套 Hako 35c9bb675f1cf5b0befd4290809d06dead728768。

问题概述

Hako-Client 的日志存储在正常运行阶段把每条日志异步提交到一个串行队列，但队列内部仍然逐条执行：

1. 查询目标文件属性和当前大小；
2. 创建 Data；
3. 打开 FileHandle；
4. seek 到文件末尾；
5. 写入一条日志；
6. 关闭文件句柄。

此外，Packet Tunnel 收到每次 NEProvider.sleep() 后，会追加一条 provider sleep 日志，然后通过 queue.sync {} 等待此前排队的所有日志写入返回。

在低日志量下这些操作可能不明显；但当内核短时间产生大量日志时，客户端会把日志条数直接放大为文件属性查询、文件打开、seek、写入和关闭次数，并可能在高频 sleep 回调中反复等待整个队列。

本问题关注 Hako-Client 的日志持久化机制。产生大量 [Memory] probe admission 日志的 Hako 内核原因应在独立 Issue 中限频或修正；即使日志源得到修复，日志存储仍应能以有界方式处理其它突发日志和高业务量场景。

设备日志证据

按北京时间分析 2026-09-09 05:23–06:00：

• core 日志 15,747 条，其中 15,737 条为同类后台 probe admission 日志。
• App 日志 557 条，几乎全部为 provider sleep/wake。
• 两个 stream 合计至少形成 16,304 次日志 append。
• core 日志约 2,928,943 字节，App 日志约 30,913 字节，合计约 2.96 MB。
• 区间长度约 37 分钟，平均约每秒 7.35 条持久化日志。
• 同期有 278 次 provider sleep；当前实现会在每次 sleep 中追加日志并执行一次同步队列屏障。
• 更长的 01:01:14–05:59:57 区间共记录 2146 组 sleep/wake，因此可能有 2146 次 sleep flush。

完整导出中保留：

• core 日志 97,635 条、约 18.16 MB；
• 其中 95,926 条为 [Memory] probe admission；
• App 日志约 0.59 MB；
• core stream 的单日上限为 20 MiB，超过上限时会读取并保留旧文件后半部分，再替换原文件。

导出的 core 日志从一个 probe 批次中途开始，与旧日志已发生容量裁剪的行为吻合。该现象主要由上游日志风暴触发，但轮转过程本身也会增加文件读取、临时文件写入和 replace 操作。

脱敏样本见
issue-sample-ios-logstore-per-line-io-1.0.4.log

与当前源码吻合的调用链

1. Hako core 通过 ExtensionProvider.writeLog() 进入平台日志，同时调用 HakoLogStore.append(..., stream: .core)。
2. HakoLogStore.append() 在隧道启动完成后，把每条日志分别提交到串行 DispatchQueue。
3. HakoLogStore.write() 对每条日志分别查询文件大小、打开句柄、seek、写入并关闭。
4. HakoLogStore.flush() 是一个空的 queue.sync {}，用于等待先前排队任务执行完成。
5. ExtensionProvider.sleep() 在每次 sleep 中追加生命周期日志并立即调用 flush。
6. HakoLogStream.bytesPerDay 为 core 设置 20 MiB、App 设置 1 MiB 上限。
7. 达到上限时，dropOldestHalf 读取后半文件内容写入临时文件，再替换原文件。

可能影响

• 高频日志量被转换为同等数量级的文件系统元数据查询、句柄打开/关闭和小块写入；
• 串行队列处理速度不足时形成积压，占用内存并延后日志落盘；
• sleep 回调中的同步屏障可能等待此前的 core 日志队列，从而延长生命周期回调返回时间；
• 日志接近上限时，裁剪旧文件会产生额外读取、临时写入和文件替换；
• 高频小写入可能增加 CPU、文件系统和存储活动。

FileHandle.close() 不等同于每条日志都执行物理 fsync，操作系统也可能合并缓存写入。因此当前证据不能把日志条数直接换算成 NAND 写入次数、硬件唤醒或固定耗电比例。

期望行为

• 正常运行阶段以有界批次追加日志，减少每条日志的元数据和句柄操作；
• 在安全生命周期内复用文件句柄，或者由单一 writer 明确管理打开、轮转和关闭；
• 日志队列必须有明确容量和溢出策略，不能因日志风暴无限增长；
• critical/error 和启动失败日志继续及时保存；普通 info 日志允许短时间合并；
• sleep 不应在每次短暂回调中无条件等待大量普通日志写入；
• 导出、清理、日期切换、容量轮转和进程终止时保持文件完整性。

建议的最小改进方向

1. 在现有串行 writer 上增加按条数或总字节数触发的有界批量 append；队列空时不保留短周期定时器。
2. 由 writer 复用当前 stream/day 的文件句柄，在日期变化、轮转、导出屏障、清理和停止时关闭或重新打开。
3. 为待写队列设置上限；达到上限时优先保留 warning/error，并对丢弃的 info/debug 输出低频汇总计数。
4. 将 sleep 行为改为只确保关键日志或已有小批次提交，不对所有普通 core 日志执行无界同步等待。
5. 将轮转检查从逐条 attributesOfItem 改为 writer 内维护的已写字节计数，并在打开文件时校准。
6. 保留显式 flush() API 供导出、停止隧道和关键故障路径使用，明确它是队列屏障还是要求持久化到存储。

建议验证

1. 使用低日志量、持续普通流量和与本次相同的日志风暴三类负载，对比文件操作次数、writer CPU 时间和队列峰值。
2. 比较逐条写入与有界批量写入下 Packet Tunnel Extension 的 CPU 时间、系统活动和每小时耗电。
3. 在写入期间触发 sleep/wake，记录 sleep 回调中等待日志队列的耗时分位数。
4. 覆盖进程被系统终止、崩溃、stopTunnel、跨 UTC 日期、达到容量上限、导出和清空日志。
5. 确认 warning/error 及时可见，普通日志允许的最大丢失窗口符合产品预期。
6. 与 Hako 内核的日志限频修复分别测试，区分“减少日志产生量”和“提高客户端日志 sink 效率”的收益。

边界

• 本次日志可以确认日志量、sleep 次数和当前逐条写入实现，不能从导出文件推导真实物理存储写入次数。
• flush() 当前是 DispatchQueue 同步屏障，不是显式 fsync。
• 上游 probe 日志风暴是本次高负载的直接来源，应在 Hako 内核独立修复；本 Issue 不要求客户端吞下无限日志。
• 当前没有文件系统 Instruments profile，不能承诺该问题单独造成的电量比例。
• 本问题建议提交到 Hako-Client；Hako 内核只负责减少不必要的日志源。

[TokenPLS]

日志问题在iOS 1.0.6大幅度改善，且默认不写日志了。