vtgate: metrics for prepared stmts (#12141)

* go/vt/vtgate: metrics for prepare statements Signed-off-by: Max Englander <max@planetscale.com> * docs/releasenotes: v16 metrics for prepare statements Signed-off-by: Max Englander <max@planetscale.com> * move to v17 Signed-off-by: Max Englander <max@planetscale.com> * v16 => v17 Signed-off-by: Max Englander <max@planetscale.com> * remove merge cruft Signed-off-by: Max Englander <max@planetscale.com> * pr feedback: -breaking +bug +tests Signed-off-by: Max Englander <max@planetscale.com> * fix tests Signed-off-by: Max Englander <max@planetscale.com> * re-org Signed-off-by: Max Englander <max@planetscale.com> * Update doc/releasenotes/17_0_0_summary.md Co-authored-by: Deepthi Sigireddi <deepthi.sigireddi@gmail.com> Signed-off-by: Max Englander <max.englander@gmail.com> --------- Signed-off-by: Max Englander <max@planetscale.com> Signed-off-by: Max Englander <max.englander@gmail.com> Co-authored-by: Deepthi Sigireddi <deepthi.sigireddi@gmail.com>
vitessio · Mar 6, 2023 · b259fe1 · b259fe1
1 parent ef28c13
commit b259fe1
Show file tree

Hide file tree

Showing 3 changed files with 151 additions and 9 deletions.
diff --git a/doc/releasenotes/17_0_0_summary.md b/doc/releasenotes/17_0_0_summary.md
@@ -4,12 +4,13 @@
 
 - **[Major Changes](#major-changes)**
   - **[Breaking Changes](#breaking-changes)**
-    - [Deprecated Stats](#deprecated-stats)
+    - [Dedicated stats for VTGate Prepare operations](#dedicated-vtgate-prepare-stats)
   - **[New command line flags and behavior](#new-flag)**
     - [Builtin backup: read buffering flags](#builtin-backup-read-buffering-flags)
   - **[New stats](#new-stats)**
     - [Detailed backup and restore stats](#detailed-backup-and-restore-stats)
   - **[Deprecations and Deletions](#deprecations-and-deletions)**
+    - [Deprecated Stats](#deprecated-stats)
 
 ## <a id="major-changes"/> Major Changes
 
@@ -19,14 +20,30 @@
 
 When using TLS with `vtgr`, we now default to TLS 1.2 if no other explicit version is configured. Configuration flags are provided to explicitly configure the minimum TLS version to be used. 
 
-#### <a id="deprecated-stats"/>Deprecated Stats
+#### <a id="dedicated-vtgate-prepare-stats"> Dedicated stats for VTGate Prepare operations
 
-These stats are deprecated in v17.
+Prior to v17 Vitess incorrectly combined stats for VTGate Execute and Prepare operations under a single stats key (`Execute`). In v17 Execute and Prepare operations generate stats under independent stats keys.
 
-| Deprecated stat | Supported alternatives |
-|-|-|
-| `backup_duration_seconds` | `BackupDurationNanoseconds` |
-| `restore_duration_seconds` | `RestoreDurationNanoseconds` |
+Here is a (condensed) example of stats output:
+
+```
+{
+  "VtgateApi": {
+    "Histograms": {
+      "Execute.src.primary": {
+        "500000": 5
+      },
+      "Prepare.src.primary": {
+        "100000000": 0
+      }
+    }
+  },
+  "VtgateApiErrorCounts": {
+    "Execute.src.primary.INVALID_ARGUMENT": 3,
+    "Execute.src.primary.ALREADY_EXISTS": 1
+  }
+}
+```
 
 ### <a id="new-flag"/> New command line flags and behavior
 
@@ -172,3 +189,12 @@ Some notes to help understand these metrics:
 * Auto-population of DDL revert actions and tables at execution-time has been removed. This is now handled entirely at enqueue-time.
 * Backwards-compatibility for failed migrations without a `completed_timestamp` has been removed (see https://github.com/vitessio/vitess/issues/8499).
 * The deprecated `Key`, `Name`, `Up`, and `TabletExternallyReparentedTimestamp` fields were removed from the JSON representation of `TabletHealth` structures.
+
+### <a id="deprecated-stats"/>Deprecated Stats
+
+These stats are deprecated in v17.
+
+| Deprecated stat | Supported alternatives |
+|-|-|
+| `backup_duration_seconds` | `BackupDurationNanoseconds` |
+| `restore_duration_seconds` | `RestoreDurationNanoseconds` |
diff --git a/go/vt/vtgate/vtgate.go b/go/vt/vtgate/vtgate.go
@@ -207,6 +207,7 @@ type VTGate struct {
 
 	// the throttled loggers for all errors, one per API entry
 	logExecute       *logutil.ThrottledLogger
+	logPrepare       *logutil.ThrottledLogger
 	logStreamExecute *logutil.ThrottledLogger
 }
 
@@ -315,6 +316,7 @@ func Init(
 			[]string{"Operation", "Keyspace", "DbType"}),
 
 		logExecute:       logutil.NewThrottledLogger("Execute", 5*time.Second),
+		logPrepare:       logutil.NewThrottledLogger("Prepare", 5*time.Second),
 		logStreamExecute: logutil.NewThrottledLogger("StreamExecute", 5*time.Second),
 	}
 
@@ -533,7 +535,7 @@ func (vtg *VTGate) ResolveTransaction(ctx context.Context, dtid string) error {
 func (vtg *VTGate) Prepare(ctx context.Context, session *vtgatepb.Session, sql string, bindVariables map[string]*querypb.BindVariable) (newSession *vtgatepb.Session, fld []*querypb.Field, err error) {
 	// In this context, we don't care if we can't fully parse destination
 	destKeyspace, destTabletType, _, _ := vtg.executor.ParseDestinationTarget(session.TargetString)
-	statsKey := []string{"Execute", destKeyspace, topoproto.TabletTypeLString(destTabletType)}
+	statsKey := []string{"Prepare", destKeyspace, topoproto.TabletTypeLString(destTabletType)}
 	defer vtg.timings.Record(statsKey, time.Now())
 
 	if bvErr := sqltypes.ValidateBindVariables(bindVariables); bvErr != nil {
@@ -552,7 +554,7 @@ handleError:
 		"BindVariables": bindVariables,
 		"Session":       session,
 	}
-	err = recordAndAnnotateError(err, statsKey, query, vtg.logExecute)
+	err = recordAndAnnotateError(err, statsKey, query, vtg.logPrepare)
 	return session, nil, err
 }
 

diff --git a/go/vt/vtgate/vtgate_test.go b/go/vt/vtgate/vtgate_test.go
@@ -81,6 +81,8 @@ func init() {
 }
 
 func TestVTGateExecute(t *testing.T) {
+	counts := rpcVTGate.timings.Timings.Counts()
+
 	createSandbox(KsTestUnsharded)
 	hcVTGateTest.Reset()
 	sbc := hcVTGateTest.AddTestTablet("aa", "1.1.1.1", 1001, KsTestUnsharded, "0", topodatapb.TabletType_PRIMARY, true, 1, nil)
@@ -97,12 +99,124 @@ func TestVTGateExecute(t *testing.T) {
 	if err != nil {
 		t.Errorf("want nil, got %v", err)
 	}
+
 	want := *sandboxconn.SingleRowResult
 	want.StatusFlags = 0 // VTGate result set does not contain status flags in sqltypes.Result
 	utils.MustMatch(t, &want, qr)
 	if !proto.Equal(sbc.Options[0], executeOptions) {
 		t.Errorf("got ExecuteOptions \n%+v, want \n%+v", sbc.Options[0], executeOptions)
 	}
+
+	newCounts := rpcVTGate.timings.Timings.Counts()
+	require.Contains(t, newCounts, "All")
+	require.Equal(t, counts["All"]+1, newCounts["All"])
+	require.Contains(t, newCounts, "Execute..primary")
+	require.Equal(t, counts["Execute..primary"]+1, newCounts["Execute..primary"])
+
+	for k, v := range newCounts {
+		if strings.HasPrefix(k, "Prepare") {
+			require.Equal(t, v, counts[k])
+		}
+	}
+}
+
+func TestVTGateExecuteError(t *testing.T) {
+	counts := errorCounts.Counts()
+
+	createSandbox(KsTestUnsharded)
+	hcVTGateTest.Reset()
+	hcVTGateTest.AddTestTablet("aa", "1.1.1.1", 1001, KsTestUnsharded, "0", topodatapb.TabletType_PRIMARY, true, 1, nil)
+	_, qr, err := rpcVTGate.Execute(
+		context.Background(),
+		&vtgatepb.Session{
+			Autocommit:   true,
+			TargetString: "@primary",
+			Options:      executeOptions,
+		},
+		"bad select id from t1",
+		nil,
+	)
+	require.Error(t, err)
+	require.Nil(t, qr)
+
+	newCounts := errorCounts.Counts()
+	require.Contains(t, newCounts, "Execute..primary.INVALID_ARGUMENT")
+	require.Equal(t, counts["Execute..primary.INVALID_ARGUMENT"]+1, newCounts["Execute..primary.INVALID_ARGUMENT"])
+
+	for k, v := range newCounts {
+		if strings.HasPrefix(k, "Prepare") {
+			require.Equal(t, v, counts[k])
+		}
+	}
+}
+
+func TestVTGatePrepare(t *testing.T) {
+	counts := rpcVTGate.timings.Timings.Counts()
+
+	createSandbox(KsTestUnsharded)
+	hcVTGateTest.Reset()
+	sbc := hcVTGateTest.AddTestTablet("aa", "1.1.1.1", 1001, KsTestUnsharded, "0", topodatapb.TabletType_PRIMARY, true, 1, nil)
+	_, qr, err := rpcVTGate.Prepare(
+		context.Background(),
+		&vtgatepb.Session{
+			Autocommit:   true,
+			TargetString: "@primary",
+			Options:      executeOptions,
+		},
+		"select id from t1",
+		nil,
+	)
+	if err != nil {
+		t.Errorf("want nil, got %v", err)
+	}
+
+	want := sandboxconn.SingleRowResult.Fields
+	utils.MustMatch(t, want, qr)
+	if !proto.Equal(sbc.Options[0], executeOptions) {
+		t.Errorf("got ExecuteOptions \n%+v, want \n%+v", sbc.Options[0], executeOptions)
+	}
+
+	newCounts := rpcVTGate.timings.Timings.Counts()
+	require.Contains(t, newCounts, "All")
+	require.Equal(t, counts["All"]+1, newCounts["All"])
+	require.Contains(t, newCounts, "Prepare..primary")
+	require.Equal(t, counts["Prepare..primary"]+1, newCounts["Prepare..primary"])
+
+	for k, v := range newCounts {
+		if strings.HasPrefix(k, "Execute") {
+			require.Equal(t, v, counts[k])
+		}
+	}
+}
+
+func TestVTGatePrepareError(t *testing.T) {
+	counts := errorCounts.Counts()
+
+	createSandbox(KsTestUnsharded)
+	hcVTGateTest.Reset()
+	hcVTGateTest.AddTestTablet("aa", "1.1.1.1", 1001, KsTestUnsharded, "0", topodatapb.TabletType_PRIMARY, true, 1, nil)
+	_, qr, err := rpcVTGate.Prepare(
+		context.Background(),
+		&vtgatepb.Session{
+			Autocommit:   true,
+			TargetString: "@primary",
+			Options:      executeOptions,
+		},
+		"bad select id from t1",
+		nil,
+	)
+	require.Error(t, err)
+	require.Nil(t, qr)
+
+	newCounts := errorCounts.Counts()
+	require.Contains(t, newCounts, "Prepare..primary.INTERNAL")
+	require.Equal(t, counts["Prepare..primary.INTERNAL"]+1, newCounts["Prepare..primary.INTERNAL"])
+
+	for k, v := range newCounts {
+		if strings.HasPrefix(k, "Execute") {
+			require.Equal(t, v, counts[k])
+		}
+	}
 }
 
 func TestVTGateExecuteWithKeyspaceShard(t *testing.T) {