Merge #147682

147682: sql: increase observability of automatic statement retries r=yuzefovich a=michae2

In #107044 we added statement-level automatic retries to the conn executor. These retries are used under Read Committed isolation to try to prevent retryable errors from escaping to the application.

This PR adds more observability to statement-level retries, in some cases bringing it up to par with transaction-level retries. See individual commits for details.

Informs: #145377

Release note: None

Co-authored-by: Michael Erickson <[email protected]>

Author: craig[bot]

docs/generated/metrics/metrics.yaml

@@ -8823,6 +8823,22 @@ layers:
       unit: COUNT
       aggregation: AVG
       derivative: NON_NEGATIVE_DERIVATIVE
+    - name: sql.statements.auto_retry.count
+      exported_name: sql_statements_auto_retry_count
+      description: Number of SQL statement automatic retries
+      y_axis_label: SQL Statements
+      type: COUNTER
+      unit: COUNT
+      aggregation: AVG
+      derivative: NON_NEGATIVE_DERIVATIVE
+    - name: sql.statements.auto_retry.count.internal
+      exported_name: sql_statements_auto_retry_count_internal
+      description: Number of SQL statement automatic retries (internal queries)
+      y_axis_label: SQL Internal Statements
+      type: COUNTER
+      unit: COUNT
+      aggregation: AVG
+      derivative: NON_NEGATIVE_DERIVATIVE
     - name: sql.stats.activity.update.latency
       exported_name: sql_stats_activity_update_latency
       description: The latency of updates made by the SQL activity updater job. Includes failed update attempts
@@ -8991,6 +9007,22 @@ layers:
       unit: COUNT
       aggregation: AVG
       derivative: NON_NEGATIVE_DERIVATIVE
+    - name: sql.txn.auto_retry.count
+      exported_name: sql_txn_auto_retry_count
+      description: Number of SQL transaction automatic retries
+      y_axis_label: SQL Transactions
+      type: COUNTER
+      unit: COUNT
+      aggregation: AVG
+      derivative: NON_NEGATIVE_DERIVATIVE
+    - name: sql.txn.auto_retry.count.internal
+      exported_name: sql_txn_auto_retry_count_internal
+      description: Number of SQL transaction automatic retries (internal queries)
+      y_axis_label: SQL Internal Statements
+      type: COUNTER
+      unit: COUNT
+      aggregation: AVG
+      derivative: NON_NEGATIVE_DERIVATIVE
     - name: sql.txn.begin.started.count
       exported_name: sql_txn_begin_started_count
       description: Number of SQL transaction BEGIN statements started

pkg/ccl/kvccl/kvfollowerreadsccl/testdata/boundedstaleness/single_row

@@ -245,24 +245,26 @@ query idx=2
 SELECT * FROM t2 AS OF SYSTEM TIME with_min_timestamp(now() - '10s', true) WHERE pk = 2
 ----
 pq: referenced descriptor ID 105: looking up ID 105: descriptor not found
-events (7 found):
+events (8 found):
  * event 1: colbatchscan trace on node_idx 2: local read
  * event 2: transaction retry on node_idx: 2
  * event 3: colbatchscan trace on node_idx 2: local read
  * event 4: transaction retry on node_idx: 2
  * event 5: colbatchscan trace on node_idx 2: local read
  * event 6: transaction retry on node_idx: 2
  * event 7: colbatchscan trace on node_idx 2: local read
+ * event 8: transaction retry on node_idx: 2
 
 query idx=2
 SELECT * FROM t2 AS OF SYSTEM TIME with_min_timestamp(now() - '10s', true) WHERE pk = 2
 ----
 pq: referenced descriptor ID 105: looking up ID 105: descriptor not found
-events (7 found):
+events (8 found):
  * event 1: colbatchscan trace on node_idx 2: local read
  * event 2: transaction retry on node_idx: 2
  * event 3: colbatchscan trace on node_idx 2: local read
  * event 4: transaction retry on node_idx: 2
  * event 5: colbatchscan trace on node_idx 2: local read
  * event 6: transaction retry on node_idx: 2
  * event 7: colbatchscan trace on node_idx 2: local read
