fastapi日志重复打印_Golang优秀源码走读---zap日志（三）

对于zap日志组件的分析，剩下的内容中比较大块的有编码器部分。zap的json序列化实现也是一个非常精彩的部分，性能相比标准库的强了不少，实现也很复杂，对于一只工作了一周的咸鱼写这部分的话会很费劲。。。。。

所以这篇打算对于其他边边角角的功能做个分析，一些小功能的实现思路也很棒。

---

日志流控器

第一次分析zap的配置时，就提到了一个功能，日志流控功能，也就是配置中的Sampling配置。

type SamplingConfig struct {
	Initial    int `json:"initial" yaml:"initial"`
	Thereafter int `json:"thereafter" yaml:"thereafter"`
}

Sampling：Sampling实现了日志的流控功能，或者叫采样配置，主要有两个配置参数，Initial和Thereafter，实现的效果是在1s的时间单位内，如果某个日志级别下同样内容的日志输出数量超过了Initial的数量，那么超过之后，每隔Thereafter的数量，才会再输出一次。是一个对日志输出的保护功能。

这次就具体看一下这个配置是如何生效的，在buildOptions方法中，会根据配置结构体，生成Option，其中如果cfg对象的Sampling不为空，返回了一个WrapCore的Option，在Option生效时，WrapCore方法会对logger对象中的Core做一次包装，并替换成WrapCore传入的方法所生成的Core对象。

func (cfg Config) buildOptions(errSink zapcore.WriteSyncer) []Option {
 
   …………………………   

   if cfg.Sampling != nil {
      opts = append(opts, WrapCore(func(core zapcore.Core) zapcore.Core {
         return zapcore.NewSampler(core, time.Second, int(cfg.Sampling.Initial), int(cfg.Sampling.Thereafter))
      }))
   }
   
   …………………………

   return opts
}

// WrapCore wraps or replaces the Logger's underlying zapcore.Core.
func WrapCore(f func(zapcore.Core) zapcore.Core) Option {
	return optionFunc(func(log *Logger) {
		log.core = f(log.core)
	})
}

// WithOptions clones the current Logger, applies the supplied Options, and
// returns the resulting Logger. It's safe to use concurrently.
func (log *Logger) WithOptions(opts ...Option) *Logger {
	c := log.clone()
	for _, opt := range opts {
		opt.apply(c)
	}
	return c
}

这里的实现和思想可以参考对zap分析的第一篇文章中的介绍，总之实现的功能就是可以对logger对象的Core做一次包装，而包装方法是可以由用户自己实现，具体在限流的实现上，实际是调用了zapcore.NewSampler方法，NewSampler方法接收四个参数，一个Core对象，即原本已经按照配置构造出来的Core对象，其余三个参数就是对限流的配置，tick是日志限流的生效周期（即从打印一条日志开始计时，在tick时间后，无论触发限流与否，内部的计数器会被置为零，重新开始计数）；first是限流阈值，即同一条日志达到first条时触发限流；触发限流后并不是完全不打印日志，而是每thereafter条日志才会输出一次。

func NewSampler(core Core, tick time.Duration, first, thereafter int) Core {
   return &sampler{
      Core:       core,
      tick:       tick,
      counts:     newCounters(),
      first:      uint64(first),
      thereafter: uint64(thereafter),
   }
}

从这个效果来看，是比较合理的，每条日志有自己独立的计数器，不是对所有日志一杆子打死，而限流后也不是完全不打印日志，只是间隔一定的条数再打印，对于业务来说，既能在故障期间尽可能的保留问题日志支撑问题定位，又不会打印太多无用的重复日志。

先看看该文件中定义的类型和实现限流功能的两个结构：

通过NewSampler方法构造出来的就是sampler对象，可以看到sampler结构包含了Core接口，并且在调用NewSampler方法时，将外部传入的Core对象直接赋值给了Core接口这种方式是Go中实现类似继承的一个语法糖，sampler结构包含了一个Core接口类型的成员，那么sampler结构就实现了Core接口，其具体的Core中的方法实现由赋值为Core的对象来完成，除此之外，sampler结构自身还可以实现Core中的方法，在这里实现了With和Check方法。最终的效果就是当把sampler结构做为Core的一个实现时，With和Check方法会使用此处sampler所单独实现的方法，Core中的其他方法，由托管的对象实现。这种方式有点类似Java中的继承和重写（Override）父类方法的功能。

