客户端日志&埋点&上报的性能优化
引子
高性能 I/O
有时候为了排查线上偶现问题，会尽可能地在关键业务点打 Log 并文件化，再上传到云以便排查。
在一些高强度业务场景中的高频模块，比如直播间中的 IM，瞬间产生几百上千条 Log 是家常便饭，这就对 Log 库的性能提出了要求（CPU 和内存）。
Okio
如何高性能地 I/O？
第一个想到的是Okio。关于为啥 Okio 的性能与好于 java.io 包的流，之后会专门写一篇分析文章。
重新写一个 Okio 版本的日志拦截器：
class OkioLogInterceptor private constructor(private var dir: String) : LogInterceptor {
private val handlerThread = HandlerThread("log_to_file_thread")
private val handler: Handler
private val dispatcher: CoroutineDispatcher
// 写日志的开始时间
var startTime = System.currentTimeMillis()
companion object {
@Volatile
private var INSTANCE: OkioLogInterceptor? = null
fun getInstance(dir: String): OkioLogInterceptor =
INSTANCE ?: synchronized(this) {
INSTANCE ?: OkioLogInterceptor(dir).apply { INSTANCE = this }
}
}
init {
handlerThread.start()
handler = Handler(handlerThread.looper)
dispatcher = handler.asCoroutineDispatcher("log_to_file_dispatcher")
}
override fun log(priority: Int, tag: String, log: String, chain: Chain) {
if (!handlerThread.isAlive) handlerThread.start()
GlobalScope.launch(dispatcher) {
// 使用 Okio 写文件
val file = File(getFileName())
file.sink(true).buffer().use {
it.writeUtf8("[$tag] $log")
it.writeUtf8("\n")
}
// 写日志结束时间
if (log == "work done") Log.v("ttaylor1","log() work is done=${System.currentTimeMillis() - startTime}")
}
chain.proceed(priority, tag, log)
}
private fun getToday(): String =
SimpleDateFormat("yyyy-MM-dd").format(Calendar.getInstance().time)
private fun getFileName() = "$dir${File.separator}${getToday()}.log"
}
FileWriter vs Okio 性能 PK
为了测试 Okio 和 FileWriter 的性能差异，编写了如下测试代码：
class LogActivity : AppCompatActivity() {
override fun onCreate(savedInstanceState: Bundle?) {
super.onCreate(savedInstanceState)
// 添加 FileWriter 或者 Okio 日志拦截器
EasyLog.addInterceptor(OkioLogInterceptor.getInstance(this.filesDir.absolutePath))
// EasyLog.addInterceptor(FileWriterLogInterceptor.getInstance(this.filesDir.absolutePath))
// 重复输出 1 万条短 log
MainScope().launch(Dispatchers.Default) { count ->
repeat(10000){
EasyLog.v("test log count=$count")
}
EasyLog.v("work done")
}
}
}
测试方案：重复输入 1 万条短 log，并且从写第一条 log 开始计时，直到最后一条 log 的 I/O 完成时输出耗时。
Okio 和 FileWriter 三次测试的对比耗时如下：
// okio
ttaylor1: log() work is done=9600
ttaylor1: log() work is done=9822
ttaylor1: log() work is done=9411
// FileWriter
ttaylor1: log() work is done=10688
ttaylor1: log() work is done=10816
ttaylor1: log() work is done=11928
看上去 Okio 在耗时上有微弱的优势。
但当我把单条 Log 的长度增加 300 倍之后，测试结果出现了反转：
// FileWriter
ttaylor1: log() work is done=13569
ttaylor1: log() work is done=12654
ttaylor1: log() work is done=13152
// okio
ttaylor1: log() work is done=14136
ttaylor1: log() work is done=15451
ttaylor1: log() work is done=15292
也就是说 Okio 在高频少量 I/O 场景性能好于 FileWriter，而高频大量 I/O 场景下没有性能优势。
这个结果让我很困惑，于是乎我在 Github 上提了 issue:
没想到瞬间就被回复了：
我的提问的本意是想确认下使用 Okio 的姿势是否得当，但没想到官方回答却是：“Okio 库就是这样的，你的测试数据是符合预期的。我们在“用自己的 UTF-8 编码以减少大量垃圾回收”和性能上做了权衡。所以导致有些测试场景下性能好，有些场景下性能没那么好。我们的期望是在真实的业务场景下 Okio 的性能会表现的好。”
不知道我翻译的准不准确，若有误翻望英语大佬指点~
这样的结果不能让我满意，隐约觉得 Okio 的使用方式有优化空间，于是我一直凝视下面这段代码：
override fun log(priority: Int, tag: String, log: String) {
GlobalScope.launch(dispatcher) {
val file = File(getFileName())
file.sink(true).buffer().use {
it.writeUtf8("[$tag] $log")
it.writeUtf8("\n")
}
}
return false
}
代码洁癖告诉我，这里有几个可以优化的地方：
- 不用每次打 Log 都新建 File 对象。
- 不用每次打 Log 都新建输出流，每次打完就关闭流。
于是我改造了 Okio 日志拦截器：
class OkioLogInterceptor private constructor(private var dir: String) : LogInterceptor {
private val handlerThread = HandlerThread("log_to_file_thread")
private val handler: Handler
private val dispatcher: CoroutineDispatcher
private var bufferedSink: BufferedSink? = null
// 初始化时，只新建一次文件
private var logFile = File(getFileName())
var startTime = System.currentTimeMillis()
companion object {
@Volatile
private var INSTANCE: OkioLogInterceptor? = null
fun getInstance(dir: String): OkioLogInterceptor =
INSTANCE ?: synchronized(this) {
INSTANCE ?: OkioLogInterceptor(dir).apply { INSTANCE = this }
}
}
init {
handlerThread.start()
handler = Handler(handlerThread.looper)
dispatcher = handler.asCoroutineDispatcher("log_to_file_dispatcher")
}
override fun log(priority: Int, tag: String, log: String, chain: Chain){
if (!handlerThread.isAlive) handlerThread.start()
GlobalScope.launch(dispatcher) {
val sink = checkSink()
sink.writeUtf8("[$tag] $log")
sink.writeUtf8("\n")
if (log == "work done") Log.v("ttaylor1","log() work is ok done=${System.currentTimeMillis() - startTime}")
}
chain.proceed(priority, tag, log)
}
private fun getToday(): String =
SimpleDateFormat("yyyy-MM-dd").format(Calendar.getInstance().time)
private fun getFileName() = "$dir${File.separator}${getToday()}.log"
// 不关流，复用 bufferedSink 对象
private fun checkSink(): BufferedSink {
if (bufferedSink == null) {
bufferedSink = logFile.appendingSink().buffer()
}
return bufferedSink!!
}
}
新增了成员变量 logFile 和 bufferedSink，避免了每次打 Log 时重新构建它们。而且我没有在每次打完 Log 就把输出流关闭掉。
重新跑一下测试代码，奇迹发生了：
ttaylor1: log() work is done=832
1万条 Log 写入的时间从 9411 ms 缩短到 832 ms，整整缩短了 11 倍！！
这个结果有点难以置信，我连忙从手机中拉取了日志文件，非常担心是因为程序 bug 导致日志输出不全。
果不其然，正确的日志文件应该包含 1 万行，而现在只有 9901 行。
转念一下，不对啊，一次flush()都没有调用，为啥文件中会有日志？
哦~，肯定是因为内存中的输出缓冲区满了之后自动进行了 flush 操作。
然后我用同样的思路写了一个 FileWriter 的版本，跑了一下测试代码：
ttaylor1: FileWriter log() work is done=1239
这下可把 FileWriter 和 Okio 的差距显现出来了，将近 50 %的速度差距。
但是。。。我才意识到这个比对是不公平的。Okio 使用了缓存，而 java.io 没使用。
改了下测试代码，在 FileWriter 外套了一层 BufferedWriter，再跑一下：
ttaylor1: BufferedWriter log() work is done=1023
速度果然有提升，但还是比 Okio 慢了 25% 左右。
算是为技术选型 Okio 提供了数据支持！
感知日志打印结束？
但还有一个问题急需解决：Log 输出不全。
这是因为当最后一条日志写入缓冲区时，若缓冲区未满就不会执行 flush 操作。这种情况下需要手动 flush。
如何感知到最后一条 Log？做不到！因为打 Log 是业务层行为，底层 Log 库无法感知上层行为。
这个场景让我联想到 “搜索框防抖”，即当你在键入关键词后，自动发起搜索的行为。
用流的思想理解上面的场景：输入框是流数据的生产者，其内容每变化一次，就是在流上生产了一个新数据。但并不是每一个数据都需要被消费，所以得做“限流”，即丢弃一切发射间隔过短的数据，直到生产出某个数据之后一段时间内不再有新数据。
Flow 的操作符debounce()就非常契合这个场景。
它的背后机制是：每当流产生新数据时，开启倒计时，如果在倒计时归零之前没有新数据，则将最后那个数据发射出去，否则重新开启倒计时。关于 Flow 限流的应用场景及原理分析可以点击
知道了背后的机制，就不需要拘泥于具体的实现方式，使用 Android 中的消息机制也能实现同样的效果（日志拦截器正好使用了 HandlerThread，现成的消息机制）。
每当新日志到来时，将其封装为一条消息发送给 Handler，紧接着再发送一条延迟消息，若有后续日志，则移除延迟消息，并重发一条新延迟消息。若无后续日志，Handler 终将收到延迟消息，此时就执行 flush 操作。
（Android 中判定 Activity 生命周期超时也是用这套机制，感兴趣的可以搜索com.android.server.wm.ActivityStack.STOP_TIMEOUT_MSG）
改造后的日志拦截器如下：
class OkioLogInterceptor private constructor(private var dir: String) : LogInterceptor {
private val handlerThread = HandlerThread("log_to_file_thread")
private val handler: Handler
private var startTime = System.currentTimeMillis()
private var bufferedSink: BufferedSink? = null
private var logFile = File(getFileName())
// 日志消息处理器
val callback = Handler.Callback { message ->
val sink = checkSink()
when (message.what) {
// flush 日志
TYPE_FLUSH -> {
sink.use {
it.flush()
bufferedSink = null
}
}
// 写日志
TYPE_LOG -> {
val log = message.obj as String
sink.writeUtf8(log)
sink.writeUtf8("\n")
}
}
// 统计耗时
if (message.obj as? String == "work done") Log.v(
"ttaylor1",
"log() work is done=${System.currentTimeMillis() - startTime}"
)
false
}
companion object {
private const val TYPE_FLUSH = -1
private const val TYPE_LOG = 1
// 若 3000 ms 内没有新日志请求，则执行 flush
private const val FLUSH_LOG_DELAY_MILLIS = 3000L
@Volatile
private var INSTANCE: OkioLogInterceptor? = null
fun getInstance(dir: String): OkioLogInterceptor =
INSTANCE ?: synchronized(this) {
INSTANCE ?: OkioLogInterceptor(dir).apply { INSTANCE = this }
}
}
init {
handlerThread.start()
handler = Handler(handlerThread.looper, callback)
}
override fun log(priority: Int, tag: String, log: String, chain: Chain) {
if (!handlerThread.isAlive) handlerThread.start()
handler.run {
// 移除上一个延迟消息
removeMessages(TYPE_FLUSH)
// 将日志作为一条消息发送出去
obtainMessage(TYPE_LOG, "[$tag] log").sendToTarget()
// 构建延迟消息并发送
val flushMessage = handler.obtainMessage(TYPE_FLUSH)
sendMessageDelayed(flushMessage, FLUSH_LOG_DELAY_MILLIS)
}
chain.proceed(priority, tag, log)
}
private fun getToday(): String =
SimpleDateFormat("yyyy-MM-dd").format(Calendar.getInstance().time)
private fun getFileName() = "$dir${File.separator}${getToday()}.log"
private fun checkSink(): BufferedSink {
if (bufferedSink == null) {
bufferedSink = logFile.appendingSink().buffer()
}
return bufferedSink!!
}
}
压缩日志
将日志日内容压缩不仅能进一步提升I/O性能，减少客户端日志上传的流量，还能为公司省钱（云存储都挺贵的）。
Gzip 是一种常用的压缩格式。Linux 就用这种格式压缩文件。除了用在文件压缩，Gzip 还用于网络压缩，它是在RFC 2016中规定的三种标准HTTP压缩格式之一。
关于 Gzip 压缩格式的详细介绍可以点击这里。
借助于装饰者模式、适配器模式、以及 Kotlin 的扩展方法语法，为原先的输出流新增 Gzip 功能很简单。
原先构建输出流的代码如下：
val bufferedSink = logFile.appendingSink().buffer()
其中appendingSink()和buffer()都是扩展方法：
fun File.appendingSink(): Sink = FileOutputStream(this, true).sink()
fun OutputStream.sink(): Sink = OutputStreamSink(this, Timeout())
fun Sink.buffer(): BufferedSink = RealBufferedSink(this)
即先构建了 FileOutputStream，然后将其适配成 OutputStreamSink，再装饰成 RealBufferedSink，最终形成 RealBufferedSink( OutputStreamSink( FileOutputStream( File ) ) )这样套娃的结构。
Okio 中实现 Gzip 压缩输出的类叫GzipSink，它也有类似的装饰构造方法：
inline fun Sink.gzip() = GzipSink(this)
只需在原有调用链上插入 gzip() 即可实现压缩：
val bufferedSink = logFile.appendingSink().gzip().buffer()
现在的套娃结构变成RealBufferedSink( GzipSink( OutputStreamSink( FileOutputStream( File ) ) ) )
跑了一下测试程序，测试方法为连续输出1万条长log，不使用 Gzip 时，日志文件大小为 251 MB，加了 Gzip 之后，只有 2.1 MB。整整缩小了是 100+ 倍。
把日志文件的后缀改成gz，这样从云端下载之后就能直接只用压缩软件解压看到原始日志。
为了对比加入压缩后 Okio 和 java.io 的速度性能差异，重写了 java.io 版压缩输出流的代码：
val outputStream = logFile.outputStream().gzip().writer().buffered()
其中outputStream()和buffered()是系统预定的装饰流扩展方法：
// 构造 FileOutputStream 并持有 File 实例
public inline fun File.outputStream(): FileOutputStream {
return FileOutputStream(this)
}
// 构造 BufferedWriter 并持有 Writer 实例
public inline fun Writer.buffered(bufferSize: Int = DEFAULT_BUFFER_SIZE): BufferedWriter =
if (this is BufferedWriter) this else BufferedWriter(this, bufferSize)
而gzip()和writer()是自定义的装饰流扩展方法：
// 构建 GZIPOutputStream 并持有 OutputStream
fun OutputStream.gzip() = GZIPOutputStream(this)
// 构建 OutputStreamWriter 并持有 OutputStream
fun OutputStream.writer(charset: Charset = Charsets.UTF_8) = OutputStreamWriter(this, charset)
GZIPOutputStream是针对 OutputStream 的，所以不得不使用 OutputStreamWrite 将 Writer 接口适配成 OuptStream 接口。
完整的 java.io 版压缩日志拦截器代码如下：
class FileWriterLogInterceptor private constructor(private var dir: String) : LogInterceptor {
private val handlerThread = HandlerThread("log_to_file_thread")
private val handler: Handler
// 统计耗时起点
private var startTime = System.currentTimeMillis()
// 用于记录平均内存的列表
private val memorys = mutableListOf<Long>()
private var fileWriter: Writer? = null
private var logFile = File(getFileName())
val callback = Handler.Callback { message ->
val sink = checkFileWriter()
// 每来一条日志，记录此时的内存占用
memorys.add(Runtime.getRuntime().totalMemory()/(1024*1024))
when (message.what) {
// 输出日志结束的标记
TYPE_FLUSH -> {
sink.use {
it.flush()
fileWriter = null
}
// 统计耗时即内存终点
Log.v(
"test",
"fileWriter work is ok done=${System.currentTimeMillis() - startTime, memory=${memorys.average()}"
)
}
// 正常写日志
TYPE_LOG -> {
val log = message.obj as String
sink.write(log)
sink.write("\n")
}
}
false
}
companion object {
private const val TYPE_FLUSH = -1
private const val TYPE_LOG = 1
// 若 300 ms 无日志请求，则进行冲刷
private const val FLUSH_LOG_DELAY_MILLIS = 300L
// 设计单例，防止启动多个写日志线程
@Volatile
private var INSTANCE: FileWriterLogInterceptor? = null
fun getInstance(dir: String): FileWriterLogInterceptor =
INSTANCE ?: synchronized(this) {
INSTANCE ?: FileWriterLogInterceptor(dir).apply { INSTANCE = this }
}
}
// 启动写日志线程
init {
handlerThread.start()
handler = Handler(handlerThread.looper, callback)
}
override fun log(priority: Int, tag: String, log: String, chain: Chain) {
if (!handlerThread.isAlive) handlerThread.start()
handler.run {
removeMessages(TYPE_FLUSH)
obtainMessage(TYPE_LOG, "[$tag] $log").sendToTarget()
val flushMessage = handler.obtainMessage(TYPE_FLUSH)
// 倒计时，用于判断“已经无新日志”
sendMessageDelayed(flushMessage, FLUSH_LOG_DELAY_MILLIS)
}
chain.proceed(priority, tag, log)
}
override fun enable(): Boolean { return true }
// 以今天日期为文件名
private fun getToday(): String = SimpleDateFormat("yyyy-MM-dd").format(Calendar.getInstance().time)
private fun getFileName() = "$dir${File.separator}${getToday()}.log"
// 构建 java.io 压缩文件输出流
private fun checkFileWriter(): Writer {
if (fileWriter == null) {
fileWriter = logFile.outputStream().gzip().writer().buffered()
}
return fileWriter!!
}
// 自定义装饰流构造方法，以简化流构建代码
private fun OutputStream.gzip() = GZIPOutputStream(this)
private fun OutputStream.writer(charset: Charset = Charsets.UTF_8) = OutputStreamWriter(this, charset)
}
下面是测试代码：
// 分别给 EasyLog 配置 Okio 日志拦截器和 FileWriter 日志拦截器
//EasyLog.addInterceptor(FileWriterLogInterceptor.getInstance(this.filesDir.absolutePath))
EasyLog.addInterceptor(OkioLogInterceptor.getInstance(this.filesDir.absolutePath))
MainScope().launch(Dispatchers.Default) {
// 连续输出1万条日志并压缩
repeat(10_000) {
EasyLog.v(str4, "test")
}
}
输出日志如下：
fileWriter work is ok done=5130, memory=160.70305938812237
fileWriter work is ok done=5172, memory=157.5844831033793
fileWriter work is ok done=5155, memory=168.01649670065987
Okio work is ok done=4765, memory=130.96940611877625
Okio work is ok done=4752, memory=130.21985602879425
Okio work is ok done=4779, memory=135.28374325134973
Okio 有 8% 左右的速度优势，及 20% 左右的内存优势。
总结
- 压缩日志是提升日志库性能的手段之一，常用的 Gzip 是压缩手段之一，Okio 和 java.io 都提供了对 Gzip 的支持，不过 Okio 在速度和内存上都稍好于 java.io。
talk is cheap, show me the code
推荐阅读
面试系列文章如下：
转载自:https://juejin.cn/post/7083634028640731143