Spend less time preparing to write log lines when the logger is disabled (#352)

* Skip some logging work when log message would be ignored

In callers like HashiCorp Terraform, the plugin logger is completely
disabled (hclog.Off) by default, but previously go-plugin would nonetheless
waste time trying to parse log lines to decide what log level to use when
calling into the logger, creating memory allocation garbage and spending
time in the JSON parser only to immediately discard the results.

The hclog.Logger API exposes information about the log level so that
callers can skip doing expensive preparation work unless it will actually
be used. We'll now use that to totally skip all of the log preparation
when the logger is completely disabled, and to skip _some_ of the work
if the log line's level is not sufficient to match the logger's level.

* Log entries use flat KVPairs, instead of slice of pointers

Previously the JSON log line parsing code would allocate separately for
each additional key/value pair in a log line. Using a flat slice of
logEntryKV instead of indirection through pointers amortizes that memory
allocation cost a little better, for a marginal decrease in allocations
per log line.

The resulting logEntryKV objects are always passed and used all together
anyway, so there is no clear advantage to splitting each into a separate
memory allocation.

Author: apparentlymart

client.go

@@ -1167,7 +1167,10 @@ func (c *Client) getGRPCMuxer(addr net.Addr) (*grpcmux.GRPCClientMuxer, error) {
 func (c *Client) logStderr(name string, r io.Reader) {
 	defer c.clientWaitGroup.Done()
 	defer c.pipesWaitGroup.Done()
+
 	l := c.logger.Named(filepath.Base(name))
+	loggerLevel := l.GetLevel()
+	loggerDisabled := loggerLevel == hclog.Off
 
 	reader := bufio.NewReaderSize(r, c.config.PluginLogBufferSize)
 	// continuation indicates the previous line was a prefix
@@ -1203,6 +1206,18 @@ func (c *Client) logStderr(name string, r io.Reader) {
 
 		_, _ = c.config.Stderr.Write([]byte{'\n'})
 
+		//
+		// Any side-effects other than writing to the hclog logger must be
+		// above this point!
+		//
+
+		if loggerDisabled {
+			// If the logger we'd be writing to is completely disabled then
+			// we can skip all of the parsing work to decide what log level
+			// we'd use to write this line.
+			continue
+		}
+
 		entry, err := parseJSON(line)
 		// If output is not JSON format, print directly to Debug
 		if err != nil {
@@ -1236,10 +1251,17 @@ func (c *Client) logStderr(name string, r io.Reader) {
 			}
 		} else {
 			panic = false
-			out := flattenKVPairs(entry.KVPairs)
 
+			logLevel := hclog.LevelFromString(entry.Level)
+			if logLevel != hclog.NoLevel && logLevel < loggerLevel {
+				// The logger will ignore this log entry anyway, so we
+				// won't spend any more time preparing it.
+				continue
+			}
+
+			out := flattenKVPairs(entry.KVPairs)
 			out = append(out, "timestamp", entry.Timestamp.Format(hclog.TimeFormat))
-			switch hclog.LevelFromString(entry.Level) {
+			switch logLevel {
 			case hclog.Trace:
 				l.Trace(entry.Message, out...)
 			case hclog.Debug:

client_logger_test.go

@@ -0,0 +1,59 @@
+package plugin
+
+import (
+	"io"
+	"sync"
+	"testing"
+
+	"github.com/hashicorp/go-hclog"
+)
+
+func BenchmarkClientLogging(b *testing.B) {
+	// We're not actually going to start the process in this benchmark,
+	// so this is just a placeholder to satisfy the ClientConfig.
+	process := helperProcess("bad-version")
+
+	tests := map[string]hclog.Level{
+		"off":   hclog.Off,
+		"error": hclog.Error,
+		"trace": hclog.Trace,
+	}
+
+	for name, logLevel := range tests {
+		b.Run(name, func(b *testing.B) {
+			logger := hclog.New(&hclog.LoggerOptions{
+				Name:   "test-logger",
+				Level:  logLevel,
+				Output: io.Discard,
+				Mutex:  new(sync.Mutex),
+			})
+
+			c := NewClient(&ClientConfig{
+				Cmd:             process,
+				Stderr:          io.Discard,
+				HandshakeConfig: testHandshake,
+				Logger:          logger,
+				Plugins:         testPluginMap,
+			})
+
+			r, w := io.Pipe()
+
+			c.clientWaitGroup.Add(1)
+			c.pipesWaitGroup.Add(1)
+			// logStderr calls Done() on both waitgroups
+			go c.logStderr("test", r)
+
+			fakeLogLine := []byte("{\"@level\":\"debug\",\"@timestamp\":\"2006-01-02T15:04:05.000000Z\",\"@message\":\"hello\",\"extra\":\"hi\",\"numbers\":[1,2,3]}\n")
+			for b.Loop() {
+				n, err := w.Write(fakeLogLine)
+				if err != nil || n != len(fakeLogLine) {
+					b.Fatal("failed to write to pipe")
+				}
+			}
+			err := w.Close() // causes the c.logStderr goroutine to exit
+			if err != nil {
+				b.Fatalf("failed to close write end of pipe: %s", err)
+			}
+		})
+	}
+}

log_entry.go

@@ -10,10 +10,10 @@ import (
 
 // logEntry is the JSON payload that gets sent to Stderr from the plugin to the host
 type logEntry struct {
-	Message   string        `json:"@message"`
-	Level     string        `json:"@level"`
-	Timestamp time.Time     `json:"timestamp"`
-	KVPairs   []*logEntryKV `json:"kv_pairs"`
+	Message   string       `json:"@message"`
+	Level     string       `json:"@level"`
+	Timestamp time.Time    `json:"timestamp"`
+	KVPairs   []logEntryKV `json:"kv_pairs"`
 }
 
 // logEntryKV is a key value pair within the Output payload
@@ -24,7 +24,7 @@ type logEntryKV struct {
 
 // flattenKVPairs is used to flatten KVPair slice into []interface{}
 // for hclog consumption.
-func flattenKVPairs(kvs []*logEntryKV) []interface{} {
+func flattenKVPairs(kvs []logEntryKV) []interface{} {
 	var result []interface{}
 	for _, kv := range kvs {
 		result = append(result, kv.Key)
@@ -66,7 +66,7 @@ func parseJSON(input []byte) (*logEntry, error) {
 
 	// Parse dynamic KV args from the hclog payload.
 	for k, v := range raw {
-		entry.KVPairs = append(entry.KVPairs, &logEntryKV{
+		entry.KVPairs = append(entry.KVPairs, logEntryKV{
 			Key:   k,
 			Value: v,
 		})