From 253c9e666cf7d52352da97d764818e510f1387c0 Mon Sep 17 00:00:00 2001 From: Adin Scannell Date: Mon, 27 Jan 2020 15:37:28 -0800 Subject: Cleanup glog and add real caller information. In general, we've learned that logging must be avoided at all costs in the hot path. It's unlikely that the optimizations here were significant in any case, since buffer would certainly escape. This also adds a test to ensure that the caller identification works as expected, and so that logging can be benchmarked. Original: BenchmarkGoogleLogging-6 1222255 949 ns/op With this change: BenchmarkGoogleLogging-6 517323 2346 ns/op Fixes #184 PiperOrigin-RevId: 291815420 --- pkg/log/BUILD | 1 - pkg/log/glog.go | 164 +++++++++++++------------------------------------ pkg/log/glog_unsafe.go | 32 ---------- pkg/log/json_k8s.go | 2 +- pkg/log/log.go | 20 ++++-- pkg/log/log_test.go | 35 +++++++++++ 6 files changed, 96 insertions(+), 158 deletions(-) delete mode 100644 pkg/log/glog_unsafe.go (limited to 'pkg/log') diff --git a/pkg/log/BUILD b/pkg/log/BUILD index 935d06963..a7c8f7bef 100644 --- a/pkg/log/BUILD +++ b/pkg/log/BUILD @@ -6,7 +6,6 @@ go_library( name = "log", srcs = [ "glog.go", - "glog_unsafe.go", "json.go", "json_k8s.go", "log.go", diff --git a/pkg/log/glog.go b/pkg/log/glog.go index 5732785b4..cab5fae55 100644 --- a/pkg/log/glog.go +++ b/pkg/log/glog.go @@ -15,149 +15,73 @@ package log import ( + "fmt" "os" + "runtime" + "strings" "time" ) // GoogleEmitter is a wrapper that emits logs in a format compatible with // package github.com/golang/glog. type GoogleEmitter struct { - // Emitter is the underlying emitter. - Emitter -} - -// buffer is a simple inline buffer to avoid churn. The data slice is generally -// kept to the local byte array, and we avoid having to allocate it on the heap. -type buffer struct { - local [256]byte - data []byte -} - -func (b *buffer) start() { - b.data = b.local[:0] -} - -func (b *buffer) String() string { - return unsafeString(b.data) -} - -func (b *buffer) write(c byte) { - b.data = append(b.data, c) -} - -func (b *buffer) writeAll(d []byte) { - b.data = append(b.data, d...) -} - -func (b *buffer) writeOneDigit(d byte) { - b.write('0' + d) -} - -func (b *buffer) writeTwoDigits(v int) { - v = v % 100 - b.writeOneDigit(byte(v / 10)) - b.writeOneDigit(byte(v % 10)) -} - -func (b *buffer) writeSixDigits(v int) { - v = v % 1000000 - b.writeOneDigit(byte(v / 100000)) - b.writeOneDigit(byte((v % 100000) / 10000)) - b.writeOneDigit(byte((v % 10000) / 1000)) - b.writeOneDigit(byte((v % 1000) / 100)) - b.writeOneDigit(byte((v % 100) / 10)) - b.writeOneDigit(byte(v % 10)) -} - -func calculateBytes(v int, pad int) []byte { - var d []byte - r := 1 - - for n := 10; v >= r; n = n * 10 { - d = append(d, '0'+byte((v%n)/r)) - r = n - } - - for i := len(d); i < pad; i++ { - d = append(d, ' ') - } - - for i := 0; i < len(d)/2; i++ { - d[i], d[len(d)-(i+1)] = d[len(d)-(i+1)], d[i] - } - return d + Writer } // pid is used for the threadid component of the header. -// -// The glog package logger uses 7 spaces of padding. See -// glob.loggingT.formatHeader. -var pid = calculateBytes(os.Getpid(), 7) - -// caller is faked out as the caller. See FIXME below. -var caller = []byte("x:0") +var pid = os.Getpid() // Emit emits the message, google-style. -func (g GoogleEmitter) Emit(level Level, timestamp time.Time, format string, args ...interface{}) { - var b buffer - b.start() - - // Log lines have this form: - // Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg... - // - // where the fields are defined as follows: - // L A single character, representing the log level (eg 'I' for INFO) - // mm The month (zero padded; ie May is '05') - // dd The day (zero padded) - // hh:mm:ss.uuuuuu Time in hours, minutes and fractional seconds - // threadid The space-padded thread ID as returned by GetTID() - // file The file name - // line The line number - // msg The user-supplied message - +// +// Log lines have this form: +// Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg... +// +// where the fields are defined as follows: +// L A single character, representing the log level (eg 'I' for INFO) +// mm The month (zero padded; ie May is '05') +// dd The day (zero padded) +// hh:mm:ss.uuuuuu Time in hours, minutes and fractional seconds +// threadid The space-padded thread ID as returned by GetTID() +// file The file name +// line The line number +// msg The user-supplied message +// +func (g *GoogleEmitter) Emit(level Level, timestamp time.Time, format string, args ...interface{}) { // Log level. + prefix := byte('?') switch level { case Debug: - b.write('D') + prefix = byte('D') case Info: - b.write('I') + prefix = byte('I') case Warning: - b.write('W') + prefix = byte('W') } // Timestamp. _, month, day := timestamp.Date() hour, minute, second := timestamp.Clock() - b.writeTwoDigits(int(month)) - b.writeTwoDigits(int(day)) - b.write(' ') - b.writeTwoDigits(int(hour)) - b.write(':') - b.writeTwoDigits(int(minute)) - b.write(':') - b.writeTwoDigits(int(second)) - b.write('.') - b.writeSixDigits(int(timestamp.Nanosecond() / 1000)) - b.write(' ') - - // The pid. - b.writeAll(pid) - b.write(' ') - - // FIXME(b/73383460): The caller, fabricated. This really sucks, but it - // is unacceptable to put runtime.Callers() in the hot path. - b.writeAll(caller) - b.write(']') - b.write(' ') - - // User-provided format string, copied. - for i := 0; i < len(format); i++ { - b.write(format[i]) + microsecond := int(timestamp.Nanosecond() / 1000) + + // 0 = this frame. + // 1 = Debugf, etc. + // 2 = Caller. + _, file, line, ok := runtime.Caller(2) + if ok { + // Trim any directory path from the file. + slash := strings.LastIndexByte(file, byte('/')) + if slash >= 0 { + file = file[slash+1:] + } + } else { + // We don't have a filename. + file = "???" + line = 0 } - // End with a newline. - b.write('\n') + // Generate the message. + message := fmt.Sprintf(format, args...) - // Pass to the underlying routine. - g.Emitter.Emit(level, timestamp, b.String(), args...) + // Emit the formatted result. + fmt.Fprintf(&g.Writer, "%c%02d%02d %02d:%02d:%02d.%06d % 7d %s:%d] %s\n", prefix, int(month), day, hour, minute, second, microsecond, pid, file, line, message) } diff --git a/pkg/log/glog_unsafe.go b/pkg/log/glog_unsafe.go deleted file mode 100644 index ea17ae349..000000000 --- a/pkg/log/glog_unsafe.go +++ /dev/null @@ -1,32 +0,0 @@ -// Copyright 2018 The gVisor Authors. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package log - -import ( - "reflect" - "unsafe" -) - -// unsafeString returns a string that points to the given byte array. -// The byte array must be preserved until the string is disposed. -func unsafeString(data []byte) (s string) { - if len(data) == 0 { - return - } - - (*reflect.StringHeader)(unsafe.Pointer(&s)).Data = uintptr(unsafe.Pointer(&data[0])) - (*reflect.StringHeader)(unsafe.Pointer(&s)).Len = len(data) - return -} diff --git a/pkg/log/json_k8s.go b/pkg/log/json_k8s.go index c2c019915..cee6eb514 100644 --- a/pkg/log/json_k8s.go +++ b/pkg/log/json_k8s.go @@ -33,7 +33,7 @@ type K8sJSONEmitter struct { } // Emit implements Emitter.Emit. -func (e K8sJSONEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) { +func (e *K8sJSONEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) { j := k8sJSONLog{ Log: fmt.Sprintf(format, v...), Level: level, diff --git a/pkg/log/log.go b/pkg/log/log.go index 91a81b288..5056f17e6 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -17,6 +17,18 @@ // This is separate from the standard logging package because logging may be a // high-impact activity, and therefore we wanted to provide as much flexibility // as possible in the underlying implementation. +// +// Note that logging should still be considered high-impact, and should not be +// done in the hot path. If necessary, logging statements should be protected +// with guards regarding the logging level. For example, +// +// if log.IsLogging(log.Debug) { +// log.Debugf(...) +// } +// +// This is because the log.Debugf(...) statement alone will generate a +// significant amount of garbage and churn in many cases, even if no log +// message is ultimately emitted. package log import ( @@ -138,8 +150,8 @@ func (l *Writer) Emit(level Level, timestamp time.Time, format string, args ...i type MultiEmitter []Emitter // Emit emits to all emitters. -func (m MultiEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) { - for _, e := range m { +func (m *MultiEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) { + for _, e := range *m { e.Emit(level, timestamp, format, v...) } } @@ -155,7 +167,7 @@ type TestEmitter struct { } // Emit emits to the TestLogger. -func (t TestEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) { +func (t *TestEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) { t.Logf(format, v...) } @@ -332,5 +344,5 @@ func CopyStandardLogTo(l Level) error { func init() { // Store the initial value for the log. - log.Store(&BasicLogger{Level: Info, Emitter: GoogleEmitter{&Writer{Next: os.Stderr}}}) + log.Store(&BasicLogger{Level: Info, Emitter: &GoogleEmitter{Writer{Next: os.Stderr}}}) } diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go index 0634e7c1f..402cc29ae 100644 --- a/pkg/log/log_test.go +++ b/pkg/log/log_test.go @@ -16,18 +16,23 @@ package log import ( "fmt" + "strings" "testing" ) type testWriter struct { lines []string fail bool + limit int } func (w *testWriter) Write(bytes []byte) (int, error) { if w.fail { return 0, fmt.Errorf("simulated failure") } + if w.limit > 0 && len(w.lines) >= w.limit { + return len(bytes), nil + } w.lines = append(w.lines, string(bytes)) return len(bytes), nil } @@ -68,3 +73,33 @@ func TestDropMessages(t *testing.T) { } } } + +func TestCaller(t *testing.T) { + tw := &testWriter{} + e := &GoogleEmitter{Writer: Writer{Next: tw}} + bl := &BasicLogger{ + Emitter: e, + Level: Debug, + } + bl.Debugf("testing...\n") // Just for file + line. + if len(tw.lines) != 1 { + t.Errorf("expected 1 line, got %d", len(tw.lines)) + } + if !strings.Contains(tw.lines[0], "log_test.go") { + t.Errorf("expected log_test.go, got %q", tw.lines[0]) + } +} + +func BenchmarkGoogleLogging(b *testing.B) { + tw := &testWriter{ + limit: 1, // Only record one message. + } + e := &GoogleEmitter{Writer: Writer{Next: tw}} + bl := &BasicLogger{ + Emitter: e, + Level: Debug, + } + for i := 0; i < b.N; i++ { + bl.Debugf("hello %d, %d, %d", 1, 2, 3) + } +} -- cgit v1.2.3