sampler的其余成员中，tick，first，thereafter都是一些参数的记录，还有一个比较重要的成员就是counts，也就是计数器，在构造sampler时由newCounters方法创建。先看看关于counters类型的定义：

const (
   _numLevels        = _maxLevel - _minLevel + 1
   _countersPerLevel = 4096
)

type counter struct {
   resetAt atomic.Int64
   counter atomic.Uint64
}

type counters [_numLevels][_countersPerLevel]counter

func newCounters() *counters {
   return &counters{}
}

counters类型实际是counter的一个二维数组的类型别名。这个二维数组可以理解成一个表格，其中存的是许多计数器，一个维度是级别的个数，也就是需要不同级别的日志独立计数，另一个维度是理论上每个级别支持的不同日志数量，也就是不同的日志独立计数。这个二维数组中总共有7x4096个计数器，理想情况下，可以对7x4096条不同日志做独立的计数。

而日志限流的检查功能实际是在sampler自身的Check方法中实现的，我们从Check方法出发看看计数器的作用和实现：

func (s *sampler) Check(ent Entry, ce *CheckedEntry) *CheckedEntry {
   if !s.Enabled(ent.Level) {
      return ce
   }

   counter := s.counts.get(ent.Level, ent.Message)
   n := counter.IncCheckReset(ent.Time, s.tick)
   if n > s.first && (n-s.first)%s.thereafter != 0 {
      return ce
   }
   return s.Core.Check(ent, ce)
}

之前在分析Core接口时我们已经分析过Check方法的作用，对于sampler方法的Check方法，作用是一样的，即获取一个检查后的CheckedEntry日志条目。

首先与ioCore方法一样，先判断了日志级别，如果日志的级别不需要打印，直接即可返回，不必经过限流计数器的判断。如果级别符合要求，先会根据级别和日志信息从counters中获取到该日志对应的计数器（怎么获取的下面说）。然后调用IncCheckReset方法，IncCheckReset方法接受两个参数，一个是日志打印的时间，一个是日志限流的生效周期。这个方法的作用是，在生效周期内，能够并发安全的累加，并返回当前是在生效周期内第n次调用该方法；而如果超过了生效周期，能够并发安全的重新开始计算生效时间，并把计数归为1返回。结合下图和后面的实现可以更好的理解这个作用。

如图，对于tick为30s的情况，假设在0:10这个时间点第一次调用了IncCheckReset这个方法，返回值即为1，并把30s后的时间点0:40记录为了到期时间，之后的30s内，调用第n次，就返回n。而30s过后，也就是0:40这个时间点之后，直到0:53这个时刻才又一次发生了调用，那么由于0:53已经超过了之前的0:40，所以1:23（0:53+30s）这个时刻会被重置为了新的到期时间，并返回n=1。在0:53和1:23之间的第n次调用，都会得到对应的n。

调用完IncCheckReset方法获得对应的n之后，对n做了一次检查，对于超过阈值（first），并且n-first不能整除thereafter的情况，都认为检查不通过，直接返回ce。只有阈值内或超出阈值的次数能整除后续间隔的情况，才会调用Core的Check方法，做原本应有的检查。

假设阈值（first）为5，thereafter为10的情况，对于一个周期内n的序列：

1，2，3，4，5，6，7，8，9，10，11，12，13，14，15，16，17，18，19，20，21，22，23，24，25，26，…………

只有第1，2，3，4，5，15，25次满足条件，才会通过检查。

到这里我们说清楚了Check方法实现的原理，下来深入到counts.get和counter.IncCheckReset方法中，解密下其中的实现原理。

先看看counters提供的get方法：

func (cs *counters) get(lvl Level, key string) *counter {
   i := lvl - _minLevel
   j := fnv32a(key) % _countersPerLevel
   return &cs[i][j]
}

func fnv32a(s string) uint32 {
	const (
		offset32 = 2166136261
		prime32  = 16777619
	)
	hash := uint32(offset32)
	for i := 0; i < len(s); i++ {
		hash ^= uint32(s[i])
		hash *= prime32
	}
	return hash
}

