diff options
| -rw-r--r-- | pkg/log/BUILD | 1 | ||||
| -rw-r--r-- | pkg/log/glog.go | 164 | ||||
| -rw-r--r-- | pkg/log/glog_unsafe.go | 32 | ||||
| -rw-r--r-- | pkg/log/json_k8s.go | 2 | ||||
| -rw-r--r-- | pkg/log/log.go | 20 | ||||
| -rw-r--r-- | pkg/log/log_test.go | 35 | ||||
| -rw-r--r-- | runsc/boot/compat.go | 2 | ||||
| -rw-r--r-- | runsc/main.go | 4 |
8 files changed, 99 insertions, 161 deletions
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) + } +} diff --git a/runsc/boot/compat.go b/runsc/boot/compat.go index 9c23b9553..8995d678e 100644 --- a/runsc/boot/compat.go +++ b/runsc/boot/compat.go @@ -65,7 +65,7 @@ func newCompatEmitter(logFD int) (*compatEmitter, error) { if logFD > 0 { f := os.NewFile(uintptr(logFD), "user log file") - target := log.MultiEmitter{c.sink, log.K8sJSONEmitter{log.Writer{Next: f}}} + target := &log.MultiEmitter{c.sink, &log.K8sJSONEmitter{log.Writer{Next: f}}} c.sink = &log.BasicLogger{Level: log.Info, Emitter: target} } return c, nil diff --git a/runsc/main.go b/runsc/main.go index abf929511..c2b0d9a9e 100644 --- a/runsc/main.go +++ b/runsc/main.go @@ -288,7 +288,7 @@ func main() { } if *alsoLogToStderr { - e = log.MultiEmitter{e, newEmitter(*debugLogFormat, os.Stderr)} + e = &log.MultiEmitter{e, newEmitter(*debugLogFormat, os.Stderr)} } log.SetTarget(e) @@ -333,7 +333,7 @@ func main() { func newEmitter(format string, logFile io.Writer) log.Emitter { switch format { case "text": - return &log.GoogleEmitter{&log.Writer{Next: logFile}} + return &log.GoogleEmitter{log.Writer{Next: logFile}} case "json": return &log.JSONEmitter{log.Writer{Next: logFile}} case "json-k8s": |