trace: Format messages only once, and only log them if needed

Today, trace.Printf and trace.Debugf format the message more than once:
at least once for logging, and once for tracing.

Some of that formatting can be expensive for large messages, causing CPU
and RAM spikes due to transient allocations. So this patch makes those
trace functions only format once, and avoid the logging calls if they're
below the logging level.

internal/trace/trace.go

@@ -39,18 +39,23 @@ func (t *Trace) NewChild(family, title string) *Trace {
 
 // Printf adds this message to the trace's log.
 func (t *Trace) Printf(format string, a ...any) {
-	t.t.Printf(format, a...)
+	t.printf(log.Info, format, a...)
-
-	log.Log(log.Info, 1, "%s %s: %s", t.family, t.title,
-		quote(fmt.Sprintf(format, a...)))
 }
 
 // Debugf adds this message to the trace's log, with a debugging level.
 func (t *Trace) Debugf(format string, a ...any) {
-	t.t.Printf(format, a...)
+	t.printf(log.Debug, format, a...)
+}
 
-	log.Log(log.Debug, 1, "%s %s: %s",
+func (t *Trace) printf(level log.Level, format string, a ...any) {
-		t.family, t.title, quote(fmt.Sprintf(format, a...)))
+	// Format the message only once, as it can be expensive.
+	msg := fmt.Sprintf(format, a...)
+	t.t.Printf("%s", msg)
+
+	// Only quote and log the message if it's going to be logged.
+	if log.V(level) {
+		log.Log(level, 2, "%s %s: %s", t.family, t.title, quote(msg))
+	}
 }
 
 // Errorf adds this message to the trace's log, with an error level.

internal/trace/trace_test.go

@@ -0,0 +1,119 @@
+package trace
+
+import (
+	"bytes"
+	"errors"
+	"io"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"blitiri.com.ar/go/chasquid/internal/nettrace"
+	"blitiri.com.ar/go/log"
+)
+
+type nopCloser struct{ io.Writer }
+
+func (nopCloser) Close() error { return nil }
+
+// setupLog replaces the default logger with one that writes to the returned
+// buffer, at the given level. It is restored when the test finishes.
+func setupLog(t *testing.T, level log.Level) *bytes.Buffer {
+	t.Helper()
+	buf := &bytes.Buffer{}
+	orig := log.Default
+	log.Default = log.New(nopCloser{buf})
+	log.Default.Level = level
+	log.Default.LogTime = false
+	log.Default.LogCaller = false
+	t.Cleanup(func() { log.Default = orig })
+	return buf
+}
+
+// traceEvents returns the rendered (HTML) active traces for the family.
+func traceEvents(t *testing.T, family string) string {
+	t.Helper()
+	req := httptest.NewRequest("GET", "/debug/traces?fam="+family+"&b=-1", nil)
+	w := httptest.NewRecorder()
+	nettrace.RenderTraces(w, req)
+	return w.Body.String()
+}
+
+// countingStringer counts how many times it was formatted.
+type countingStringer struct{ n *int }
+
+func (c countingStringer) String() string {
+	*c.n++
+	return "stringer"
+}
+
+func TestFormatOnce(t *testing.T) {
+	for _, level := range []log.Level{log.Info, log.Debug} {
+		setupLog(t, level)
+		tr := New("TestFormatOnce", "title")
+
+		n := 0
+		tr.Debugf("%v", countingStringer{&n})
+		if n != 1 {
+			t.Errorf("level %d: Debugf formatted %d times, expected 1",
+				level, n)
+		}
+
+		n = 0
+		tr.Printf("%v", countingStringer{&n})
+		if n != 1 {
+			t.Errorf("level %d: Printf formatted %d times, expected 1",
+				level, n)
+		}
+
+		tr.Finish()
+	}
+}
+
+func TestLog(t *testing.T) {
+	// At info level, debug messages are not logged.
+	buf := setupLog(t, log.Info)
+	tr := New("TestLog", "title")
+	tr.Printf("info %d", 1)
+	tr.Debugf("debug %d", 2)
+	tr.Errorf("error %d", 3)
+	tr.Error(errors.New("error 4"))
+	tr.Finish()
+
+	expected := "_ TestLog title: info 1\n" +
+		"_ TestLog title: error: error 3\n" +
+		"_ TestLog title: error: error 4\n"
+	if got := buf.String(); got != expected {
+		t.Errorf("unexpected log at info level:\n got: %q\nwant: %q",
+			got, expected)
+	}
+
+	// At debug level, they are. Messages are quoted.
+	buf = setupLog(t, log.Debug)
+	tr = New("TestLog", "title")
+	tr.Debugf("debug %q\n", "x")
+	tr.Finish()
+
+	expected = `. TestLog title: debug \"x\"\n` + "\n"
+	if got := buf.String(); got != expected {
+		t.Errorf("unexpected log at debug level:\n got: %q\nwant: %q",
+			got, expected)
+	}
+}
+
+func TestTraceEvents(t *testing.T) {
+	// Debug messages are added to the trace even if they are not logged.
+	setupLog(t, log.Info)
+	tr := New("TestTraceEvents", "title")
+	tr.Printf("info %d", 1)
+	tr.Debugf("debug %d", 2)
+	tr.Errorf("error %d", 3)
+
+	body := traceEvents(t, "TestTraceEvents")
+	for _, s := range []string{"info 1", "debug 2", "error: error 3"} {
+		if !strings.Contains(body, s) {
+			t.Errorf("trace does not contain %q:\n%s", s, body)
+		}
+	}
+	tr.Finish()
+}