深入Operator日志框架，实现一个高性能的Operator
关注微信公众号《云原生CTO》更多云原生干货等你来探索
专注于 云原生技术 分享
提供优质云原生开发 视频技术培训
面试技巧，及技术疑难问题解答
云原生技术分享不仅仅局限于Go、Rust、Python、Istio、containerd、CoreDNS、Envoy、etcd、Fluentd、Harbor、Helm、Jaeger、Kubernetes、Open Policy Agent、Prometheus、Rook、TiKV、TUF、Vitess、Argo、Buildpacks、CloudEvents、CNI、Contour、Cortex、CRI-O、Falco、Flux、gRPC、KubeEdge、Linkerd、NATS、Notary、OpenTracing、Operator Framework、SPIFFE、SPIRE 和 Thanos等
深入Operator日志框架，实现一个高性能的Operator
让我们用Operator日志记录来展开我们的主题。不同于最常见的打印方法fmt.Printf，它不会在消息中打印具体的参数信息，而是单独在日志中打印，比如JSON字符串。
{"severity":"INFO","eventTime":"2022-07-09T09:04:55.260Z","logger":"controller.opresource","message":"Deleting OpResource, because it is no longer in scope!","reconciler group":"op.spotify.com","reconciler kind":"OpResource","name":"afs-proxy-0618bce","namespace":"","name":"afs-proxy"}
这是Operator日志打印的规范方式吗?让我们通过深入研究Operator日志框架的实现和使用细节来揭示答案。
Log in operator
controller-runtime alias.go提供了一个默认的Log对象，默认情况下由go-logr执行该对象的实现
// Log is the base logger used by controller-runtime. It delegates
// to another logr.Logger. You *must* call SetLogger to
// get any actual logging.
Log = log.Log
Go-logr是一个简单的日志框架，它本身没有日志输出功能，而是对Dave Cheney提出的Go日志分类的进一步优化。
一般情况下，一个Go程序只需要两个级别的日志:INFO和ERROR;而其他层次并不重要。对于调试，它提供v级输出，放弃跟踪或调试等其他级别。
它的实现包括Logr和LogSink接口，任何外部日志框架都可以通过实现LogSink来集成Logr。
在默认的controller-runtime中，DelegatingLogSink被实现为默认的Logr日志输出，其中logger使用简单的NullLogSink。这个默认实现对于大多数场景已经足够了，并且可以与fmt.Sprintf结合使用。
log.V(10).Info(fmt.Sprintf("Create Resources for User:%s, Project:%s", user, project))
然而， DelegatingLogSink有一个明显的缺陷：当它被部署为集群范围的控制器并管理数千个资源时，它的低效率是一个性能瓶颈。以下两个是导致其效率低下的主要原因。
它使用了很多锁 。DelegatingLogSink使用一个 promisesLock互斥锁，并且两者 WithName和 WithValues的方法 loggerPromise需要锁，甚至 Enable, Info和 Error函数依赖于 RLock，读锁。毫无疑问，在具有大量写入操作的日志输出中频繁锁定，即使使用读锁定，也会导致性能下降。
func (l *DelegatingLogSink) Info(level int, msg string,keysAndValues ...interface{}) {
l.lock.RLock()
defer l.lock.RUnlock()
l.logger.Info(level, msg, keysAndValues...)
}
日志内容使用的是fmt.Sprintf。我们使用字符串。Join或Buffer操作来替换fmt.Sprintf和+连接字符串，以提高许多Go字符串操作的效率(阅读golang中的连接字符串快速基准:+或fmt.Sprintf了解更多)。但是在编写日志时，我们确实希望从日志框架中免费获得这一点，而不是重新创建轮子，这是logr和controller-runtime的默认实现无法提供的。
其他选项
如果我们放弃默认实现，还有其他选项吗?如何切换?
Go社区提供了广泛的日志包，甚至本地的也可以满足基本的日志输出需求。
在《A Sip of Go Log》中，我们深入挖掘了日志的基本逻辑，并比较了一些流行的日志开源包，其中Uber的zap以其性能吸引了我们的眼球。让我们回顾一下这些惊人的数字，看看zap是否是最好的选择。
controller-runtime已经有了默认的zapr实现，它已经在内部的很多地方被使用了。但为什么不将它用作默认实现呢?
用户可以通过定制一个Logger来集成zap，以实现某些附加功能，如时间转换、日志输出到外部存储等，controller-runtime将其封装为一个Logger。Logger最终在zap控制器运行时实现。
按照以下四个步骤定义zap Logger。
zap.go实现了console和json两种编码器，并提供了zapr标准Logger所需的功能，如WriteTo和Level。
默认情况下，zapr采用consoleEncoder和debugLevel/warnLevelin开发模式，而使用jsonencoder和infollevel /errorLevelin生产。
至于替换这个Operator中的默认Logr，在初始化main方法中的Reconciler时，我们只需要使用Log: zap.New()，然后我们可以按以下模式在控制器中打印日志。
func log(ctx context.Context) {
log.FromContext(ctx).Info("message", "param1", param1, "param2", param2 ...)
log.FromContext(ctx).Error(err, "message", "param1", param1, "param2", param2 ...)
}
为什么zap这么快
zap采取的5个步骤(每个步骤都反映了优化)主要使用Go的两个特性，这两个特性决定了zap的效率。
使用同步。池，以避免输出日志时的内存开销。
日志。Check是打印的第一步，在Check方法中进行了两项性能优化。
避免不必要的操作，如跳过不必要的日志级别，直接返回不需要打印的日志。例如，如果我们的日志级别是Info，那么一旦出现调试级别日志，它就直接返回。重用Entry对象。zap构造一个真正打印的Entry对象，它将被Checked，以便在同步保存的对象中重用它。池，降低高频日志对象的创建和消除频率，最终减少GC。
func getCheckedEntry() *CheckedEntry {
ce := _cePool.Get().(*CheckedEntry)
ce.reset()
return ce
}
每次写后更新池
func (ce *CheckedEntry) Write(fields ...Field) {
//…
putCheckedEntry(ce)
}
在输出日志时，我们还使用同步。内存优化池。默认的consoleEncoder和jsonEncoder都将打印的信息存储在buffer中，buffer使用sync构建的bufferPool。池中获取一个对象，并通过下面的拼接获得最终的输出日志。
// console_encoder.go
func (c consoleEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, error) {5 years ago • Akshay Shah [Fix allocation when returning []byte to pool …]
line := bufferpool.Get()
// ...
}
// json_encoder.go
func (enc *jsonEncoder) clone() *jsonEncoder {
clone := getJSONEncoder()
clone.EncoderConfig = enc.EncoderConfig
clone.spaced = enc.spaced
clone.openNamespaces = enc.openNamespaces
clone.buf = bufferpool.Get()
return clone
}
func (enc *jsonEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, error) {5 years ago • Akshay Shah [Fix allocation when returning []byte to pool …]
final := enc.clone()
//...
}
// buffer.Pool
type Pool struct {
p *sync.Pool
}
// NewPool constructs a new Pool.
func NewPool() Pool {
return Pool{p: &sync.Pool{
New: func() interface{} {
return &Buffer{bs: make([]byte, 0, _size)}
},
}}
}
func (p Pool) Get() *Buffer {5 years ago • Akshay Shah [Expose Buffer pools to third-party encoders (…]
buf := p.p.Get().(*Buffer)
buf.Reset()
buf.pool = p
return buf
}
避免使用interface{}设计api和优化JSON序列化。通过强类型设计和零内存开销实现JSON序列化。
在zap的日志输出中，JSON格式是最终统一的输出格式，甚至console_encoder也最终调用json_encoder来打印字段。Fields结构设计显著提高了日志打印的速度，并用于定义每个输入参数的类型信息，以快速将类型转换为字符串。并且在Field的AddTo方法中定义了所有可能的类型和字符串之间的转换，避免了zap的类型推断和反射，大大提高了输出效率。
// zap console_encoder.go
func (c consoleEncoder) writeContext(line *buffer.Buffer, extra []Field) {
context := c.jsonEncoder.Clone().(*jsonEncoder)
defer func() {
// putJSONEncoder assumes the buffer is still used, but we write out the buffer so
// we can free it.
context.buf.Free()
putJSONEncoder(context)
}()
addFields(context, extra)
// ...
}
func addFields(enc ObjectEncoder, fields []Field) {
for i := range fields {
fields[i].AddTo(enc)
}
}
// Field.go
type Field struct {
Key string
Type FieldType
Integer int64
String string
Interface interface{}
}
// AddTo exports a field through the ObjectEncoder interface. It's primarily
// useful to library authors, and shouldn't be necessary in most applications.
func (f Field) AddTo(enc ObjectEncoder) {
var err error
switch f.Type {
case ArrayMarshalerType:
err = enc.AddArray(f.Key, f.Interface.(ArrayMarshaler))
case ObjectMarshalerType:
err = enc.AddObject(f.Key, f.Interface.(ObjectMarshaler))
case InlineMarshalerType:
err = f.Interface.(ObjectMarshaler).MarshalLogObject(enc)
case BinaryType:
enc.AddBinary(f.Key, f.Interface.([]byte))
case BoolType:
enc.AddBool(f.Key, f.Integer == 1)
case ByteStringType:
enc.AddByteString(f.Key, f.Interface.([]byte))
// more type convert func
}
当然，不要忘记释放在bufferPool中获得的对象!
性能测试
让一个基准测试来验证zap的出色性能。
import (
"fmt"
"testing"
"github.com/go-logr/logr"
"github.com/go-logr/logr/funcr"
"sigs.k8s.io/controller-runtime/pkg/log"
"sigs.k8s.io/controller-runtime/pkg/log/zap"
)
//go:noinline
func doInfoOneArg(b *testing.B, log logr.Logger) {
for i := 0; i < b.N; i++ {
log.Info("this is", "a", "string")
}
}
//go:noinline
func doInfoSeveralArgs(b *testing.B, log logr.Logger) {
for i := 0; i < b.N; i++ {
log.Info("multi",
"bool", true, "string", "str", "int", 42,
"float", 3.14, "struct", struct{ X, Y int }{93, 76})
}
}
// Default Logr
func BenchmarkDiscardLogInfoOneArg(b *testing.B) {
var log logr.Logger = logr.Discard()
doInfoOneArg(b, log)
}
// DKL: Default Kubernetes controllerruntime Logr
func BenchmarkDiscardLogInfoOneArgDKL(b *testing.B) {
var log logr.Logger = log.Log
doInfoOneArg(b, log)
}
// KLZ: Kubernetes controllerruntime ZapLogr
func BenchmarkDiscardLogInfoOneArgKLZ(b *testing.B) {
var log logr.Logger = zap.New()
doInfoOneArg(b, log)
}
func BenchmarkDiscardLogInfoSeveralArgs(b *testing.B) {
var log logr.Logger = logr.Discard()
doInfoSeveralArgs(b, log)
}
func BenchmarkDiscardLogInfoSeveralArgsDKL(b *testing.B) {
var log logr.Logger = log.Log
doInfoSeveralArgs(b, log)
}
func BenchmarkDiscardLogInfoSeveralArgsKLZ(b *testing.B) {
var log logr.Logger = zap.New()
doInfoSeveralArgs(b, log)
}
// output:
BenchmarkDiscardLogInfoOneArg-16 34606057 34.10 ns/op 32 B/op 1 allocs/op
BenchmarkDiscardLogInfoOneArgDKL-16 23754621 47.12 ns/op 32 B/op 1 allocs/op
BenchmarkDiscardLogInfoOneArgKLZ-16 4568048 284.3 ns/op 32 B/op 1 allocs/op
BenchmarkDiscardLogInfoSeveralArgs-16 14577048 102.1 ns/op 176 B/op 2 allocs/op
BenchmarkDiscardLogInfoSeveralArgsDKL-16 12127125 90.31 ns/op 176 B/op 2 allocs/op
BenchmarkDiscardLogInfoSeveralArgsKLZ-16 3421066 386.2 ns/op 180 B/op 2 allocs/op
通过比较这三个日志包在无参数和多参数场景中的性能，我可以“自豪地”宣布zap是最好的:zap Logr比controller-runtime中的默认Logr快大约7倍。
很容易得出这样的结论:如果我们想实现一个高性能的Operator，就必须替换默认的Log实现。但是需要注意的是，如果您仍然使用v1，则可能需要将kubebuilder升级到最新的v3版本，这涉及到从klog迁移到logr，请参考结构化和上下文日志迁移说明以获得指导。
结构化和上下文日志迁移: https://github.com/kubernetes/community/blob/HEAD/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#structured-and-contextual-logging-migration-instructions
感谢你的阅读!