TiDB 记录日志原理解读

【是否原创】是
【首发渠道】知乎
【首发渠道链接】https://zhuanlan.zhihu.com/p/432558861
【正文】

一、引言

日志一直是溯源系统运行错误的重要存在。TiDB 也不例外在系统中进行日志的记录。我们经常遇到的有两种。一种是 tidb.log 格式，记录系统运行时各类日志。另外一个就是慢查询日志，一般以 tidb-slow.log 命名。日志等级一般分为 5 种。从低到高依次是：“DEBUG”、“INFO”、“WARNNING”、“ERROR”、“CRITICAL”。慢查询阈值默认 300ms。超过阈值就会记录下来。日志等级设置地越低，慢查询阈值越小，单位时间内记录的日志就会越多。它对性能的影响程度也就越大。此外，TiDB 也支持通过开启 general log 来记录每一次请求所发送的 sql 语句信息。如此繁多的日志种类，TiDB 究竟是怎样去处理的。我带着问题去到源码做了一个简单的解读，在此分享给大家。

二、Zap 替换 go 原生日志包

TiDB 在启动时会做一些初始化工作。比如读取配置、设置全局变量、设置CPU亲和性、设置日志组件。相关的代码在tidb-server/mian.go文件中可以看到：

func main() {
  //省略部分代码
	setGlobalVars()
	setCPUAffinity()
	setupLog()
	setHeapProfileTracker()
	setupTracing() // Should before createServer and after setup config.
	printInfo()
	setupBinlogClient()
	setupMetrics()

其中 setupLog 方法所做最重要的事就是使用 zap 替换全局 logger。在继续跟踪源码之前，首先解释一下为什么要做替换日志组件的操作。go 原生日志包秉承 go 简洁设计的思想，实现简单，但是功能较为简陋。在性能上并没有突出表现。相比于原生日志包，zap 最突出的表现就是高性能。下表就是 zap 与其他日志包性能对比的情况。TiDB 作为底层分布式基础设施，要尽可能将性能用在数据服务上。对于日志记录，则需要使用性能损耗小，功能支持多的日志组件。

继续说回日志组件的替换。进到 setupLog 方法。首先拿到全局配置对象。然后使用 logutil 初始化日志组件并传入日志相关配置。

func setupLog() {
	cfg := config.GetGlobalConfig()
	err := logutil.InitLogger(cfg.Log.ToLogConfig())
}

进到 InitLogger 方法，它会根据配置构造一个 zap logger 对象。然后调用 ReplaceGlobals 方法全局替换 logger 为 zap logger。紧接着下面也会构造慢查询logger 用以记录慢查询语句。此外，这里也构造 grpc 的 logger 对象。

func InitLogger(cfg *LogConfig) error {
	gl, props, err := log.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.FatalLevel))
	if err != nil {
		return errors.Trace(err)
	}
	log.ReplaceGlobals(gl, props)

	// init dedicated logger for slow query log
	SlowQueryLogger, _, err = newSlowQueryLogger(cfg)
	if err != nil {
		return errors.Trace(err)
	}
  	_, _, err = initGRPCLogger(cfg)
	if err != nil {
		return errors.Trace(err)
	}

	return nil
}

至此，日志组件替换以及logger对象初始化完成。

三、根据日志等级记录

TIDB 使用 logger 对象在程序中任何需要记录日志的地方输出日志。通过 Info、Warn、Error 等方法记录不同等级的日志。

// Info logs a message at InfoLevel. The message includes any fields passed
// at the log site, as well as any fields accumulated on the logger.
func (log *Logger) Info(msg string, fields ...Field) {
	if ce := log.check(InfoLevel, msg); ce != nil {
		ce.Write(fields...)
	}
}

通过 tidb 配置中的 log level 项，可以控制不同等级日志打印与否。日志打印策略就是每次写日志都会读取配置中 log level 进行 check 操作，如果当前记录日志的等级高于 log level 配置值。那么这条日志将被记录。

