`querylog`: json format version 2 #15271

timvaillancourt · 2024-02-16T20:14:26Z

Description

This PR adds a new version 2.0 format for --querylog-format=json. This new format is opt-in with the flag --querylog-json-v2, however I propose the new format replaces the current format in later releases

The motivation is to resolve cases where the current format produces invalid JSON caused by certain bind variables values that break json's spec (bug confirmed/identified by Vinted and Slack in prod - Slack 🧵)

The version 2.0 format resolves the bind-variable breakage by letting encoding/json library marshal the []byte value as base64, which is default behaviour in the library. The original implementation builds json manually using fmt.Sprintf(...), printing []byte as %q, which explains how we got here. The new format is a breaking change to users of --querylog-format=json, however, which is why I added this behind a flag

Breaking changes:

Bind variable values are base64 encoded (transparently by encoding/json)
- Resolves Bug Report: FormatBindVariables return invalid JSON string #12872
- Users reading querylogs with Go's encoding/json + unmarshal using the LogStatsJSON struct (or the value field only as []byte) won't need to know it was base64
- Users reading querylogs from other languages will need to be aware of the base64 encoding of bind var values, but I think that is unavoidable
Effective Caller field renamed to EffectiveCaller, to be consistent with ImmediateCaller and other camel-cased fields
- Also spaces in json keys is kind of gross 😄
Start and End renamed to StartTime and EndTime respectively, for clarity and to be consistent with the other Time-suffixed vars (eg: PlanTime/ExecuteTime)
Pre-existing CachedPlan key/value added to new vttablet format
The order of the key/values changed
When certain values are nil/"" they are not added to the json (via json:",omitempty")

The existing text and json (without --querylog-json-v2 flag) formats should be unaffected by this change

Example vtgate log (pretty-printed, without redaction):

{
  "RemoteAddr": "<ADDR HERE>",
  "Username": "<USERNAME HERE>",
  "ImmediateCaller": "<CALLER HERE>",
  "EffectiveCaller": "<CALLER HERE>",
  "Method": "test",
  "TabletType": "PRIMARY",
  "StmtType": "select",
  "SQL": "select * from testtable where name = :strVal and message = :bytesVal",
  "BindVariables": {
    "bytesVal": {
      "Type": "VARBINARY",
      "Value": "FmtAtEq6S9Y="
    },
    "strVal": {
      "Type": "VARCHAR",
      "Value": "YWJj"
    }
  },
  "StartTime": "2017-01-01T01:02:03Z",
  "EndTime": "2017-01-01T01:02:04.000001234Z",
  "ShardQueries": 0,
  "RowsAffected": 0,
  "RowsReturned": 0,
  "PlanTime": 0,
  "ExecuteTime": 0,
  "CommitTime": 0,
  "TablesUsed": [
    "ks1.tbl1",
    "ks2.tbl2"
  ],
  "SessionUUID": "suuid",
  "CachedPlan": false,
  "ActiveKeyspace": "db"
}

Example vttablet log (pretty-printed, without redaction):

{
  "CallInfo": "<INFO HERE>",
  "Username": "<USERNAME HERE>",
  "ImmediateCaller": "<CALLER HERE>",
  "EffectiveCaller": "<CALLER HERE>",
  "RewrittenSQL": "sql with pii",
  "TotalTime": 1000001234,
  "ResponseSize": 1,
  "Method": "test",
  "PlanType": "",
  "OriginalSQL": "sql",
  "BindVariables": {
    "bytesVal": {
      "Type": "VARBINARY",
      "Value": "FmtAtEq6S9Y="
    },
    "intVal": {
      "Type": "INT64",
      "Value": "MQ=="
    }
  },
  "RowsAffected": 0,
  "NumberOfQueries": 1,
  "StartTime": "2017-01-01T01:02:03Z",
  "EndTime": "2017-01-01T01:02:04.000001234Z",
  "MysqlResponseTime": 0,
  "WaitingForConnection": 0,
  "QuerySources": 2,
  "TransactionID": 12345,
  "ReservedID": 0,
  "CachedPlan": false
}

Related Issue(s)

Checklist

"Backport to:" labels have been added if this change should be back-ported to release branches
If this change is to be back-ported to previous releases, a justification is included in the PR description
Tests were added or are not required
Did the new or modified tests pass consistently locally and on CI?
Documentation was added or is not required