get方法，即根据level和key拿到该二维数组坐标为i，j的一个counter，在实际使用时，level就是日志级别，key是日志的message。其中i的计算方式就是根据参数和最低级别做一个减法，得到的就是i；j的计算稍微复杂一点，先对于这条日志内容，使用32位的FNV算法做了hash，再对求得的hash值模4096，得到的值就是j。以此完成了使用级别和日志内容对数组中的计数器的定位。

这里稍微展开说一下，FNV哈希算法是一种高离散性的哈希算法，对于非常相似的字符串能很好的做出区分，但由于定位时又对hash值取余，一定程度上会导致不同的日志内容定位到的j的值发生碰撞，也就是可能出现不同的日志共用了同一个计数器的现象，这也是这里使用上的一个缺点。

type counter struct {
   resetAt atomic.Int64
   counter atomic.Uint64
}

func (c *counter) IncCheckReset(t time.Time, tick time.Duration) uint64 {
   tn := t.UnixNano()
   resetAfter := c.resetAt.Load()
   if resetAfter > tn {
      return c.counter.Inc()
   }

   c.counter.Store(1)

   newResetAfter := tn + tick.Nanoseconds()
   if !c.resetAt.CAS(resetAfter, newResetAfter) {
      // We raced with another goroutine trying to reset, and it also reset
      // the counter to 1, so we need to reincrement the counter.
      return c.counter.Inc()
   }

   return 1
}

counter结构是真正实现计数器的结构，包含两个成员，类型分别是atomic.Int64和 atomic.Uint64，这两个类型是uber自身封装的原子类型，底层实现还是go的sync/atomic中的原子操作，这两个类型在这里不做展开。resetAt也就是上文所说的待重置的时间，counter是真实的用来存数量的计数器。

在IncCheckReset方法中，从上文可以看到，t是日志条目中的时间，tick是生效周期。先把传入的t转化为纳秒单位，比较了t和resetAt的大小，如果t还没超过resetAt，直接返回counter自增的值即可。这里的Load和Inc也是对sync/atomic中方法的封装，分别是原子读取和原子自增。

而如果t时间已经达到了待重置的时间，就要接着做重置的动作了，首先直接用原子存储方法将counter变量置为了1。计数器重置为1后，下来就是要重新计算待重置时间了，自然是t的纳秒时间戳tn加上tick的纳秒数，就是新的待重置时间（就是上面图中0:53发生调用后，被重置为1:23的过程）。但这里并不会无条件重置掉，而是通过CAS操作来比较并交换。

先补充下CAS的知识：

CAS就是比较并交换，过程是这样，给定三个参数V、E和N，V表示要更新变量的值，E表示预期值，N表示新值。仅当 V值等于E值时，才会将V的值设为N，如果V值和E值不同，则说明已经有其他线程做了更新，则当前线程则什么都不做。最后，CAS 返回更新是否成功，并且该操作具有原子性。

在这里的使用上resetAt变量本身就是V，resetAfter也就是在上文中从resetAt中读取的值就是E，N是新计算出来的要更新到的值。使用这种方式，可以保证在上面方法的Load之后没有其他线程更新过resetAt。而对于更新成功和失败，采用了两种处理策略。更新失败，说明其他协程已经更新过这个值，那conter的值极有可能不再是上面刚重置的1，那么返回的值就应该是counter自增之后的结果；而如果更新成功，说明当前协程是第一个尝试更新的，一定应该返回1.

这里使用这些原子操作，主要是为了保证在临界状态下，也就是并发有多个协程都检查到了resetAt需要更新时，只有一个协程能更新成功，并且其他协程不会重复更新。

需要说明的是，虽然使用了这么多原子操作来保证并发安全，但这个方法并不是真正的并发安全，在极端情况下，resetAt虽然不会被重复更新，但由于多个协程之间的c.counter.Inc()和c.counter.Store(1)的时序无法保证，可能出现counter反复被重置为1的情况。但从整体的角度考虑，这里只是一个计数器，只要能够保证在大多数时候可靠就可以了，对于极端场景下重复重置为1的情况，影响无非是多打印了几条日志，不会非常多，并且后续的限流机制也能生效，这就已经够了。相比对这里的绝对并发安全的追求，我们更需要的是不耗费太多的性能。

本来还想把日志分割也做一下分析，没想到限流这块的代码要讲清楚已经写了这么多了，看来下周可以再水一篇了~~~~~

（上面对于竞态的分析是基于代码以及测试结果的反推，水平有限，如果分析有误，欢迎指正）