以 Info 方法举例，方法中传入的 InfoLevel 枚举值就是 0，而当前设置的日志等级是 ERROR 。进入到判断方法 log.check，详细解读一下它是怎样判断是否要记录这条日志的。相关代码如下。传入的 lv1 是 Info 等级，其属性值为 0 。zapcore.DPanicLevel 枚举值为 3。

lvl < zapcore.DPanicLevel 的结果为 true。再看后半段，需要进入 Enabled 方法。在该方法内部将首先调用 Level 方法获取能够记录的最小日志等级。再返回当前日志等级大于或等于该等级的布尔结果（ return lvl >= l ）。在这里，结果将返回 false。因为 0 >= 2 的结果为 false。那么 !log.core.Enabled(lvl) 的结果即为true。所以这个 if 可以进入，该函数就直接返回 nil 了。这将导致 Info 方法中 ce != nil 判断为 false。也就不会调用 ce.Write(fields…) 方法写日志了。

func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry {
	// Check the level first to reduce the cost of disabled log calls.
	// Since Panic and higher may exit, we skip the optimization for those levels.
	if lvl < zapcore.DPanicLevel && !log.core.Enabled(lvl) {
		return nil
	}
  
// Enabled implements the zapcore.LevelEnabler interface, which allows the
// AtomicLevel to be used in place of traditional static levels.
func (lvl AtomicLevel) Enabled(l zapcore.Level) bool {
	return lvl.Level().Enabled(l)
}
  
// Level returns the minimum enabled log level.
func (lvl AtomicLevel) Level() zapcore.Level {
	return zapcore.Level(int8(lvl.l.Load()))
}
  
// Enabled returns true if the given level is at or above this level.
func (l Level) Enabled(lvl Level) bool {
	return lvl >= l
}

四、记录 general log

可以通过设置系统变量来开启记录 general log 的功能。

set @@tidb_general_log = true;

官网对 general log 的描述可以参考这里：https://docs.pingcap.com/zh/tidb/stable/system-variables#tidb_general_log

记录 genral log 的逻辑被封装到一个方法中。具体是 session/session.go 中的 logGeneralQuery。

func logGeneralQuery(execStmt *executor.ExecStmt, s *session, isPrepared bool) {
	vars := s.GetSessionVars()
	if variable.ProcessGeneralLog.Load() && !vars.InRestrictedSQL {
		var query string
    //省略部分代码
    logutil.BgLogger().Info("GENERAL_LOG",
			zap.Uint64("conn", vars.ConnectionID),
			zap.Stringer("user", vars.User),
      // xxxxx
			zap.String("txn_mode", vars.GetReadableTxnMode()),
			zap.String("sql", query))
	}
}

该方法中最值得注意的是 if 判断的逻辑。主要分为两段。第一个就是读取系统变量 tidb_general_log。后面一段则是判断当前执行的语句是否为受限SQL。即使不向 TiDB 发送请求，TiDB 内部也在时刻执行一些内部语句，以维持系统正常运行。这些内部执行的 SQL 有 Restricted 标记，保证在开启 general log 时不会打印出来，干扰用户判断。

通过一些 IDE 的 find usages 功能。发现总共有三个地方引用该方法。可以分为两类。第一个是 logStmt 方法中调用了该方法。另外就是 cachedPlanExec 和 preparedStmtExec 方法调用。向 TiDB 发送的 sql 主要分为两类。一种是普通查询，另一种是预查询。这两种查询在 TiDB 内部做请求分发时会走不同的 case。具体可以看到 server/conn 包中的 dispatch 方法。查询语句报文的首位将标志它的语句类型。普通查询的 cmd 将匹配 mysql.ComQuery，走普通查询流程。预查询的 cmd 将首先匹配 ComStmtPrepare。在执行阶段则会匹配 handleStmtExecute。二者执行流程不同，想要同时能够记录这两种sql，就需要在不同的流程中调用 logGeneralQuery 方法了。

func (cc *clientConn) dispatch(ctx context.Context, data []byte) error {
  //省略部分代码
	cc.lastPacket = data
	cmd := data[0]
	data = data[1:]
	dataStr := string(hack.String(data))
	switch cmd {
	case mysql.ComQuery: // Most frequently used command.
		if len(data) > 0 && data[len(data)-1] == 0 {
			data = data[:len(data)-1]
			dataStr = string(hack.String(data))
		}
		return cc.handleQuery(ctx, dataStr)
	case mysql.ComStmtPrepare:
		return cc.handleStmtPrepare(ctx, dataStr)
	case mysql.ComStmtExecute:
		return cc.handleStmtExecute(ctx, data)
	}
}

五、记录慢查询

记录慢查询的逻辑主要封装在 executor/adapter.go 中的 LogSlowQuery 方法。首先会从 ctx，log，config 等对象中拿记录满日志所需的信息。然后读取慢查询阈值设置和慢查询记录开关。然后经过一个判断是否要记录该日志。判断的前一部分是慢查询记录开关关闭或者是事务消耗时间小于阈值。另外一部分条件是配置的日志等级大于 Debug 并且 trace 功能关闭。两个条件同时满足，则不会打印慢查询日志。接着往下走，就是拼装满查询日志对象。然后判断事务耗时是否小于阈值。小于则以 debug 模式打印。以为前面的代码注释也提到如果处于 debug 模式，无论如何都要打印出来。如果不小于。那么就以 Warn 级别打印。

func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) {
	sessVars := a.Ctx.GetSessionVars()
	level := log.GetLevel()
	cfg := config.GetGlobalConfig()
	costTime := time.Since(sessVars.StartTime) + sessVars.DurationParse
	threshold := time.Duration(atomic.LoadUint64(&cfg.Log.SlowThreshold)) * time.Millisecond
	enable := cfg.Log.EnableSlowLog
	// if the level is Debug, or trace is enabled, print slow logs anyway
	force := level <= zapcore.DebugLevel || trace.IsEnabled()
	if (!enable || costTime < threshold) && !force {
		return
	}
	sql := FormatSQL(a.GetTextToLog())
	_, digest := sessVars.StmtCtx.SQLDigest()
// 省略部分代码
	slowItems := &variable.SlowQueryLogItems{
		TxnTS:             txnTS,
		SQL:               sql.String(),
		Digest:            digest.String(),
		//省略部分代码
		WriteSQLRespTotal: stmtDetail.WriteSQLRespDuration,
		ExecRetryCount:    a.retryCount,
	}
	if costTime < threshold {
		logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(slowItems))
	} else {
		logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(slowItems))
	}
}

通过 IDE 的 find usages 找到引用该方法的地方。主要是在 FinishExecuteStmt中。从方法名也可以看出，这个方法在语句执行流程的最后阶段。在方法被会做记录满查询、语句 summary、执行延时指标等操作。

// FinishExecuteStmt is used to record some information after `ExecStmt` execution finished:
// 1. record slow log if needed.
// 2. record summary statement.
// 3. record execute duration metric.
// 4. update the `PrevStmt` in session variable.
// 5. reset `DurationParse` in session variable.
func (a *ExecStmt) FinishExecuteStmt(txnTS uint64, err error, hasMoreResults bool) {
	sessVars := a.Ctx.GetSessionVars()
	execDetail := sessVars.StmtCtx.GetExecDetails()
	//省略部分代码
	succ := err == nil
	// `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`.
	a.LogSlowQuery(txnTS, succ, hasMoreResults)
	a.SummaryStmt(succ)

六、总结

上面通过一些简单的代码追踪，大致了解了一下 TiDB 记录日志的机制。对慢查询，general log 的记录过程以及相关的配置项也有了更加深入的印象。