+ * event 8: transaction retry on node_idx: 2

pkg/ccl/logictestccl/testdata/logic_test/txn_retry

@@ -0,0 +1,92 @@
+# Test that automatic transaction retries and automatic statement retries are
+# counted separately.
+
+statement ok
+SET max_retries_for_read_committed = 5
+
+statement ok
+SET tracing = on
+
+statement ok
+BEGIN ISOLATION LEVEL READ COMMITTED
+
+# There's currently some quirky behavior for the first statement of a read-
+# committed transaction: it is subject to both transaction retries and statement
+# retries. We can see this if we force more than max_retries_for_read_committed
+# number of retries for the first statement.
+
+query I
+SELECT crdb_internal.force_retry(7)
+----
+0
+
+statement ok
+SET tracing = off
+
+# We use transaction retry count + statement retry count to decide if we have
+# retried enough. We don't currently remember statement retry counts across
+# transaction retries, so we end up retrying 17 times here instead of 7.
+
+query T nosort
+SELECT message FROM [SHOW TRACE FOR SESSION] WHERE message LIKE '%executing after % retries%'
+----
+executing after 1 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 2 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 3 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 4 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 5 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 1 transaction retries, last retry reason: read committed retry limit exceeded; set by max_retries_for_read_committed=5: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 1 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 2 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 3 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 4 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 5 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 2 transaction retries, last retry reason: read committed retry limit exceeded; set by max_retries_for_read_committed=5: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 1 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 2 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 3 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 4 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 5 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+
+statement ok
+SET tracing = on
+
+query I
+SELECT crdb_internal.force_retry(3)
+----
+0
+
+statement ok
+SET tracing = off
+
+# We use transaction retry count + statement retry count to decide if we have
+# retried enough. We don't currently remember which statements participated in
+# previous transaction retries, so we end up retrying 1 time here instead of 3.
+
+query T nosort
+SELECT message FROM [SHOW TRACE FOR SESSION] WHERE message LIKE '%executing after % retries%'
+----
+executing after 2 transaction retries, last retry reason: read committed retry limit exceeded; set by max_retries_for_read_committed=5: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+executing after 1 statement retries, last retry reason: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+
+statement ok
+SET tracing = on
+
+query I
+SELECT 0
+----
+0
+
+statement ok
+SET tracing = off
+
+# By the time we get to the last statement, the transaction retry count hasn't
+# been affected by any of the statement retries, showing that it is separate.
+
+query T nosort
+SELECT message FROM [SHOW TRACE FOR SESSION] WHERE message LIKE '%executing after % retries%'
+----
+executing after 2 transaction retries, last retry reason: read committed retry limit exceeded; set by max_retries_for_read_committed=5: TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
+
+statement ok
+COMMIT

pkg/ccl/logictestccl/tests/3node-tenant/generated_test.go

@@ -12,7 +12,7 @@ go_test(
         "//build/toolchains:is_heavy": {"test.Pool": "heavy"},
         "//conditions:default": {"test.Pool": "large"},
     }),
-    shard_count = 33,
+    shard_count = 34,
     tags = ["cpu:2"],
     deps = [
         "//pkg/base",

pkg/ccl/logictestccl/tests/fakedist-disk/BUILD.bazel

@@ -12,7 +12,7 @@ go_test(
         "//build/toolchains:is_heavy": {"test.Pool": "heavy"},
         "//conditions:default": {"test.Pool": "large"},
     }),
-    shard_count = 33,
+    shard_count = 34,
     tags = ["cpu:2"],
     deps = [
         "//pkg/base",

pkg/ccl/logictestccl/tests/fakedist-disk/generated_test.go

@@ -12,7 +12,7 @@ go_test(
         "//build/toolchains:is_heavy": {"test.Pool": "heavy"},
         "//conditions:default": {"test.Pool": "large"},
     }),
-    shard_count = 34,
+    shard_count = 35,
     tags = ["cpu:2"],
     deps = [
         "//pkg/base",