From 7f6d94133559208b68acb423db098a047d494774 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Vicent=20Mart=C3=AD?= <42793+vmg@users.noreply.github.com>
Date: Mon, 25 Mar 2024 10:12:32 +0100
Subject: [PATCH] logstats: do not allocate memory while logging (#15539)

Signed-off-by: Vicent Marti <vmg@strn.cat>
---
 go/logstats/logger.go                         | 217 ++++++++++++++++++
 go/vt/vtgate/logstats/logstats.go             | 122 +++++-----
 go/vt/vtgate/logstats/logstats_test.go        |  17 +-
 go/vt/vttablet/filelogger/filelogger_test.go  |   2 +-
 .../sysloglogger/sysloglogger_test.go         |   2 +-
 .../tabletserver/tabletenv/logstats.go        | 106 +++++----
 .../tabletserver/tabletenv/logstats_test.go   |   8 +-
 7 files changed, 343 insertions(+), 131 deletions(-)
 create mode 100644 go/logstats/logger.go

diff --git a/go/logstats/logger.go b/go/logstats/logger.go
new file mode 100644
index 00000000000..90e208e7703
--- /dev/null
+++ b/go/logstats/logger.go
@@ -0,0 +1,217 @@
+/*
+Copyright 2024 The Vitess 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 logstats
+
+import (
+	"io"
+	"slices"
+	"strconv"
+	"strings"
+	"sync"
+	"time"
+
+	"vitess.io/vitess/go/hack"
+	"vitess.io/vitess/go/sqltypes"
+	querypb "vitess.io/vitess/go/vt/proto/query"
+)
+
+type logbv struct {
+	Name string
+	BVar *querypb.BindVariable
+}
+
+// Logger is a zero-allocation logger for logstats.
+// It can output logs as JSON or as plaintext, following the commonly used
+// logstats format that is shared between the tablets and the gates.
+type Logger struct {
+	b     []byte
+	bvars []logbv
+	n     int
+	json  bool
+}
+
+func sortBVars(sorted []logbv, bvars map[string]*querypb.BindVariable) []logbv {
+	for k, bv := range bvars {
+		sorted = append(sorted, logbv{k, bv})
+	}
+	slices.SortFunc(sorted, func(a, b logbv) int {
+		return strings.Compare(a.Name, b.Name)
+	})
+	return sorted
+}
+
+func (log *Logger) appendBVarsJSON(b []byte, bvars map[string]*querypb.BindVariable, full bool) []byte {
+	log.bvars = sortBVars(log.bvars[:0], bvars)
+
+	b = append(b, '{')
+	for i, bv := range log.bvars {
+		if i > 0 {
+			b = append(b, ',', ' ')
+		}
+		b = strconv.AppendQuote(b, bv.Name)
+		b = append(b, `: {"type": `...)
+		b = strconv.AppendQuote(b, querypb.Type_name[int32(bv.BVar.Type)])
+		b = append(b, `, "value": `...)
+
+		if sqltypes.IsIntegral(bv.BVar.Type) || sqltypes.IsFloat(bv.BVar.Type) {
+			b = append(b, bv.BVar.Value...)
+		} else if bv.BVar.Type == sqltypes.Tuple {
+			b = append(b, '"')
+			b = strconv.AppendInt(b, int64(len(bv.BVar.Values)), 10)
+			b = append(b, ` items"`...)
+		} else {
+			if full {
+				b = strconv.AppendQuote(b, hack.String(bv.BVar.Value))
+			} else {
+				b = append(b, '"')
+				b = strconv.AppendInt(b, int64(len(bv.BVar.Values)), 10)
+				b = append(b, ` bytes"`...)
+			}
+		}
+		b = append(b, '}')
+	}
+	return append(b, '}')
+}
+
+func (log *Logger) Init(json bool) {
+	log.n = 0
+	log.json = json
+	if log.json {
+		log.b = append(log.b, '{')
+	}
+}
+
+func (log *Logger) Redacted() {
+	log.String("[REDACTED]")
+}
+
+func (log *Logger) Key(key string) {
+	if log.json {
+		if log.n > 0 {
+			log.b = append(log.b, ',', ' ')
+		}
+		log.b = append(log.b, '"')
+		log.b = append(log.b, key...)
+		log.b = append(log.b, '"', ':', ' ')
+	} else {
+		if log.n > 0 {
+			log.b = append(log.b, '\t')
+		}
+	}
+	log.n++
+}
+
+func (log *Logger) StringUnquoted(value string) {
+	if log.json {
+		log.b = strconv.AppendQuote(log.b, value)
+	} else {
+		log.b = append(log.b, value...)
+	}
+}
+
+func (log *Logger) TabTerminated() {
+	if !log.json {
+		log.b = append(log.b, '\t')
+	}
+}
+
+func (log *Logger) String(value string) {
+	log.b = strconv.AppendQuote(log.b, value)
+}
+
+func (log *Logger) StringSingleQuoted(value string) {
+	if log.json {
+		log.b = strconv.AppendQuote(log.b, value)
+	} else {
+		log.b = append(log.b, '\'')
+		log.b = append(log.b, value...)
+		log.b = append(log.b, '\'')
+	}
+}
+
+func (log *Logger) Time(t time.Time) {
+	const timeFormat = "2006-01-02 15:04:05.000000"
+	if log.json {
+		log.b = append(log.b, '"')
+		log.b = t.AppendFormat(log.b, timeFormat)
+		log.b = append(log.b, '"')
+	} else {
+		log.b = t.AppendFormat(log.b, timeFormat)
+	}
+}
+
+func (log *Logger) Duration(t time.Duration) {
+	log.b = strconv.AppendFloat(log.b, t.Seconds(), 'f', 6, 64)
+}
+
+func (log *Logger) BindVariables(bvars map[string]*querypb.BindVariable, full bool) {
+	// the bind variables are printed as JSON in text mode because the original
+	// printing syntax, which was simply `fmt.Sprintf("%v")`, is not stable or
+	// safe to parse
+	log.b = log.appendBVarsJSON(log.b, bvars, full)
+}
+
+func (log *Logger) Int(i int64) {
+	log.b = strconv.AppendInt(log.b, i, 10)
+}
+
+func (log *Logger) Uint(u uint64) {
+	log.b = strconv.AppendUint(log.b, u, 10)
+}
+
+func (log *Logger) Bool(b bool) {
+	log.b = strconv.AppendBool(log.b, b)
+}
+
+func (log *Logger) Strings(strs []string) {
+	log.b = append(log.b, '[')
+	for i, t := range strs {
+		if i > 0 {
+			log.b = append(log.b, ',')
+		}
+		log.b = strconv.AppendQuote(log.b, t)
+	}
+	log.b = append(log.b, ']')
+}
+
+func (log *Logger) Flush(w io.Writer) (err error) {
+	if log.json {
+		log.b = append(log.b, '}')
+	}
+	log.b = append(log.b, '\n')
+	_, err = w.Write(log.b)
+
+	clear(log.bvars)
+	log.bvars = log.bvars[:0]
+	log.b = log.b[:0]
+	log.n = 0
+
+	loggerPool.Put(log)
+	return err
+}
+
+var loggerPool = sync.Pool{New: func() any {
+	return &Logger{}
+}}
+
+// NewLogger returns a new Logger instance to perform logstats logging.
+// The logger must be initialized with (*Logger).Init before usage and
+// flushed with (*Logger).Flush once all the key-values have been written
+// to it.
+func NewLogger() *Logger {
+	return loggerPool.Get().(*Logger)
+}
diff --git a/go/vt/vtgate/logstats/logstats.go b/go/vt/vtgate/logstats/logstats.go
index 5ea7820a72e..8f8ba41e3cd 100644
--- a/go/vt/vtgate/logstats/logstats.go
+++ b/go/vt/vtgate/logstats/logstats.go
@@ -18,21 +18,16 @@ package logstats
 
 import (
 	"context"
-	"encoding/json"
-	"fmt"
 	"io"
 	"net/url"
 	"time"
 
 	"github.com/google/safehtml"
 
-	"vitess.io/vitess/go/sqltypes"
+	"vitess.io/vitess/go/logstats"
 	"vitess.io/vitess/go/streamlog"
-	"vitess.io/vitess/go/tb"
 	"vitess.io/vitess/go/vt/callerid"
 	"vitess.io/vitess/go/vt/callinfo"
-	"vitess.io/vitess/go/vt/log"
-
 	querypb "vitess.io/vitess/go/vt/proto/query"
 )
 
@@ -128,69 +123,60 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
 		return nil
 	}
 
-	// FormatBindVariables call might panic so we're going to catch it here
-	// and print out the stack trace for debugging.
-	defer func() {
-		if x := recover(); x != nil {
-			log.Errorf("Uncaught panic:\n%v\n%s", x, tb.Stack(4))
-		}
-	}()
-
-	formattedBindVars := "\"[REDACTED]\""
-	if !streamlog.GetRedactDebugUIQueries() {
-		_, fullBindParams := params["full"]
-		formattedBindVars = sqltypes.FormatBindVariables(
-			stats.BindVariables,
-			fullBindParams,
-			streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON,
-		)
-	}
-
-	// TODO: remove username here we fully enforce immediate caller id
+	redacted := streamlog.GetRedactDebugUIQueries()
+	_, fullBindParams := params["full"]
 	remoteAddr, username := stats.RemoteAddrUsername()
 
-	var fmtString string
-	switch streamlog.GetQueryLogFormat() {
-	case streamlog.QueryLogFormatText:
-		fmtString = "%v\t%v\t%v\t'%v'\t'%v'\t%v\t%v\t%.6f\t%.6f\t%.6f\t%.6f\t%v\t%q\t%v\t%v\t%v\t%q\t%q\t%q\t%v\t%v\t%q\n"
-	case streamlog.QueryLogFormatJSON:
-		fmtString = "{\"Method\": %q, \"RemoteAddr\": %q, \"Username\": %q, \"ImmediateCaller\": %q, \"Effective Caller\": %q, \"Start\": \"%v\", \"End\": \"%v\", \"TotalTime\": %.6f, \"PlanTime\": %v, \"ExecuteTime\": %v, \"CommitTime\": %v, \"StmtType\": %q, \"SQL\": %q, \"BindVars\": %v, \"ShardQueries\": %v, \"RowsAffected\": %v, \"Error\": %q, \"TabletType\": %q, \"SessionUUID\": %q, \"Cached Plan\": %v, \"TablesUsed\": %v, \"ActiveKeyspace\": %q}\n"
-	}
-
-	tables := stats.TablesUsed
-	if tables == nil {
-		tables = []string{}
-	}
-	tablesUsed, marshalErr := json.Marshal(tables)
-	if marshalErr != nil {
-		return marshalErr
+	log := logstats.NewLogger()
+	log.Init(streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON)
+	log.Key("Method")
+	log.StringUnquoted(stats.Method)
+	log.Key("RemoteAddr")
+	log.StringUnquoted(remoteAddr)
+	log.Key("Username")
+	log.StringUnquoted(username)
+	log.Key("ImmediateCaller")
+	log.StringSingleQuoted(stats.ImmediateCaller())
+	log.Key("Effective Caller")
+	log.StringSingleQuoted(stats.EffectiveCaller())
+	log.Key("Start")
+	log.Time(stats.StartTime)
+	log.Key("End")
+	log.Time(stats.EndTime)
+	log.Key("TotalTime")
+	log.Duration(stats.TotalTime())
+	log.Key("PlanTime")
+	log.Duration(stats.PlanTime)
+	log.Key("ExecuteTime")
+	log.Duration(stats.ExecuteTime)
+	log.Key("CommitTime")
+	log.Duration(stats.CommitTime)
+	log.Key("StmtType")
+	log.StringUnquoted(stats.StmtType)
+	log.Key("SQL")
+	log.String(stats.SQL)
+	log.Key("BindVars")
+	if redacted {
+		log.Redacted()
+	} else {
+		log.BindVariables(stats.BindVariables, fullBindParams)
 	}
-	_, err := fmt.Fprintf(
-		w,
-		fmtString,
-		stats.Method,
-		remoteAddr,
-		username,
-		stats.ImmediateCaller(),
-		stats.EffectiveCaller(),
-		stats.StartTime.Format("2006-01-02 15:04:05.000000"),
-		stats.EndTime.Format("2006-01-02 15:04:05.000000"),
-		stats.TotalTime().Seconds(),
-		stats.PlanTime.Seconds(),
-		stats.ExecuteTime.Seconds(),
-		stats.CommitTime.Seconds(),
-		stats.StmtType,
-		stats.SQL,
-		formattedBindVars,
-		stats.ShardQueries,
-		stats.RowsAffected,
-		stats.ErrorStr(),
-		stats.TabletType,
-		stats.SessionUUID,
-		stats.CachedPlan,
-		string(tablesUsed),
-		stats.ActiveKeyspace,
-	)
-
-	return err
+	log.Key("ShardQueries")
+	log.Uint(stats.ShardQueries)
+	log.Key("RowsAffected")
+	log.Uint(stats.RowsAffected)
+	log.Key("Error")
+	log.String(stats.ErrorStr())
+	log.Key("TabletType")
+	log.String(stats.TabletType)
+	log.Key("SessionUUID")
+	log.String(stats.SessionUUID)
+	log.Key("Cached Plan")
+	log.Bool(stats.CachedPlan)
+	log.Key("TablesUsed")
+	log.Strings(stats.TablesUsed)
+	log.Key("ActiveKeyspace")
+	log.String(stats.ActiveKeyspace)
+
+	return log.Flush(w)
 }
diff --git a/go/vt/vtgate/logstats/logstats_test.go b/go/vt/vtgate/logstats/logstats_test.go
index dbe49b200b8..ae3c01e0f0b 100644
--- a/go/vt/vtgate/logstats/logstats_test.go
+++ b/go/vt/vtgate/logstats/logstats_test.go
@@ -79,7 +79,7 @@ func TestLogStatsFormat(t *testing.T) {
 		{ // 0
 			redact:   false,
 			format:   "text",
-			expected: "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n",
+			expected: "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n",
 			bindVars: intBindVar,
 		}, { // 1
 			redact:   true,
@@ -99,7 +99,7 @@ func TestLogStatsFormat(t *testing.T) {
 		}, { // 4
 			redact:   false,
 			format:   "text",
-			expected: "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\tmap[strVal:type:VARCHAR value:\"abc\"]\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n",
+			expected: "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\t{\"strVal\": {\"type\": \"VARCHAR\", \"value\": \"abc\"}}\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n",
 			bindVars: stringBindVar,
 		}, { // 5
 			redact:   true,
@@ -129,14 +129,13 @@ func TestLogStatsFormat(t *testing.T) {
 			streamlog.SetQueryLogFormat(test.format)
 			if test.format == "text" {
 				got := testFormat(t, logStats, params)
+				t.Logf("got: %s", got)
 				assert.Equal(t, test.expected, got)
-				for _, variable := range logStats.BindVariables {
-					fmt.Println("->" + fmt.Sprintf("%v", variable))
-				}
 				return
 			}
 
 			got := testFormat(t, logStats, params)
+			t.Logf("got: %s", got)
 			var parsed map[string]any
 			err := json.Unmarshal([]byte(got), &parsed)
 			assert.NoError(t, err)
@@ -157,12 +156,12 @@ func TestLogStatsFilter(t *testing.T) {
 	params := map[string][]string{"full": {}}
 
 	got := testFormat(t, logStats, params)
-	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
+	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
 	assert.Equal(t, want, got)
 
 	streamlog.SetQueryLogFilterTag("LOG_THIS_QUERY")
 	got = testFormat(t, logStats, params)
-	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
+	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
 	assert.Equal(t, want, got)
 
 	streamlog.SetQueryLogFilterTag("NOT_THIS_QUERY")
@@ -180,12 +179,12 @@ func TestLogStatsRowThreshold(t *testing.T) {
 	params := map[string][]string{"full": {}}
 
 	got := testFormat(t, logStats, params)
-	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
+	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
 	assert.Equal(t, want, got)
 
 	streamlog.SetQueryLogRowThreshold(0)
 	got = testFormat(t, logStats, params)
-	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
+	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
 	assert.Equal(t, want, got)
 	streamlog.SetQueryLogRowThreshold(1)
 	got = testFormat(t, logStats, params)
diff --git a/go/vt/vttablet/filelogger/filelogger_test.go b/go/vt/vttablet/filelogger/filelogger_test.go
index 1562c9626a8..f747ebba93b 100644
--- a/go/vt/vttablet/filelogger/filelogger_test.go
+++ b/go/vt/vttablet/filelogger/filelogger_test.go
@@ -60,7 +60,7 @@ func TestFileLog(t *testing.T) {
 	for i := 0; i < 10; i++ {
 		time.Sleep(10 * time.Millisecond)
 
-		want := "\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\t\t\"test 1\"\tmap[]\t1\t\"test 1 PII\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"\t\n\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\t\t\"test 2\"\tmap[]\t1\t\"test 2 PII\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"\t\n"
+		want := "\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\t\t\"test 1\"\t{}\t1\t\"test 1 PII\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"\t\n\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\t\t\"test 2\"\t{}\t1\t\"test 2 PII\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"\t\n"
 		contents, _ := os.ReadFile(logPath)
 		got := string(contents)
 		if want == got {
diff --git a/go/vt/vttablet/sysloglogger/sysloglogger_test.go b/go/vt/vttablet/sysloglogger/sysloglogger_test.go
index c62a4396ac6..8347d0433af 100644
--- a/go/vt/vttablet/sysloglogger/sysloglogger_test.go
+++ b/go/vt/vttablet/sysloglogger/sysloglogger_test.go
@@ -85,7 +85,7 @@ func (fw *failingFakeWriter) Close() error          { return nil }
 // expectedLogStatsText returns the results expected from the plugin processing a dummy message generated by mockLogStats(...).
 func expectedLogStatsText(originalSQL string) string {
 	return fmt.Sprintf("Execute\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\tPASS_SELECT\t"+
-		"\"%s\"\t%s\t1\t\"%s\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"", originalSQL, "map[]", originalSQL)
+		"\"%s\"\t%s\t1\t\"%s\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"", originalSQL, "{}", originalSQL)
 }
 
 // expectedRedactedLogStatsText returns the results expected from the plugin processing a dummy message generated by mockLogStats(...)
diff --git a/go/vt/vttablet/tabletserver/tabletenv/logstats.go b/go/vt/vttablet/tabletserver/tabletenv/logstats.go
index 962b5f0b122..ad7e09de169 100644
--- a/go/vt/vttablet/tabletserver/tabletenv/logstats.go
+++ b/go/vt/vttablet/tabletserver/tabletenv/logstats.go
@@ -18,7 +18,6 @@ package tabletenv
 
 import (
 	"context"
-	"fmt"
 	"io"
 	"net/url"
 	"strings"
@@ -26,6 +25,7 @@ import (
 
 	"github.com/google/safehtml"
 
+	"vitess.io/vitess/go/logstats"
 	"vitess.io/vitess/go/sqltypes"
 	"vitess.io/vitess/go/streamlog"
 	"vitess.io/vitess/go/vt/callerid"
@@ -181,55 +181,65 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
 		return nil
 	}
 
-	rewrittenSQL := "[REDACTED]"
-	formattedBindVars := "\"[REDACTED]\""
-
-	if !streamlog.GetRedactDebugUIQueries() {
-		rewrittenSQL = stats.RewrittenSQL()
-
-		_, fullBindParams := params["full"]
-		formattedBindVars = sqltypes.FormatBindVariables(
-			stats.BindVariables,
-			fullBindParams,
-			streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON,
-		)
-	}
-
+	redacted := streamlog.GetRedactDebugUIQueries()
+	_, fullBindParams := params["full"]
 	// TODO: remove username here we fully enforce immediate caller id
 	callInfo, username := stats.CallInfo()
 
-	// Valid options for the QueryLogFormat are text or json
-	var fmtString string
-	switch streamlog.GetQueryLogFormat() {
-	case streamlog.QueryLogFormatText:
-		fmtString = "%v\t%v\t%v\t'%v'\t'%v'\t%v\t%v\t%.6f\t%v\t%q\t%v\t%v\t%q\t%v\t%.6f\t%.6f\t%v\t%v\t%v\t%q\t\n"
-	case streamlog.QueryLogFormatJSON:
-		fmtString = "{\"Method\": %q, \"CallInfo\": %q, \"Username\": %q, \"ImmediateCaller\": %q, \"Effective Caller\": %q, \"Start\": \"%v\", \"End\": \"%v\", \"TotalTime\": %.6f, \"PlanType\": %q, \"OriginalSQL\": %q, \"BindVars\": %v, \"Queries\": %v, \"RewrittenSQL\": %q, \"QuerySources\": %q, \"MysqlTime\": %.6f, \"ConnWaitTime\": %.6f, \"RowsAffected\": %v,\"TransactionID\": %v,\"ResponseSize\": %v, \"Error\": %q}\n"
+	log := logstats.NewLogger()
+	log.Init(streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON)
+	log.Key("Method")
+	log.StringUnquoted(stats.Method)
+	log.Key("CallInfo")
+	log.StringUnquoted(callInfo)
+	log.Key("Username")
+	log.StringUnquoted(username)
+	log.Key("ImmediateCaller")
+	log.StringSingleQuoted(stats.ImmediateCaller())
+	log.Key("Effective Caller")
+	log.StringSingleQuoted(stats.EffectiveCaller())
+	log.Key("Start")
+	log.Time(stats.StartTime)
+	log.Key("End")
+	log.Time(stats.EndTime)
+	log.Key("TotalTime")
+	log.Duration(stats.TotalTime())
+	log.Key("PlanType")
+	log.StringUnquoted(stats.PlanType)
+	log.Key("OriginalSQL")
+	log.String(stats.OriginalSQL)
+	log.Key("BindVars")
+	if redacted {
+		log.Redacted()
+	} else {
+		log.BindVariables(stats.BindVariables, fullBindParams)
 	}
-
-	_, err := fmt.Fprintf(
-		w,
-		fmtString,
-		stats.Method,
-		callInfo,
-		username,
-		stats.ImmediateCaller(),
-		stats.EffectiveCaller(),
-		stats.StartTime.Format("2006-01-02 15:04:05.000000"),
-		stats.EndTime.Format("2006-01-02 15:04:05.000000"),
-		stats.TotalTime().Seconds(),
-		stats.PlanType,
-		stats.OriginalSQL,
-		formattedBindVars,
-		stats.NumberOfQueries,
-		rewrittenSQL,
-		stats.FmtQuerySources(),
-		stats.MysqlResponseTime.Seconds(),
-		stats.WaitingForConnection.Seconds(),
-		stats.RowsAffected,
-		stats.TransactionID,
-		stats.SizeOfResponse(),
-		stats.ErrorStr(),
-	)
-	return err
+	log.Key("Queries")
+	log.Int(int64(stats.NumberOfQueries))
+	log.Key("RewrittenSQL")
+	if redacted {
+		log.Redacted()
+	} else {
+		log.String(stats.RewrittenSQL())
+	}
+	log.Key("QuerySources")
+	log.StringUnquoted(stats.FmtQuerySources())
+	log.Key("MysqlTime")
+	log.Duration(stats.MysqlResponseTime)
+	log.Key("ConnWaitTime")
+	log.Duration(stats.WaitingForConnection)
+	log.Key("RowsAffected")
+	log.Uint(uint64(stats.RowsAffected))
+	log.Key("TransactionID")
+	log.Int(stats.TransactionID)
+	log.Key("ResponseSize")
+	log.Int(int64(stats.SizeOfResponse()))
+	log.Key("Error")
+	log.String(stats.ErrorStr())
+
+	// logstats from the vttablet are always tab-terminated; keep this for backwards
+	// compatibility for existing parsers
+	log.TabTerminated()
+
+	return log.Flush(w)
 }
diff --git a/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go b/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go
index 84de50aae74..f04b1498982 100644
--- a/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go
+++ b/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go
@@ -74,7 +74,7 @@ func TestLogStatsFormat(t *testing.T) {
 	streamlog.SetRedactDebugUIQueries(false)
 	streamlog.SetQueryLogFormat("text")
 	got := testFormat(logStats, url.Values(params))
-	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n"
+	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n"
 	if got != want {
 		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
 	}
@@ -128,7 +128,7 @@ func TestLogStatsFormat(t *testing.T) {
 
 	streamlog.SetQueryLogFormat("text")
 	got = testFormat(logStats, url.Values(params))
-	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\tmap[strVal:type:VARCHAR value:\"abc\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n"
+	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\t{\"strVal\": {\"type\": \"VARCHAR\", \"value\": \"abc\"}}\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n"
 	if got != want {
 		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
 	}
@@ -165,14 +165,14 @@ func TestLogStatsFilter(t *testing.T) {
 	params := map[string][]string{"full": {}}
 
 	got := testFormat(logStats, url.Values(params))
-	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n"
+	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n"
 	if got != want {
 		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
 	}
 
 	streamlog.SetQueryLogFilterTag("LOG_THIS_QUERY")
 	got = testFormat(logStats, url.Values(params))
-	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n"
+	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n"
 	if got != want {
 		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
 	}