真责任链模式
还有一个对日志库的基本诉求就是“美化日志”。
还是重新定义一个拦截器：
// 调用堆栈拦截器 class CallStackLogInterceptor : LogInterceptor { companion object { private const val HEADER = "┌──────────────────────────────────────────────────────────────────────────────────────────────────────" private const val FOOTER = "└──────────────────────────────────────────────────────────────────────────────────────────────────────" private const val LEFT_BORDER = '│' // 用于过滤日志调用栈（将EasyLog中的类过滤） private val blackList = listOf( CallStackLogInterceptor::class.java.name, EasyLog::class.java.name ) } override fun log(priority: Int, tag: String, log: String) { // 打印头部 Log.println(priority, tag, HEADER) // 打印日志 Log.println(priority, tag, "$LEFT_BORDER$log") // 打印堆栈信息 getCallStack(blackList).forEach { val callStack = StringBuilder() .append(LEFT_BORDER) .append("\t${it}").toString() Log.println(priority, tag, callStack) } // 打印尾部 Log.println(priority, tag, FOOTER) } override fun enable(): Boolean { return true } }
对于业务层的一条日志，调用堆栈拦截器输出了好几条日志，依次是头部、日志、堆栈、尾部。
为了降低复杂度，把获取调用栈的逻辑单独抽象为一个方法：
fun getCallStack(blackList: List<String>): List<String> { return Thread.currentThread() .stackTrace.drop(3) // 获取调用堆栈，过滤上面的3个，因为它们就是这里看到3个方法 .filter { it.className !in blackList } // 过滤黑名单 .map { "${it.className}.${it.methodName}(${it.fileName}:${it.lineNumber})" } }
按照上面map()中那样的格式，在 Logcat 中就能有点击跳转效果。
然后把调用堆栈拦截器插入到所有拦截器的头部：
EasyLog.addFirstInterceptor(CallStackLogInterceptor())
打印效果是这样的：
看上去还不错~，但当我打开日志文件后，却只有DemoActivity.onCreate()这一行日志，并没有堆栈信息。。。
原因就在于我用了一个假的责任链模式！！
责任链模式就好比“老师发考卷”：
- 真责任链是这样发考卷的：老师将考卷递给排头同学，排头同学再传递给第二个同学，如此往复，直到考卷最终递到我的手里。
- 假责任链是这样发考卷的：老师站讲台不动，叫到谁的名字，谁就走上去拿自己的考卷。
学生时代当然希望老师用假责任链模式发考卷，因为若用真责任链，前排的每一个同学都可以看到我的分数，还能在我的考卷上乱涂乱画。
但在打日志这个场景中，用假责任链模式的后果就是，后续拦截器拿不到前序拦截器的处理结果。
其实它根本称不上责任链，因为就不存在“链”，至多是一个“策略模式的遍历”
关于策略模式的详细解析可以点击一句话总结殊途同归的设计模式：工厂模式=？策略模式=？模版方法模式
所以只能用真责任链重构，为了向后传递拦截器的处理结果，拦截器就得持有其后续拦截器：
interface LogInterceptor { // 后续拦截器 var nextInterceptor:LogInterceptor? fun log(priority: Int, tag: String, log: String) fun enable():Boolean }
然后在具体的拦截器实例中实现这个抽象属性：
open class LogcatInterceptor : LogInterceptor { override var nextInterceptor: LogInterceptor? = null get()= field set(value) { field = value } override fun log(priority: Int, tag: String, log: String) { if (enable()) { Log.println(priority, tag, log) } // 将log请求传递给下一个拦截器 nextInterceptor?.log(priority, tag, log) } override fun enable(): Boolean { return true } }
因为所有的拦截器都通过链的方式连接，所以 EasyLog 就不需要再持有一组拦截器，而只需要持有头拦截器就好了：
object EasyLog { // 头拦截器 private val logInterceptor : LogInterceptor? = null // 注入拦截器 fun setInterceptor(interceptor: LogInterceptor) { logInterceptor = interceptor } }
注入拦截器的代码也需要做相应的变化：
class MyApplication : Application() { override fun onCreate() { super.onCreate() // 构建所有拦截器 val dir = this.filesDir.absolutePath val fileInterceptor = FileWriterLogInterceptor.getInstance(dir) val logcatInterceptor = LogcatInterceptor() val callStackLogInterceptor = CallStackLogInterceptor() // 安排拦截器链接顺序 callStackLogInterceptor.nextInterceptor = logcatInterceptor logcatInterceptor.nextInterceptor = fileInterceptor // 将头部拦截器注入 EasyLog.setInterceptor(callStackLogInterceptor) } }
这个设计能满足功能要求，但是对于接入方来说，复杂度有点高，因为不得不手动安排拦截器的顺序，而且如果想改动拦截器的顺序也非常麻烦。
我想到了 OkHttp，它也采用了真拦截器模式，但并不需要手动安排拦截器的顺序。它是怎么做到的？由于篇幅原因，源码分析不展开了，感兴趣的同学可以点开okhttp3.internal.http.RealInterceptorChain。
下面运用这个思想，重构一下 EasyLog。
首先要新建一条链：
class Chain( // 持有一组拦截器 private val interceptors: List<LogInterceptor>, // 当前拦截器索引 private val index: Int = 0 ) { // 将日志请求在链上传递 fun proceed(priority: Int, tag: String, log: String) { // 用一条新的链包裹链上的下一个拦截器 val next = Chain(interceptors, index + 1) // 执行链上当前的拦截器 val interceptor = interceptors.getOrNull(index) // 执行当前拦截器逻辑，并传入新建的链 interceptor?.log(priority, tag, log, next) } }
链持有一组拦截器和索引，其中索引表示当前需要执行的是哪个拦截器。
链包含一个proceed()方法，它是让日志请求在链上传递起来的关键。每次执行该方法都会新建一个链条并将索引+1，下次通过该链条获取的拦截器就是“下一个拦截器”。
紧接着根据当前索引获取当前拦截器，将日志请求传递给它的同时，将“下一个拦截器”以链条的形式也传递给它。
重构之后的调用栈拦截器如下：
class CallStackLogInterceptor : LogInterceptor { companion object { private const val HEADER = "┌──────────────────────────────────────────────────────────────────────────────────────────────────────" private const val FOOTER = "└──────────────────────────────────────────────────────────────────────────────────────────────────────" private const val LEFT_BORDER = '│' private val blackList = listOf( CallStackLogInterceptor::class.java.name, EasyLog::class.java.name, Chain::class.java.name, ) } override fun log(priority: Int, tag: String, log: String, chain: Chain) { // 将日志请求传递给下一个拦截器 chain.proceed(priority, tag, HEADER) // 将日志请求传递给下一个拦截器 chain.proceed(priority, tag, "$LEFT_BORDER$log") getCallStack(blackList).forEach { val callStack = StringBuilder() .append(LEFT_BORDER) .append("\t${it}").toString() // 将日志请求传递给下一个拦截器 chain.proceed(priority, tag, callStack) } // 将日志请求传递给下一个拦截器 chain.proceed(priority, tag, FOOTER) } override fun enable(): Boolean { return true } }
和之前假责任链的区别在于，将已经美化过的日志传递给了后续拦截器，其中就包括文件日志拦截器，这样写入文件的日志也被美化了。
EasyLog 也需要做相应的改动：
object EasyLog { // 持有一组拦截器 private val logInterceptors = mutableListOf<LogInterceptor>() // 将所有日志拦截器传递给链条 private val interceptorChain = Chain(logInterceptors) fun addInterceptor(interceptor: LogInterceptor) { logInterceptors.add(interceptor) } fun addFirstInterceptor(interceptor: LogInterceptor) { logInterceptors.add(0, interceptor) } fun removeInterceptor(interceptor: LogInterceptor) { logInterceptors.remove(interceptor) } @Synchronized private fun log( priority: Int, message: String, tag: String, vararg args: Any, throwable: Throwable? = null ) { var logMessage = message.format(*args) if (throwable != null) { logMessage += getStackTraceString(throwable) } // 日志请求传递给链条 interceptorChain.proceed(priority, tag, logMessage) } }
这样一来上层注入拦截的代码不需要更改，还是按序 add 就好，将拦截器形成链条的复杂度被隐藏在 EasyLog 的内部。
高性能 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 限流的应用场景及原理分析可以点击
Kotlin 异步 | Flow 限流的应用场景及原理 - 掘金 (juejin.cn)
知道了背后的机制，就不需要拘泥于具体的实现方式，使用 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!! } }
Talk is cheap, show me the code
EasyLog 已上传 GitHub，链接在这里
后续
目前只是搭了一个高可扩展，高性能的日子组件的框架，后续文章会逐步介绍如何进行下一步的优化，欢迎关注~
总结
- “简单”和“弹性”是库设计中首要关注的两个方面。
- Kotlin 有诸多语法特性能极大地降低代码的复杂度。
- 真责任链模式非常适用于为日志库提供弹性。它使得动态为日志库新增功能成为可能，它使得每次的处理结果得以在传递给后续处理者。
- 用
HandlerThread实现异步串行日志输出。
- 用
Okio实现高性能的日志文件化。
- 在高频日志文件化的场景下，复用输出流能极大地提高性能。同时需要延迟消息机制保证日志的完整性。
推荐阅读
面试系列文章如下：
面试题 | 徒手写一个 ConcurrentLinkedQueue？
RecyclerView 面试题 | 哪些情况下表项会被回收到缓存池？
