可观测性的开销:日志同步写与异步写,指标热路径上每次记录多少纳秒

  操作                                         | ns/op(中位数) | allocs/op
  -------------------------------------------+------------+----------
  atomic.Int64.Add(1)                        | 4.0        | 0        
  sync.Mutex 加一                              | 7.7        | 0        
  time.Now()                                 | 32.5       | 0        
  Prometheus Counter.Inc()                   | 3.9        | 0        
  CounterVec.WithLabelValues(…).Inc()(每次查标签) | 35.1       | 0        
  CounterVec 缓存 child 后 .Inc()               | 3.9        | 0        
  Gauge.Set()                                | 1.9        | 0        
  Histogram.Observe()(默认 11 个桶)              | 18.9       | 0        
  HistogramVec.WithLabelValues(…).Observe()  | 33.8       | 0        
  Counter.Inc() 10 个 goroutine 并发(每次操作的均摊耗时) | 60.0       | 0        
  atomic.Int64.Add(1) 10 个 goroutine 并发      | 66.1       | 0        
  slog.Info 级别被关掉                            | 5.9        | 0        
  slog.Info(文本)写到 io.Discard                 | 595.9      | 0        
  slog.Info(JSON)写到 io.Discard               | 636.3      | 2        
  一次不带标签的 Counter.Inc 和一次 atomic 加一差不多(都是几纳秒);带标签的 WithLabelValues 每次要把标签值做哈希查表,约十倍;Histogram 要按桶二分查找再做几次原子操作;日志一行是几百纳秒,而且和字段个数、编码方式有关;关掉的日志级别几乎免费。并发写同一个计数器时,缓存行争用让每次操作慢了十几倍(atomic 本身也一样)

  操作                              | ns/op(中位数) | µs/op
  --------------------------------+------------+------
  Counter.inc()(无标签)              | 199        | 0.20 
  Counter.labels(…).inc()(每次查标签)  | 707        | 0.71 
  缓存 child 后 .inc()               | 212        | 0.21 
  Gauge.set()                     | 207        | 0.21 
  Histogram.observe()(无标签)        | 539        | 0.54 
  Histogram.labels(…).observe()   | 967        | 0.97 
  span(no-op,没配 SDK)              | 2016       | 2.02 
  span(SDK + SimpleSpanProcessor) | 8701       | 8.70 
  span(SDK + BatchSpanProcessor)  | 9092       | 9.09 
  span(SDK + Batch,5 个属性)         | 12269      | 12.27
  logging.info,级别被关掉              | 94         | 0.09 
  logging.info → NullHandler      | 2630       | 2.63 
  logging.info → 文件(格式化 + 写入)     | 8835       | 8.84 
  同样是 Counter.inc():Python 199 ns,Go 3.9 ns,Python 是 Go 的 51 倍(算出来的比值);Python 里指标操作是零点几到一微秒,一个 span 是 9.1 到 12.3 µs,一行日志写文件是 8.8 µs(NullHandler 是 2.6 µs,说明大部分在格式化和写文件);给 span 加属性、指标带标签的查询都会增加耗时

  目的地每次写入耗时 | 方式      | logger.info 耗时 p50(ms) | p99(ms) | 最大(ms) | 2000 次调用用的总时间(s) | 目的地实际写入的行数 | 被丢弃的行数
  ----------+---------+------------------------+---------+--------+------------------+------------+-------
  3 ms      | (a)同步   | 4.525                  | 4.768   | 5.3    | 10.0             | 2000       | 0     
  3 ms      | (b)异步队列 | 0.117                  | 0.371   | 1.1    | 10.0             | 2000       | 0     
  8 ms      | (a)同步   | 11.326                 | 12.216  | 14.2   | 21.8             | 2000       | 0     
  8 ms      | (b)异步队列 | 0.125                  | 0.352   | 1.5    | 10.0             | 1934       | 66    
  同步写时,目的地的耗时全部加在请求路径上:3 ms 的目的地让每次调用多 3 ms;8 ms 的目的地让 200 个/秒的请求跟不上(调用被拖慢,总时间变长)。异步队列把调用的耗时降到微秒级,代价是目的地跟不上时队列满了就只能丢日志(或者阻塞调用方)

  配置                  | 每秒处理的请求数(3 轮中位数) | 每个请求的平均耗时(ms) | 比 (a) 多出的耗时(µs/请求)
  --------------------+------------------+---------------+-------------------
  (a)什么都不记录           | 999              | 1.001         | 0                 
  (b)+ 2 次指标          | 998              | 1.002         | 1                 
  (c)+ 3 行 JSON 日志写文件 | 965              | 1.036         | 36                
  (d)+ 1 个 span       | 950              | 1.052         | 52                
  每一档比上一档多出的耗时:指标 1 µs,再加 3 行日志 35 µs,再加 1 个 span 16 µs;全部加上比什么都不记录多 52 µs,占 1 ms 请求的 5.2%(算出来的)。请求本身越短,这个占比越大
ERRORS {}