Deployment Notes

Signed-off-by: Tim Vaillancourt <[email protected]>

vitess-bot · 2024-02-16T20:14:29Z

Signed-off-by: Tim Vaillancourt <[email protected]>

codecov · 2024-02-16T22:39:31Z

Codecov Report

Attention: Patch coverage is 79.56989% with 19 lines in your changes missing coverage. Please review.

Project coverage is 67.50%. Comparing base (d4f0c2a) to head (4246773).
Report is 496 commits behind head on main.

Files	Patch %	Lines
go/streamlog/bind_variable.go	70.37%	16 Missing ⚠️
go/streamlog/streamlog.go	80.00%	1 Missing ⚠️
go/vt/vtgate/logstats/logstats.go	92.85%	1 Missing ⚠️
go/vt/vttablet/tabletserver/tabletenv/logstats.go	94.73%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #15271      +/-   ##
==========================================
+ Coverage   67.38%   67.50%   +0.12%     
==========================================
  Files        1560     1562       +2     
  Lines      192752   193439     +687     
==========================================
+ Hits       129886   130582     +696     
+ Misses      62866    62857       -9

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

Signed-off-by: Tim Vaillancourt <[email protected]>

github-actions · 2024-03-21T01:27:18Z

This PR is being marked as stale because it has been open for 30 days with no activity. To rectify, you may do any of the following:

Push additional commits to the associated branch.
Remove the stale label.
Add a comment indicating why it is not stale.

If no action is taken within 7 days, this PR will be closed.

timvaillancourt · 2024-03-21T20:21:04Z

~~I plan to wrap this up once I can figure out a smart way to add optimizer hints on the vttablet level. It seems vtgate has logic to add optimizer hints but it's not clear in vttablet~~

~~I'm curious if @harshit-gangal has time for a quick chat about that detail?~~

EDIT: clicked wrong PR tab, this comment was for #14460

GuptaManan100

Looks good to me!

mdlayher

CC @vmg because you just worked on some code in this area.

mdlayher · 2024-03-29T12:41:21Z

go/streamlog/bind_variable.go

