龙空技术网

最新面试必问:怎么写一个又好又快的日志库?(一)

JAVA后端架构 89

前言:

而今兄弟们对“java异常信息怎么生成日志”可能比较看重,姐妹们都想要学习一些“java异常信息怎么生成日志”的相关内容。那么小编也在网摘上汇集了一些对于“java异常信息怎么生成日志””的相关资讯,希望大家能喜欢,朋友们一起来了解一下吧!

在面试中,这类题目称为场景题,即就一个实际业务场景给出解决方案,难度较高,若无与之相关的实战经验,非常考验临场应变及综合运用储备知识的能力。这篇就来分析下“写一个 Log 需要考虑些哪些方面?”

先抛一个砖

简单是任何一个库设计都要考虑的首要问题。

接口设计

如果库接口设计不合理,造成理解、接入、使用的高复杂度。那。。。这个库就没人用呗~

先来看这样一个设计:

abstract class ULogBase : IULog {    private val logger by lazy {        ULogCore(initConfig())    }    override fun v(tag: String, message: String) {        logger.printLog(Log.VERBOSE, tag, message)    }    override fun v(tag: String, message: String, throwable: Throwable) {        logger.printLog(Log.VERBOSE, tag, message)    }    override fun i(tag: String, message: String) {        logger.printLog(Log.INFO, tag, message)    }    override fun i(tag: String, message: String, throwable: Throwable) {        logger.printLog(Log.INFO, tag, message, throwable)    }    override fun d(tag: String, message: String) {        logger.printLog(Log.DEBUG, tag, message)    }    override fun d(tag: String, message: String, throwable: Throwable) {        logger.printLog(Log.DEBUG, tag, message, throwable)    }    override fun w(tag: String, message: String) {        logger.printLog(Log.WARN, tag, message)    }    override fun w(tag: String, message: String, throwable: Throwable) {        logger.printLog(Log.WARN, tag, message, throwable)    }    override fun e(tag: String, message: String) {        logger.printLog(Log.ERROR, tag, message)    }    override fun e(tag: String, message: String, throwable: Throwable) {        logger.printLog(Log.ERROR, tag, message,throwable)    }    override fun a(tag: String, message: String, tagReport: String) {        logger.printLog(Log.ASSERT, tag, message, tagReport = tagReport)    }    override fun a(tag: String, message: String, throwable: Throwable, tagReport: String) {        logger.printLog(Log.ASSERT, tag, message, throwable, tagReport = tagReport)    }    abstract fun initConfig() : ULogConfig}

这是 Log 库对外公布的接口。它尊重了 Android 端打 Log 的习俗。毕竟 android.util.Log 已经习以为常。使用新库时,平滑过渡,不会有陌生感。

但这个接口设计有优化的地方。

override fun v(tag: String, message: String) {    logger.printLog(Log.VERBOSE, tag, message)}override fun v(tag: String, message: String, throwable: Throwable) {    logger.printLog(Log.VERBOSE, tag, message, throwable)}

同级别的 Log 输出,声明了2个方法。在 Java 中不得不这样做,因参数不同而进行方法重载。

运用 Kotlin 的语法特性参数默认值和可空类型,就能降低接口复杂度:

// 声明参数 throwable 是可空类型,并默认赋予空值override fun v(tag: String, message: String, throwable: Throwable? = null) {    logger.printLog(Log.VERBOSE, tag, message, throwable)}

把2个接口变为1个接口,而调用效果保持不变:

ULog.v("test","log")ULog.v("test","log",Exception("error"))

当调用第一条语句时,Kotlin 默认给 throwable 参数传递 null 值。

接入难度

这个接口设计,第二个尴尬点是 ULogBase 是抽象的,业务层不得不实例化才能使用。。。

这无疑增加了使用负担。而这样做的目的仅仅是为了“配置”,即根据不同的业务场景传入不同的参数:

object NimLogger : ULogBase() {    override fun initConfig(): ULogConfig {        return ULogConfig.Builder(requireNotNull(NimConfig.context()))// 和 context 耦合            .module("nim")            .debug(NimConfig.isDebug()) // 和编译类型耦合            .build()    }}

业务端必须重写 initConfig() 方法生成一个 ULogConfig 对象,用来表示业务配置。

看看业务配置包括哪些:

class ULogConfig private constructor(builder: Builder) {    val module = builder.mModule // 模块名    val isDebug = builder.mIsDebug // 编译类型    val context = builder.context // 上下文    val logModulePath = builder.mLogModulePath // 路径名    val logRootPath = builder.mLogRootPath // 根路径名    val enableToFile = builder.enableToFile // 是否写文件    val isValidPath : Boolean        get() {            return !TextUtils.isEmpty(logModulePath) && !TextUtils.isEmpty(logRootPath)        }    class Builder(val context: Context) {        lateinit var mModule: String            private set        var mIsDebug: Boolean = true            private set        var enableToFile: Boolean = true            private set        var mLogModulePath: String = ""            private set        var mLogRootPath: String = ""            private set        fun module(name: String): Builder {            mModule = name            return this        }        fun debug(debug: Boolean): Builder {            mIsDebug = debug            return this        }        fun enableToFile(enable : Boolean): Builder {            enableToFile = enable            return this        }        fun build(): ULogConfig {            if (mModule == null) {                throw IllegalArgumentException("Be sure to set the module name")            }            if (TextUtils.isEmpty(mLogModulePath)) {                mLogModulePath = getLogPath(mModule)            }            if (TextUtils.isEmpty(mLogRootPath)) {                mLogRootPath = getLogPath()            }            return ULogConfig(this)        }        private fun getLogPath(module : String = "") : String {            return if(mIsDebug) {                File(context.filesDir,  "uLog/debug/$module").absolutePath            } else {                File(context.filesDir,  "uLog/release/$module").absolutePath            }        }    }}

业务配置信息包括,模块名、编译类型、上下文、路径名、是否写文件。

其中前 4 个参数是为了给不同模块的日志生成不同的日志路径。这个设计,见仁见智~

优点是信息降噪,只关注想关注模块的日志。缺点是,大部分业务模块都和多个底层功能模块耦合,大部分问题是综合性问题,需要关注整个链路上所有模块的日志。

我偏好的策略是,将所有日志打入一个文件,通过 tag 来区分模块,如果只想关注某个模块的日志,sublime 可以方便地选中包含指定 tag 的所有行,一个复制粘贴就完成了信息降噪。毕竟想分开是轻而易举的事情,但是想合并就很难了~

复杂度(建造者模式)

Kotlin 相较于 Java 的最大优势就是降低复杂度。在库接口设计及内部实现时就要充分发挥 Kotlin 的优势,比如 Kotlin 的世界里已不需要 Builder 模式了。

Builder 模式有如下优势:

为参数标注语义:在Builder模式中,每个属性的赋值都是一个函数,函数名标注了属性语义。可选参数&分批赋值:Builder模式中,除了必选参数,其他参数是可选的,可分批赋值。而直接使用构造函数必须一下子为所有参数赋值。增加参数约束条件:可以在参数不符合要求时,抛出异常。

但 Builder 模式也有代价,新增了一个中间类Builder。

使用 Kotlin 的命名参数+参数默认值+require()语法,在没有任何副作用的情况下就能实现 Builder 模式:

class Person(    val name: String,    //'为以下可选参数设置默认值'    val gender: Int = 1,    val age: Int= 0,    val height: Int = 0,    val weight: Int = 0)//'使用命名参数构建 Person 实例'val p  = Person(name = “taylor”,gender = 1,weight = 43)

命名参数为每个实参赋予了语义,而且不需要按构造方法中声明的顺序来赋值,可以跳着来。

如果想增加参数约束条件可以调用require()方法:

data class Person(    // 这个是必选参数    val name: String,    val gender: Int = 1,    val age: Int= 0,    val height: Int = 0,    val weight: Int = 0){    //'在构造函数被调用的时候执行参数合法检查'    init {        require(name.isNotEmpty()){”name cant be empty“}    }}

此时如果像下面这样构造 Person,则会抛出异常:

val p = Person(name="",gender = 1)java.lang.IllegalArgumentException: name cant be empty

本来在 build() 方法中执行的额外初始化逻辑也可以全部写在init代码块中。

最后这个库,在具体打印日志时的操作也及其复杂(不知道你能不能一下子看明白这 log 是怎么打的?):

internal class ULogCore(private val config: ULogConfig) {    companion object {        const val DELETE_DAY_NUMBER = 7        const val TAG_LOG = "ULogCore"        const val SUFFIX = ".java"        const val TAG_PARAM = "param"        const val KEY_ASSET_MSG = "key_asset_message"        const val STACK_TRACK_INDEX = 7        val tag_log_type = arrayOf("VERBOSE", "DEBUG", "INFO", "WARN", "ERROR", "ASSERT")        var initOperation  = AtomicBoolean(false)        var logDateFormat = SimpleDateFormat("yyyy-MM-dd", Locale.CHINA)    }    fun printLog(        type: Int,        tagText: String,        message: String,        throwable: Throwable? = null,        tagReport: String? = ""    ) {        val stackTrace = Thread.currentThread().stackTrace        CoroutineScope(Dispatchers.Default).launch {            val finalMessage = processMessage(type, message, stackTrace)            val tagFinal = if (TextUtils.isEmpty(tagText)) TAG_LOG else tagText            if (config.isDebug) {                when (type) {                    Log.VERBOSE -> Log.v(tagFinal, finalMessage, throwable)                    Log.DEBUG -> Log.d(tagFinal, finalMessage, throwable)                    Log.INFO -> Log.i(tagFinal, finalMessage, throwable)                    Log.WARN -> Log.w(tagFinal, finalMessage, throwable)                    Log.ERROR -> Log.e(tagFinal, finalMessage, throwable)                    Log.ASSERT -> Log.e(tagFinal, finalMessage, throwable)                    else -> {                    }                }            }            val logDir = File(config.logModulePath)            if (!logDir.exists() || logDir.isFile) {                logDir.mkdirs()            }            if (!initOperation.getAndSet(true)) {                val filterDates = ArrayList<String>().apply {                    for(i in 0..DELETE_DAY_NUMBER) {                        val calendar = Calendar.getInstance()                        calendar.add(Calendar.DAY_OF_MONTH, -i)                        val date = logDateFormat.format(calendar.time)                        Log.i(TAG_LOG, date)                        add(date)                    }                }                config.logRootPath.takeIf { !TextUtils.isEmpty(it) }?.run {                    val list = ArrayList<File>()                    File(this).listFiles()?.forEach { file ->                        Log.i(TAG_LOG, "module $this")                        file.listFiles()?.filter { child ->                            !child.isMatchDateFile(filterDates)                        }?.apply {                            list.addAll(this)                        }                    }                    list                }?.run {                    forEach {                        Log.i(TAG_LOG,"delete file ${it.name}")                        it.delete()                    }                }                if (!ULogFwHThread.isAlive) {                    ULogFwHThread.start()                }            }            if (config.enableToFile) {                if (config.isValidPath) {                    var formatReportTag = ""                    if (type == Log.ASSERT && tagReport != null && tagReport.isNotEmpty()) {                        var assetMsgSet = MMKV.defaultMMKV().getStringSet(KEY_ASSET_MSG, HashSet())                        val rawMsg = message+tagReport                        Log.i(TAG_LOG, "asset md5 raw message $rawMsg")                        val key = ULogUtils.getMD5(rawMsg, false)                        Log.i(TAG_LOG, "assetMsgSet is $assetMsgSet , asset message key is $key")                        formatReportTag = "[#$tagReport#]"                        if (assetMsgSet?.contains(key) == true) {                            Log.i(TAG_LOG, "This log is asset mode and has save to file once, so ignore it.")                        } else {                            assetMsgSet?.add(key)                            MMKV.defaultMMKV().putStringSet(KEY_ASSET_MSG, assetMsgSet)                            EventBus.getDefault().post(                                ULogTagEvent(                                    tagReport,                                    logDateFormat.format(Date(System.currentTimeMillis()))                                )                            )                        }                    }                    ULogFwHThread.addEntry(                        ULogEntry(                            config,                            type,                            "[$tagFinal] $formatReportTag: $message",                            throwable                        )                    )                } else {                    Log.i(TAG_LOG, "printLog invalid log file path logRootPath : " +                            "${config.logRootPath} logModulePath : ${config.logModulePath}")                }            } else {                Log.i(TAG_LOG,"enableToFile is closed")            }        }    }    private fun processMessage(        type: Int,        msg: String,        stackTraceElement: Array<StackTraceElement>    ): String {        fun typeTag(logType: Int): String? {            return if (logType >= Log.VERBOSE && logType <= Log.ASSERT) tag_log_type[logType - 2] else "LOG"        }        val targetElement = stackTraceElement[STACK_TRACK_INDEX]        var fileName = targetElement.fileName        if (TextUtils.isEmpty(fileName)) {            var className = targetElement.className            val classNameInfo = className.split("\.".toRegex()).toTypedArray()            if (classNameInfo.isNotEmpty()) {                className = classNameInfo[classNameInfo.size - 1]            }            if (className.contains("$")) {                className = className.split("\$".toRegex()).toTypedArray()[0]            }            fileName = className + SUFFIX        }        val methodName = targetElement.methodName        var lineNumber = targetElement.lineNumber        if (lineNumber < 0) {            lineNumber = 0        }        val headString = String.format("[ (%s:%s) => %s ]", fileName, lineNumber, methodName)        val threadInfo = String.format("thread - {{ %s }}", Thread.currentThread().name)        val sb = StringBuilder(headString).apply {            append("\n╔═════════════════════════════════════════════════════════════════════════════════════════")            append("\n║ ").append(threadInfo)            append("\n╟┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈")            append("\n║ [").append(typeTag(type)).append("] - ").append(msg)            append("\n╚═════════════════════════════════════════════════════════════════════════════════════════")        }        return sb.toString()    }}

printLog() 是每次打日志都会调用的方法,在这个方法里面做了很多很多事情~,包括美化日志、向 Logcat 输出日志、创建日志文件夹、删除过期日志、写日志到文件、将日志上传云。

先不说违反了单一职责原则造成的高复杂度,高理解成本,同时也不能满足下面这些需求:

自定义我的日志美化样式。(毕竟我们不一样,有不同的审美)在不改库的前提下,更换写文件方式(比如更高性能的I/O库)。在不改库的前提下,更换上传云逻辑。(从阿里云换成亚马逊云)在不改库的前提下,增加本地日志加密。在不改库的前提下,修改日志文件的根目录。

这些动态的配置效果,应该是一个库具备的弹性。如果动不动就要改库,它还配叫库?

如果一定要给 “一个库的基本修养” 提两条纲领的话,我愿意把 “简单” 和 “弹性” 放在首位。

高可扩展

看完刚才的砖之后,我再抛一个砖。

object EasyLog {    private const val VERBOSE = 2    private const val DEBUG = 3    private const val INFO = 4    private const val WARN = 5    private const val ERROR = 6    private const val ASSERT = 7    // 拦截器列表    private val logInterceptors = mutableListOf<LogInterceptor>()    fun d(message: String, tag: String = "", vararg args: Any) {        log(DEBUG, message, tag, *args)    }    fun e(message: String, tag: String = "", vararg args: Any, throwable: Throwable? = null) {        log(ERROR, message, tag, *args, throwable = throwable)    }    fun w(message: String, tag: String = "", vararg args: Any) {        log(WARN, message, tag, *args)    }    fun i(message: String, tag: String = "", vararg args: Any) {        log(INFO, message, tag, *args)    }    fun v(message: String, tag: String = "", vararg args: Any) {        log(VERBOSE, message, tag, *args)    }    fun wtf(message: String, tag: String = "", vararg args: Any) {        log(ASSERT, message, tag, *args)    }    // 注入拦截器    fun addInterceptor(interceptor: LogInterceptor) {        logInterceptors.add(interceptor)    }    // 从头部注入拦截器    fun addFirstInterceptor(interceptor: LogInterceptor) {        logInterceptors.add(0, interceptor)    }}

日志库对上层的接口封装在一个单例 EasyLog 里。

日志库提供了和 android.util.Log 几乎一样的打印接口,但增加了一个可变参数args,这是为了方便地为字串的通配符赋值。

假责任链模式

日志库还提供了一个新接口addInterceptor(),用于动态地注入日志拦截器:

interface LogInterceptor {    // 进行日志    fun log(priority: Int, tag: String, log: String)    // 是否允许进行日志    fun enable():Boolean}

日志拦截器是一个接口,定义了两个抽象的行,为分别是进行日志和是否允许日志。

所有的日志接口都将打印日志委托给了log()方法:

object EasyLog {    @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)        }        // 遍历日志拦截器,将日志打印分发给所有拦截器        logInterceptors.forEach { interceptor ->            if (interceptor.enable()) interceptor.log(priority, tag, logMessage)        }    }    // 对 String.format() 的封装,以求简洁    fun String.format(vararg args: Any) =        if (args.isNullOrEmpty()) this else String.format(this, *args)    // 读取堆栈    private fun getStackTraceString(tr: Throwable?): String {        if (tr == null) {            return ""        }        var t = tr        while (t != null) {            if (t is UnknownHostException) {                return ""            }            t = t.cause        }        val sw = StringWriter()        val pw = PrintWriter(sw)        tr.printStackTrace(pw)        pw.flush()        return sw.toString()    }}

这里用了同步方法,为了防止多线程调用时日志乱序。

这里还运用了责任链模式(假的),使得 EasyLog 和日志处理的具体逻辑解耦,它只是持有一组日志拦截器,当有日志请求时,就分发给所有的拦截器。

这样做的好处就是,可以在业务层动态地为日志组件提供新的功能。

当然日志库得提供一些基本的拦截器,比如将日志输出到 Logcat:

open class LogcatInterceptor : LogInterceptor {    override fun log(priority: Int, tag: String, log: String){        Log.println(priority, tag, log)    }    override fun enable(): Boolean {       return true    }}

Log.println(priority, tag, log)是 android.util.Log 提供的,按优先级将日志输出到 Logcat 的方法。使用这个方法可以降低复杂度,因为不用写类似下面的代码:

when(priority){    VERBOSE -> Log.v(...)    ERROR -> Log.e(...)}

之所以要将 LogcatInterceptor 声明为 open,是因为业务层有动态重写enable()方法的需求:

EasyLog.addInterceptor(object : LogcatInterceptor() {    override fun enable(): Boolean {        return BuildConfig.DEBUG     }})

这样就把日志输出到 Logcat 的开关 和 build type 联系起来了,就不需要将 build type 作为 EasyLog 的一个配置字段了。

除了输出到 Logcat,另一个基本需求就是日志文件化,新建一个拦截器:

class FileWriterLogInterceptor     private constructor(private var dir: String) : LogInterceptor {    private val handlerThread = HandlerThread("log_to_file_thread")    private val handler: Handler    private val dispatcher: CoroutineDispatcher    // 带参单例    companion object {        @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)        // 将 handler 转换成 Dispatcher        dispatcher = handler.asCoroutineDispatcher("log_to_file_dispatcher")    }    override fun log(priority: Int, tag: String, log: String) {        // 启动协程串行地将日志写入文件        if (!handlerThread.isAlive) handlerThread.start()        GlobalScope.launch(dispatcher) {            FileWriter(getFileName(), true).use {                it.append("[$tag] $log")                it.append("\n")                it.flush()            }        }    }    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"}

日志写文件的思路是:“异步串行地将字串通过流输出到文件中”。

异步化是为了不阻塞主线程,串行化是为了保证日志顺序。HandlerThread 就很好地满足了异步化串行的要求。

为了简化“将日志作为消息发送到异步线程中”这段代码,使用了协程,这样代码就转变成:每次日志请求到来时,启动协程,在其中完成创建流、输出到流、关闭流。隐藏了收发消息的复杂度。

日志拦截器被设计为单例,目的是让 App 内存中只存在一个写日志的线程。

日志文件的路径由构造方法传入,这样就避免了日志拦截器和 Context 的耦合。

use()是Closeable的扩展方法,它隐藏了流操作的try-catch,降低了复杂度,关于这方面的详细介绍可以点击

Kotlin 源码 | 降低代码复杂度的法宝 - 掘金 (juejin.cn)

然后业务层就可以像这样动态地为日志组件添加写文件功能:

class MyApplication : Application() {    override fun onCreate() {        super.onCreate()        // 日志文件路径        val dir = this.filesDir.absolutePath        // 构造日志拦截器单例        val interceptor = FileWriterLogInterceptor.getInstance(dir)        // 注入日志拦截器单例        EasyLog.addInterceptor(interceptor)    }}
真责任链模式

还有一个对日志库的基本诉求就是“美化日志”。

还是重新定义一个拦截器:

// 调用堆栈拦截器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)    }}

链持有一组拦截器和索引,其中索引表示当前需要执行的是哪个拦截器。

链包含一个procee()方法,它是让日志请求在链上传递起来的关键。每次执行该方法都会新建一个链条并将索引+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 三次测试的对比耗时如下:

// okiottaylor1: log() work is done=9600ttaylor1: log() work is done=9822ttaylor1: log() work is done=9411// FileWriterttaylor1: log() work is done=10688ttaylor1: log() work is done=10816ttaylor1: log() work is done=11928

看上去 Okio 在耗时上有微弱的优势。

但当我把单条 Log 的长度增加 300 倍之后,测试结果出现了反转:

// FileWriterttaylor1: log() work is done=13569ttaylor1: log() work is done=12654ttaylor1: log() work is done=13152// okiottaylor1: log() work is done=14136ttaylor1: log() work is done=15451ttaylor1: log() work is done=15292

也就是说 Okio 在高频少量 I/O 场景性能好于 FileWriter,而高频大量 I/O 场景下没有性能优势。

这个结果让我很困惑,于是乎我在 Github 上提了 issue:

Okio is slower when writing long strings into file frequently compared with FileWriter · Issue #1098 · square/okio

没想到瞬间就被回复了:

我的提问的本意是想确认下使用 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()就非常契合这个场景。

它的背后机制是:每当流产生新数据时,开启倒计时,如果在倒计时归零之前没有新数据,则将最后那个数据发射出去,否则重新开启倒计时。

知道了背后的机制,就不需要拘泥于具体的实现方式,使用 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!!    }}
后续

目前只是搭了一个高可扩展,高性能的日子组件的框架,后续文章会逐步介绍如何进行下一步的优化,欢迎关注~

总结“简单”和“弹性”是库设计中首要关注的两个方面。Kotlin 有诸多语法特性能极大地降低代码的复杂度。真责任链模式非常适用于为日志库提供弹性。它使得动态为日志库新增功能成为可能,它使得每次的处理结果得以在传递给后续处理者。用HandlerThread实现异步串行日志输出。用Okio实现高性能的日志文件化。在高频日志文件化的场景下,复用输出流能极大地提高性能。同时需要延迟消息机制保证日志的完整性。

最近是面试的高峰期,有一些小伙伴,让我帮忙找一些面试题资料,于是我翻遍了收藏的6T资料后,汇总整理出来,可以说是程序员面试必备!所有资料都整理到网盘了,需要的小伙伴转发+关注后私信我回复【666】即可获取,欢迎下载~~~~

作者:唐子玄

链接:

标签: #java异常信息怎么生成日志