+
+// NewBindVariable returns a wrapped *querypb.BindVariable object.
+func NewBindVariable(bv *querypb.BindVariable) BindVariable {
+	newBv := BindVariable{


We know the capacity of newBv.Values up front and should preallocate it here before the loop.

mdlayher · 2024-03-29T12:41:47Z

go/streamlog/bind_variable.go

+
+// MarshalJSON renders the BindVariableValue as json and optionally redacts the value.
+func (bv BindVariableValue) MarshalJSON() ([]byte, error) {
+	out := map[string]interface{}{


Suggested change

out := map[string]interface{}{

out := map[string]any{

For new code IMO.

mdlayher · 2024-03-29T12:42:35Z

go/streamlog/bind_variable.go

+
+// bindVariablesValuesToProto converts a slice of *BindVariableValue to *querypb.Value.
+func bindVariablesValuesToProto(vals []*BindVariableValue) ([]*querypb.Value, error) {
+	values := make([]*querypb.Value, len(vals))


Suggested change

values := make([]*querypb.Value, len(vals))

values := make([]*querypb.Value, 0, len(vals))

This needs to be allocated with length 0 or else you'll end up appending to a slice populated with zero values up front.

mdlayher · 2024-03-29T12:43:29Z

go/streamlog/streamlog.go

@@ -90,6 +99,9 @@ func registerStreamLogFlags(fs *pflag.FlagSet) {
 	// QueryLogFormat controls the format of the query log (either text or json)
 	fs.StringVar(&queryLogFormat, "querylog-format", queryLogFormat, "format for query logs (\"text\" or \"json\")")

+	// QueryLogJSONFormat controls whether the new querylog json format is used
+	fs.BoolVar(&queryLogJSONV2, "querylog-json-v2", false, "use v2 format for querylog-format=json")


If we already have --querylog-format=json, why not --querylog-format=json-v2 rather than a new flag?

mdlayher · 2024-03-29T12:43:46Z

go/vt/vtgate/logstats/logstats.go

@@ -36,14 +36,13 @@ import (
 	querypb "vitess.io/vitess/go/vt/proto/query"
 )

-// LogStats records the stats for a single vtgate query


mdlayher · 2024-03-29T12:45:00Z

go/vt/vtgate/logstats/logstats.go

@@ -52,13 +51,21 @@ type LogStats struct {
 	PlanTime       time.Duration
 	ExecuteTime    time.Duration
 	CommitTime     time.Duration
-	Error          error
+	Error          error `json:",omitempty"`


This seems incorrect. Did you intend for -?

mdlayher · 2024-03-29T12:45:34Z

go/vt/vtgate/logstats/logstats.go

 	TablesUsed     []string
 	SessionUUID    string
 	CachedPlan     bool
 	ActiveKeyspace string // ActiveKeyspace is the selected keyspace `use ks`
 }

+type LogStatsJSON struct {


Name with JSONv2 to separate from the base implementation?

mdlayher · 2024-03-29T12:46:42Z

go/vt/vttablet/tabletserver/tabletenv/logstats.go

 	PlanType             string
 	OriginalSQL          string
-	BindVariables        map[string]*querypb.BindVariable
-	rewrittenSqls        []string
+	BindVariables        map[string]streamlog.BindVariable `json:",omitempty"`


Same question as prior.

mdlayher · 2024-03-29T12:46:46Z

go/vt/vttablet/tabletserver/tabletenv/logstats.go

 	TransactionID        int64
 	ReservedID           int64
-	Error                error
+	Error                error `json:",omitempty"`


Same question as prior.

mdlayher · 2024-03-29T12:46:55Z

go/vt/vtgate/logstats/logstats.go

 	Method         string
 	TabletType     string
 	StmtType       string
 	SQL            string
-	BindVariables  map[string]*querypb.BindVariable
+	BindVariables  map[string]streamlog.BindVariable `json:",omitempty"`


vmg · 2024-04-01T14:13:07Z

Oy my bad, I completely overlooked this PR when I began working on #15539 so there's an obvious conflict. That PR is now merged and the arewefast results are looking amazingly good (up to 5% less CPU usage on the tablets in the OLTP benchmarks, which are usually not very CPU hungry). So now we had a good understanding that query logging is a CPU bottleneck, and the approach I chose in #15539 seems to be very good at tackling that whilst being reasonably maintainable.

Because of this, I'd like to see the changes in this PR implemented using the same style of "log builder" that I've merged. I think all the proposed syntax changes here are perfectly reasonable, and shipping them behind a v2 flag is a good idea, but I'd be very wary of using encoding/json as the serialization because it allocates like a sieve. It'd be a significant regression!

@timvaillancourt: I'm gonna try to find some time this week (maybe Friday morning since it's a day off) to port this PR to the new builder API. If this is urgent to you, please feel free to do it yourself and ask me any questions! Otherwise I don't mind picking up the work here because, again, we've found out how critical performance-wise is the logging path.

timvaillancourt · 2024-04-10T22:45:57Z

Oy my bad, I completely overlooked this PR when I began working on #15539 so there's an obvious conflict. That PR is now merged and the arewefast results are looking amazingly good (up to 5% less CPU usage on the tablets in the OLTP benchmarks, which are usually not very CPU hungry). So now we had a good understanding that query logging is a CPU bottleneck, and the approach I chose in #15539 seems to be very good at tackling that whilst being reasonably maintainable.

@vmg 👋 long time! No problem, I'm excited to see performance improvements - I suspected this code path could be optimized

I'd be very wary of using encoding/json as the serialization because it allocates like a sieve. It'd be a significant regression!

Yeah, that's a big drawback for this PR 👎. Perhaps this is why fmt.Sprintf(...) was used originally? I wonder if this could eventually move to github.com/go-json-experiment/json (heard but did not confirm it allocates less), once it's part of the standard library

@timvaillancourt: I'm gonna try to find some time this week (maybe Friday morning since it's a day off) to port this PR to the new builder API. If this is urgent to you, please feel free to do it yourself and ask me any questions! Otherwise I don't mind picking up the work here because, again, we've found out how critical performance-wise is the logging path.

This isn't urgent but happy to help somehow! If you have some time to describe what you had planned I can offload this optionally

Signed-off-by: Vilius Okockis <[email protected]>

DeathBorn · 2024-04-17T06:22:08Z

https://github.com/vitessio/vitess/pull/15539/files#diff-3c26e166a7ecbd772596c75f87d03b0dc849be5a5a443b8429be0e28a170519cR66-R68
@vmg I think there is a bug - it should be Type and Value instead of lowercased values.

DeathBorn · 2024-04-17T06:56:05Z

@timvaillancourt from our perspective, it is good enough to encode only JSON string values, so this is my backport on top of almost zero allocation logger.
a1f1266...a774f11

encode bench

import (
	"bytes"
	"context"
	"fmt"
	"testing"
	"time"

	"vitess.io/vitess/go/logstats"
	"vitess.io/vitess/go/streamlog"
	querypb "vitess.io/vitess/go/vt/proto/query"
	"vitess.io/vitess/go/vt/vtgate"
)

func BenchmarkLogStatsFormat(b *testing.B) {
	b.ReportAllocs()

	stats := vtgate.NewLogStats(context.Background(), "test", "sql1", "suuid", nil)
	stats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC)
	stats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC)

	stats.Table = "ks1.tbl1,ks2.tbl2"
	stats.TabletType = "MASTER"
	stats.Keyspace = "db"
	stats.BindVariables = map[string]*querypb.BindVariable{
		"Type_BINARY,  ": {Type: querypb.Type_BINARY, Value: []byte("a")},                     // encoded base64
		"Type_BIT,     ": {Type: querypb.Type_BIT, Value: []byte("1")},                        // encoded base64
		"Type_BLOB,    ": {Type: querypb.Type_BLOB, Value: []byte("a")},                       // encoded base64
		"Type_CHAR,    ": {Type: querypb.Type_CHAR, Value: []byte("a")},                       // encoded base64
		"Type_DATE,    ": {Type: querypb.Type_DATE, Value: []byte("2012-02-24")},              // encoded base64
		"Type_DATETIME,": {Type: querypb.Type_DATETIME, Value: []byte("2012-02-24 23:19:43")}, // encoded base64
		"Type_DECIMAL, ": {Type: querypb.Type_DECIMAL, Value: []byte("1.00")},                 // encoded base64
		"Type_ENUM,    ": {Type: querypb.Type_ENUM, Value: []byte("a")},                       // encoded base64
		"Type_FLOAT32, ": {Type: querypb.Type_FLOAT32, Value: []byte("1.00")},
		"Type_FLOAT64, ": {Type: querypb.Type_FLOAT64, Value: []byte("1.00")},
		"Type_INT8,    ": {Type: querypb.Type_INT8, Value: []byte("1")},
		"Type_INT16,   ": {Type: querypb.Type_INT16, Value: []byte("1")},
		"Type_INT24,   ": {Type: querypb.Type_INT24, Value: []byte("1")},
		"Type_INT32,   ": {Type: querypb.Type_INT32, Value: []byte("1")},
		"Type_INT64,   ": {Type: querypb.Type_INT64, Value: []byte("1")},
		"Type_SET,     ": {Type: querypb.Type_SET, Value: []byte("a")},                         // encoded base64
		"Type_TEXT,    ": {Type: querypb.Type_TEXT, Value: []byte("a")},                        // encoded base64
		"Type_TIME,    ": {Type: querypb.Type_TIME, Value: []byte("23:19:43")},                 // encoded base64
		"Type_TIMESTAMP": {Type: querypb.Type_TIMESTAMP, Value: []byte("2012-02-24 23:19:43")}, // encoded base64
		"Type_UINT8,   ": {Type: querypb.Type_UINT8, Value: []byte("1")},
		"Type_UINT16,  ": {Type: querypb.Type_UINT16, Value: []byte("1")},
		"Type_UINT24,  ": {Type: querypb.Type_UINT24, Value: []byte("1")},
		"Type_UINT32,  ": {Type: querypb.Type_UINT32, Value: []byte("1")},
		"Type_UINT64,  ": {Type: querypb.Type_UINT64, Value: []byte("1")},
		"Type_VARBINARY": {Type: querypb.Type_VARBINARY, Value: []byte("a")}, // encoded base64
		"Type_VARCHAR, ": {Type: querypb.Type_VARCHAR, Value: []byte("a")},   // encoded base64
		"Type_YEAR,    ": {Type: querypb.Type_YEAR, Value: []byte("1")},      // encoded base64
		"Type_TUPLE,1  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_FLOAT64, Value: []byte("1")}, {Type: querypb.Type_FLOAT64, Value: []byte("2")}}},
		"Type_TUPLE,2  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_INT64, Value: []byte("1")}, {Type: querypb.Type_INT64, Value: []byte("2")}}},
		"Type_TUPLE,3  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_UINT64, Value: []byte("1")}, {Type: querypb.Type_UINT64, Value: []byte("2")}}},
		"Type_TUPLE,4  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_VARBINARY, Value: []byte("aa")}, {Type: querypb.Type_VARBINARY, Value: []byte("bb")}}},
		"Type_TUPLE,5  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_VARBINARY, Value: []byte("aa")}, {Type: querypb.Type_INT64, Value: []byte("1")}}},
	}
	fullBindParams := true
	remoteAddr, username := stats.RemoteAddrUsername()
	*streamlog.QueryLogFormat = streamlog.QueryLogFormatJSON
	*streamlog.QueryLogJSONV2 = true

	b.RunParallel(func(pb *testing.PB) {
		for pb.Next() {
			var w bytes.Buffer
			log := logstats.NewLogger()
			log.Init(*streamlog.QueryLogFormat == 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 *streamlog.QueryLogJSONV2 {
				log.BindVariablesV2(stats.BindVariables, fullBindParams)
			} else {
				log.BindVariables(stats.BindVariables, fullBindParams)
			}
			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("InTransaction")
			log.Bool(stats.InTransaction)
			log.Key("Table")
			log.String(stats.Table)
			log.Key("Keyspace")
			log.String(stats.Keyspace)

			log.Flush(&w)
		}
	})

}

old bench

import (
	"bytes"
	"context"
	"fmt"
	"testing"
	"time"

	"vitess.io/vitess/go/sqltypes"
	"vitess.io/vitess/go/streamlog"
	querypb "vitess.io/vitess/go/vt/proto/query"
	"vitess.io/vitess/go/vt/vtgate"
)

func BenchmarkLogStatsFormat(b *testing.B) {
	b.ReportAllocs()

	stats := vtgate.NewLogStats(context.Background(), "test", "sql1", "suuid", nil)
	stats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC)
	stats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC)

	stats.Table = "ks1.tbl1,ks2.tbl2"
	stats.TabletType = "MASTER"
	stats.Keyspace = "db"
	stats.BindVariables = map[string]*querypb.BindVariable{
		"Type_BINARY,  ": {Type: querypb.Type_BINARY, Value: []byte("a")},
		"Type_BIT,     ": {Type: querypb.Type_BIT, Value: []byte("1")},
		"Type_BLOB,    ": {Type: querypb.Type_BLOB, Value: []byte("a")},
		"Type_CHAR,    ": {Type: querypb.Type_CHAR, Value: []byte("a")},
		"Type_DATE,    ": {Type: querypb.Type_DATE, Value: []byte("2012-02-24")},
		"Type_DATETIME,": {Type: querypb.Type_DATETIME, Value: []byte("2012-02-24 23:19:43")},
		"Type_DECIMAL, ": {Type: querypb.Type_DECIMAL, Value: []byte("1.00")},
		"Type_ENUM,    ": {Type: querypb.Type_ENUM, Value: []byte("a")},
		"Type_FLOAT32, ": {Type: querypb.Type_FLOAT32, Value: []byte("1.00")},
		"Type_FLOAT64, ": {Type: querypb.Type_FLOAT64, Value: []byte("1.00")},
		"Type_INT8,    ": {Type: querypb.Type_INT8, Value: []byte("1")},
		"Type_INT16,   ": {Type: querypb.Type_INT16, Value: []byte("1")},
		"Type_INT24,   ": {Type: querypb.Type_INT24, Value: []byte("1")},
		"Type_INT32,   ": {Type: querypb.Type_INT32, Value: []byte("1")},
		"Type_INT64,   ": {Type: querypb.Type_INT64, Value: []byte("1")},
		"Type_SET,     ": {Type: querypb.Type_SET, Value: []byte("a")},
		"Type_TEXT,    ": {Type: querypb.Type_TEXT, Value: []byte("a")},
		"Type_TIME,    ": {Type: querypb.Type_TIME, Value: []byte("23:19:43")},
		"Type_TIMESTAMP": {Type: querypb.Type_TIMESTAMP, Value: []byte("2012-02-24 23:19:43")},
		"Type_UINT8,   ": {Type: querypb.Type_UINT8, Value: []byte("1")},
		"Type_UINT16,  ": {Type: querypb.Type_UINT16, Value: []byte("1")},
		"Type_UINT24,  ": {Type: querypb.Type_UINT24, Value: []byte("1")},
		"Type_UINT32,  ": {Type: querypb.Type_UINT32, Value: []byte("1")},
		"Type_UINT64,  ": {Type: querypb.Type_UINT64, Value: []byte("1")},
		"Type_VARBINARY": {Type: querypb.Type_VARBINARY, Value: []byte("a")},
		"Type_VARCHAR, ": {Type: querypb.Type_VARCHAR, Value: []byte("a")},
		"Type_YEAR,    ": {Type: querypb.Type_YEAR, Value: []byte("1")},
		"Type_TUPLE,1  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_FLOAT64, Value: []byte("1")}, {Type: querypb.Type_FLOAT64, Value: []byte("2")}}},
		"Type_TUPLE,2  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_INT64, Value: []byte("1")}, {Type: querypb.Type_INT64, Value: []byte("2")}}},
		"Type_TUPLE,3  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_UINT64, Value: []byte("1")}, {Type: querypb.Type_UINT64, Value: []byte("2")}}},
		"Type_TUPLE,4  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_VARBINARY, Value: []byte("aa")}, {Type: querypb.Type_VARBINARY, Value: []byte("bb")}}},
		"Type_TUPLE,5  ": {Type: querypb.Type_TUPLE, Values: []*querypb.Value{{Type: querypb.Type_VARBINARY, Value: []byte("aa")}, {Type: querypb.Type_INT64, Value: []byte("1")}}},
	}
	fullBindParams := true
	remoteAddr, username := stats.RemoteAddrUsername()
	*streamlog.QueryLogFormat = streamlog.QueryLogFormatJSON

	b.RunParallel(func(pb *testing.PB) {
		for pb.Next() {
			var w bytes.Buffer
			formattedBindVars := sqltypes.FormatBindVariables(
				stats.BindVariables,
				fullBindParams,
				*streamlog.QueryLogFormat == streamlog.QueryLogFormatJSON,
			)

			var fmtString string
			switch *streamlog.QueryLogFormat {
			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%q\t%t\t%q\t\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, \"Keyspace\": %q, \"Table\": %q, \"TabletType\": %q, \"InTransaction\": %t, \"SessionUUID\": %q}\n"
			}

			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.Keyspace,
				stats.Table,
				stats.TabletType,
				stats.InTransaction,
				stats.SessionUUID,
			)
		}
	})

}

// new
BenchmarkLogStatsFormat-10    	  361864	      3034 ns/op	    2594 B/op	      19 allocs/op
// old
BenchmarkLogStatsFormat-10    	  180460	      6335 ns/op	    9026 B/op	     113 allocs/op

Basically, only JSON string values add allocations. Tuples do not.

Signed-off-by: Vilius Okockis <[email protected]>

github-actions · 2024-05-18T01:28:54Z

This PR is being marked as stale because it has been open for 30 days with no activity. To rectify, you may do any of the following:

Push additional commits to the associated branch.
Remove the stale label.
Add a comment indicating why it is not stale.

If no action is taken within 7 days, this PR will be closed.

github-actions · 2024-07-21T01:31:47Z

This PR is being marked as stale because it has been open for 30 days with no activity. To rectify, you may do any of the following:

Push additional commits to the associated branch.
Remove the stale label.
Add a comment indicating why it is not stale.

If no action is taken within 7 days, this PR will be closed.

github-actions · 2024-07-28T01:32:04Z

This PR was closed because it has been stale for 7 days with no activity.

timvaillancourt added 2 commits February 16, 2024 12:29

querylog: json format version 2

2fb06a7

Signed-off-by: Tim Vaillancourt <[email protected]>

Add NewBindVariables helper

fe608ba

Signed-off-by: Tim Vaillancourt <[email protected]>

github-actions bot added this to the v20.0.0 milestone Feb 16, 2024

timvaillancourt added 2 commits February 16, 2024 23:21

Redact bind var value only

8f63ad5

Signed-off-by: Tim Vaillancourt <[email protected]>

gofmt

6d86698

Signed-off-by: Tim Vaillancourt <[email protected]>

Fix vtcombo e2e test

150727c

Signed-off-by: Tim Vaillancourt <[email protected]>

DeathBorn approved these changes Feb 17, 2024

View reviewed changes

fix copylocks linter err

4246773

Signed-off-by: Tim Vaillancourt <[email protected]>

timvaillancourt marked this pull request as ready for review February 20, 2024 00:19

timvaillancourt requested review from harshit-gangal, systay, shlomi-noach, rohit-nayak-ps, frouioui, GuptaManan100 and deepthi as code owners February 20, 2024 00:19

github-actions bot added the Stale Marks PRs as stale after a period of inactivity, which are then closed after a grace period. label Mar 21, 2024

github-actions bot removed the Stale Marks PRs as stale after a period of inactivity, which are then closed after a grace period. label Mar 22, 2024

deepthi mentioned this pull request Mar 29, 2024

logstats: do not allocate memory while logging #15539

Merged

5 tasks

deepthi requested review from mdlayher and removed request for shlomi-noach and rohit-nayak-ps March 29, 2024 01:13

GuptaManan100 reviewed Mar 29, 2024

View reviewed changes

mdlayher reviewed Mar 29, 2024

View reviewed changes

DeathBorn added a commit to vinted/vitess that referenced this pull request Apr 16, 2024

base64 encode bindvar strings in json, inspired by vitessio#15271

65b4bd9

Signed-off-by: Vilius Okockis <[email protected]>

DeathBorn added a commit to vinted/vitess that referenced this pull request Apr 23, 2024

base64 encode bindvar strings in json, inspired by vitessio#15271

8dd70e0

Signed-off-by: Vilius Okockis <[email protected]>

github-actions bot added the Stale Marks PRs as stale after a period of inactivity, which are then closed after a grace period. label May 18, 2024

timvaillancourt removed the Stale Marks PRs as stale after a period of inactivity, which are then closed after a grace period. label May 21, 2024

timvaillancourt added Component: VTGate Component: VTTablet labels May 29, 2024

frouioui modified the milestones: v20.0.0, v21.0.0 Jun 20, 2024

github-actions bot added the Stale Marks PRs as stale after a period of inactivity, which are then closed after a grace period. label Jul 21, 2024

github-actions bot closed this Jul 28, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`querylog`: json format version 2 #15271

`querylog`: json format version 2 #15271

timvaillancourt commented Feb 16, 2024 •

edited

Loading

vitess-bot bot commented Feb 16, 2024

codecov bot commented Feb 16, 2024 •

edited

Loading

github-actions bot commented Mar 21, 2024

timvaillancourt commented Mar 21, 2024 •

edited

Loading

GuptaManan100 left a comment

mdlayher left a comment

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

mdlayher Mar 29, 2024

vmg commented Apr 1, 2024

timvaillancourt commented Apr 10, 2024 •

edited

Loading

DeathBorn commented Apr 17, 2024

DeathBorn commented Apr 17, 2024

github-actions bot commented May 18, 2024

github-actions bot commented Jul 21, 2024

github-actions bot commented Jul 28, 2024

	values := make([]*querypb.Value, len(vals))
	values := make([]*querypb.Value, 0, len(vals))

querylog: json format version 2 #15271

querylog: json format version 2 #15271

Conversation

timvaillancourt commented Feb 16, 2024 • edited Loading

Description

Related Issue(s)

Checklist

Deployment Notes

vitess-bot bot commented Feb 16, 2024

Review Checklist

General

Tests

Documentation

New flags

If a workflow is added or modified:

Backward compatibility

codecov bot commented Feb 16, 2024 • edited Loading

Codecov Report

github-actions bot commented Mar 21, 2024

timvaillancourt commented Mar 21, 2024 • edited Loading

GuptaManan100 left a comment

Choose a reason for hiding this comment

mdlayher left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vmg commented Apr 1, 2024

timvaillancourt commented Apr 10, 2024 • edited Loading

DeathBorn commented Apr 17, 2024

DeathBorn commented Apr 17, 2024

github-actions bot commented May 18, 2024

github-actions bot commented Jul 21, 2024

github-actions bot commented Jul 28, 2024

`querylog`: json format version 2 #15271

`querylog`: json format version 2 #15271

timvaillancourt commented Feb 16, 2024 •

edited

Loading

codecov bot commented Feb 16, 2024 •

edited

Loading

timvaillancourt commented Mar 21, 2024 •

edited

Loading

timvaillancourt commented Apr 10, 2024 •

edited

Loading