[yugabyte#24431] YSQL: Supplement read restart error with more info

Summary:
### Motivation

Read restart errors are a common occurence in YugabyteDB.

Mitigation strategy varies case-by-case. Well known approaches:

1. Use READ COMMITTED isolation level. A popular mitigation strategy.
2. Increase ysql_output_buffer_size. This is applicable for large SELECTs that have a low read restart rate.
3. Use the deferrable mode. This is for background tasks that scan a lot of rows.
4. Leverage time sync service. Best option but still early.

However, these mitigitation strategies do not always work. Such cases require addressing the underlying problem. Currently, the logs lack sufficient detail, leading to speculation rather than concrete diagnosis.

### Examples

#### Running CREATE/DROP TEMP TABLE concurrently results in a read restart error

```
2025-04-04 01:57:32.353 UTC [587443] ERROR:  Restart read required at:  read: { days: 20182 time: 01:57:32.350502 } local_limit: { days: 20182 time: 01:57:32.350502 } global_limit: <min> in_txn_limit: <max> serial_no: 0 } (yb_max_query_layer_retries set to 0 are exhausted)
```

Users do not expect this error because TEMP TABLEs  are local to each pg backend. Moreover, increasing ysql_output_buffer_size does not mitigate the error here because read restart errors on DDLs cannot be retried yet. That said, users find it helpful to understand the root cause of the error. After this revision, the log becomes

```
2025-04-04 01:57:32.353 UTC [587443] DETAIL:  restart_read_time: { read: { days: 20182 time: 01:57:32.350502 } local_limit: { days: 20182 time: 01:57:32.350502 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }, original_read_time: { read: { days: 20182 time: 01:57:32.096749 } local_limit: { days: 20182 time: 01:57:32.098414 } global_limit: { days: 20182 time: 01:57:32.596749 } in_txn_limit: <max> serial_no: 0 }, table: template1.pg_yb_invalidation_messages [ysql_schema=pg_catalog] [00000001000030008001000000001f90], tablet: 00000000000000000000000000000000, leader_uuid: f1ac558309244cbab385761b531980f0, key: SubDocKey(DocKey(CoTableId=901f0000-0000-0180-0030-000001000000, [], [13515, 10]), [SystemColumnId(0)]), start_time: 2025-04-04 01:57:32.094965+00
```

**Cause:** The read restart error is returned when accessing the `pg_yb_invalidation_messages` table in the above example.
**Mitigation:** Avoid creating TEMP TABLEs from mutliple sessions concurrently. Note: The issue is fixed by table-level locking.

#### CREATE INDEX NONCONCURRENTLY

CREATE INDEX NONCONCURRENTLY accesses both the user table as well as syscatalog. How can the user identify whether the read restart error occurred due to a concurrent DDL or DML?

```
[ts-1] 2025-04-04 04:25:47.694 UTC [665450] DETAIL:  restart_read_time: { read: { days: 20182 time: 04:25:47.512991 } local_limit: { days: 20182 time: 04:25:47.512991 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }, original_read_time: { read: { days: 20182 time: 04:25:47.012991 } local_limit: { days: 20182 time: 04:25:47.512991 } global_limit: { days: 20182 time: 04:25:47.512991 } in_txn_limit: <max> serial_no: 0 }, table: yugabyte.test_table [ysql_schema=public] [000034cb000030008000000000004000], tablet: bf9d2bf8908b43d4b8b5ff75b169bf11, leader_uuid: 6d60cea932ca41498fee5ad07c375d18, key: SubDocKey(DocKey(0x0a73, [5], []), [ColumnId(1)])
```

**Cause:** In the above log, the error occurs on the user table.
**Mitigation:** Stop concurrent writes when creating the INDEX.

The read restart can also be on a catalog table. Example:

```
[ts-1] 2025-04-04 02:17:48.392 UTC [592811] DETAIL:  restart_read_time: { read: { days: 20182 time: 02:17:48.326938 } local_limit: { days: 20182 time: 02:17:48.326938 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }, original_read_time: { read: { days: 20182 time: 02:17:48.023542 } local_limit: { days: 20182 time: 02:17:48.024082 } global_limit: { days: 20182 time: 02:17:48.523542 } in_txn_limit: <max> serial_no: 0 }, table: yugabyte.pg_attribute [ysql_schema=pg_catalog] [000034cb0000300080010000000004e1], tablet: 00000000000000000000000000000000, leader_uuid: e941d4ee43bc40a8b4303eab317f52fd, key: SubDocKey(DocKey(CoTableId=e1040000-0000-0180-0030-0000cb340000, [], [16384, 5]), []), start_time: 2025-04-04 02:17:48.022154+00
[ts-1] 2025-04-04 02:17:48.392 UTC [592811] STATEMENT:  CREATE INDEX NONCONCURRENTLY non_concurrent_idx_0 ON test_table(key)
```

#### Read restarts on absent keys

Users sometimes report that they notice read restart errors even though they are no conflicting keys. To better observe such scenarios, print a key on which read restart error occurred. There can be multiple such keys, so we print the first one we encounter.

Here's an example fixed by yugabyte#25214.

Setup

```
CREATE TABLE keys(k1 INT, k2 INT, PRIMARY KEY(k1 ASC, k2 ASC));
INSERT INTO keys(k1, k2) VALUES (1, 1);
```

The following query

```
INSERT INTO keys(k1, k2) VALUES (0, 0), (9, 9) ON CONFLICT DO NOTHING
```

results in a read restart error even though none of 0 or 9 conflict with 1.

```
2025-04-04 17:55:03.013 UTC [955800] DETAIL:  restart_read_time: { read: { days: 20182 time: 17:55:03.012147 } local_limit: { days: 20182 time: 17:55:03.012147 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }, original_read_time: { read: { days: 20182 time: 17:55:02.983152 } local_limit: { days: 20182 time: 17:55:03.483152 } global_limit: { days: 20182 time: 17:55:03.483152 } in_txn_limit: { days: 20182 time: 17:55:03.011777 } serial_no: 0 }, table: yugabyte.keys [ysql_schema=public] [000034cb000030008000000000004000], tablet: 2a19ede71f7e4389b1ca682e87318b32, leader_uuid: 7010bbec8ec94110b5e2316bca5319f4, key: SubDocKey(DocKey([], [1, 1]), [SystemColumnId(0)]), start_time: 2025-04-04 17:55:03.010743+00
```

This helps us understand where the read restart error occurred. It occurs on key = (1, 1), not relevant to the INSERT ON CONFLICT statement. The key field helps diagnose such scenarios.

**Mitigation:** See 1bcb09c for the fix.

#### Local Limit Fixes

Commits d67ba12 and 02ced43 fix some bugs with the local llimit mechanism. Identifying the value of local limit when the issue occurs is fairly straightforward. The error message has local limit.

```
[ts-1] 2025-04-04 02:17:48.392 UTC [592811] DETAIL:  restart_read_time: { read: { days: 20182 time: 02:17:48.326938 } local_limit: { days: 20182 time: 02:17:48.326938 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }, original_read_time: { read: { days: 20182 time: 02:17:48.023542 } local_limit: { days: 20182 time: 02:17:48.024082 } global_limit: { days: 20182 time: 02:17:48.523542 } in_txn_limit: <max> serial_no: 0 }, table: yugabyte.pg_attribute [ysql_schema=pg_catalog] [000034cb0000300080010000000004e1], tablet: 00000000000000000000000000000000, leader_uuid: e941d4ee43bc40a8b4303eab317f52fd, key: SubDocKey(DocKey(CoTableId=e1040000-0000-0180-0030-0000cb340000, [], [16384, 5]), []), start_time: 2025-04-04 02:17:48.022154+00
[ts-1] 2025-04-04 02:17:48.392 UTC [592811] STATEMENT:  CREATE INDEX NONCONCURRENTLY non_concurrent_idx_0 ON test_table(key)
```

#### pg_partman faces read restart errors

pg_partman faces a read restart error on max query

```
ERROR:  Restart read required at: { read: { physical: 1730622229379200 } local_limit: { physical: 1730622229379200 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
CONTEXT: SQL statement "SELECT max(id)::text FROM public.t1_p100000"
```

**Cause:** This is because there is no range index on the tablet 1_p100000 to retrieve the max value efficiently using the index.

A log such as

```
2025-04-04 18:55:31.936 UTC [963409] DETAIL:  restart_read_time: { read: { days: 20182 time: 18:55:31.934321 } local_limit: { days: 20182 time: 18:55:31.934321 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }, original_read_time: { days: 20182 time: 18:55:31.738805 }, table: yugabyte.tokens_idx [ysql_schema=public] [000034cb000030008000000000004003], tablet: {tokens_idx_tablet_id1}, leader_uuid: {ts2_peer_id}, key: SubDocKey(DocKey([], [300, "G%\xf8S\xde\xb0h\xe6)\xa3G0\x96\xae\x9e9\xf7r\xbe\xc3\x00\x00!!"]), [SystemColumnId(0)]), start_time: 2025-04-04 18:55:31.933012+00
```

informs us the table on which the read restart error occurred. If the table is an index such as tokens_idx, the query is using an index scan.

**Upgrade/Rollback safety:**

Adds a new key restart_read_key to tserver.proto. The key is marked optional. When absent an empty value is printed in its stead.
Jira: DB-13338

Test Plan:
Jenkins

Backport-through: 2024.2

Reviewers: smishra, pjain

Reviewed By: pjain

Subscribers: yql

Differential Revision: https://phorge.dev.yugabyte.com/D42883

Author: pao214

docs/content/preview/architecture/transactions/read-restart-error.md

@@ -24,7 +24,7 @@ Read restart errors are raised to maintain the _read-after-commit-visibility_ gu
 YugabyteDB doesn't require atomic clocks, but instead allows a configurable setting for maximum clock skew. Time synchronization protocols such as NTP synchronize commodity hardware clocks periodically to keep the skew low and bounded. Additionally, YugabyteDB has optimizations to resolve this ambiguity internally with best-effort. However, when it can't resolve the error internally, YugabyteDB outputs a `read restart` error to the external client, similar to the following:
 
 ```output
-ERROR:  Query error: Restart read required at: { read: { physical: 1656351408684482 } local_limit: { physical: 1656351408684482 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
+ERROR:  Query error: Restart read required
 ```
 
 The following scenario describes how clock skew can result in the above mentioned ambiguity around data visibility in detail:

src/postgres/src/backend/utils/error/elog.c

@@ -4624,6 +4624,27 @@ yb_errdetail_from_status(const char *fmt, const size_t nargs, const char **args)
 	return 0;					/* return value does not matter */
 }
 
+int
+yb_errdetail_log_from_status(const char *fmt, const size_t nargs, const char **args)
+{
+	Assert(!IsMultiThreadedMode());
+
+	ErrorData  *edata = &errordata[errordata_stack_depth];
+	MemoryContext oldcontext;
+
+	recursion_depth++;
+	CHECK_STACK_DEPTH();
+	oldcontext = MemoryContextSwitchTo(edata->assoc_context);
+
+	YB_EVALUATE_MESSAGE_FROM_STATUS(edata->domain, detail_log,
+									false /* appendval */ ,
+									true /* translateit */ , nargs, args);
+
+	MemoryContextSwitchTo(oldcontext);
+	recursion_depth--;
+	return 0;					/* return value does not matter */
+}
+
 /*
  * Set the given field to the given value (assumed to be palloc-d) or, if the
  * new value is null, pstrdup the existing value of the field to ensure that

src/postgres/src/backend/utils/misc/pg_yb_utils.c

@@ -857,7 +857,10 @@ void
 GetStatusMsgAndArgumentsByCode(const uint32_t pg_err_code, YbcStatus s,
 							   const char **msg_buf, size_t *msg_nargs,
 							   const char ***msg_args, const char **detail_buf,
-							   size_t *detail_nargs, const char ***detail_args)
+							   size_t *detail_nargs, const char ***detail_args,
+							   const char **detail_log_buf,
+							   size_t *detail_log_nargs,
+							   const char ***detail_log_args)
 {
 	const char *status_msg = YBCMessageAsCString(s);
 	size_t		status_nargs;
@@ -871,6 +874,9 @@ GetStatusMsgAndArgumentsByCode(const uint32_t pg_err_code, YbcStatus s,
 	*detail_buf = NULL;
 	*detail_nargs = 0;
 	*detail_args = NULL;
+	*detail_log_buf = NULL;
+	*detail_log_nargs = 0;
+	*detail_log_args = NULL;
 	elog(DEBUG2, "status_msg=%s pg_err_code=%d", status_msg, pg_err_code);
 
 	switch (pg_err_code)
@@ -891,6 +897,36 @@ GetStatusMsgAndArgumentsByCode(const uint32_t pg_err_code, YbcStatus s,
 			*detail_nargs = status_nargs;
 			*detail_args = status_args;
 			break;
+		case ERRCODE_YB_RESTART_READ:
+			*msg_buf = "Restart read required";
+			*msg_nargs = 0;
+			*msg_args = NULL;
+
+			/*
+			 * Read restart errors occur when writes fall within the uncertianty
+			 * interval [read_time, global_limit).
+			 *
+			 * Moreover, read_time can be less than the current time since it
+			 * is picked as the docdb tablet's safe time as an optimization in
+			 * some cases.
+			 *
+			 * As a consequence, read_time may be lower than the commit time of the
+			 * previous transaction from the same session.
+			 *
+			 * In this case, a read restart error may be issued to move the read
+			 * time past the commit time.
+			 *
+			 * To capture such cases, print the start time of the statement. This
+			 * allows comparison between the start time and the original read time.
+			 */
+			*detail_log_buf = psprintf("%s, stmt_start_time: %s, txn_start_time: %s, iso:%d",
+									   status_msg,
+									   timestamptz_to_str(GetCurrentStatementStartTimestamp()),
+									   timestamptz_to_str(GetCurrentTransactionStartTimestamp()),
+									   XactIsoLevel);
+			*detail_log_nargs = status_nargs;
+			*detail_log_args = status_args;
+			break;
 		case ERRCODE_YB_DEADLOCK:
 			*msg_buf = "deadlock detected";
 			*msg_nargs = 0;

src/postgres/src/include/pg_yb_utils.h

@@ -1160,7 +1160,10 @@ void		GetStatusMsgAndArgumentsByCode(const uint32_t pg_err_code, YbcStatus s,
 										   const char ***msg_args,
 										   const char **detail_buf,
 										   size_t *detail_nargs,
-										   const char ***detail_args);
+										   const char ***detail_args,
+										   const char **detail_log_buf,
+										   size_t *detail_log_nargs,
+										   const char ***detail_log_args);
 
 bool		YbIsBatchedExecution();
 void		YbSetIsBatchedExecution(bool value);
@@ -1201,21 +1204,30 @@ YbOptSplit *YbGetSplitOptions(Relation rel);
 			const char *funcname = YBCStatusFuncname(_status); \
 			const char *msg_buf = NULL; \
 			const char *detail_buf = NULL; \
+			const char *detail_log_buf = NULL; \
 			size_t msg_nargs = 0; \
 			size_t detail_nargs = 0; \
+			size_t detail_log_nargs = 0; \
 			const char **msg_args = NULL; \
 			const char **detail_args = NULL; \
+			const char **detail_log_args = NULL; \
 			GetStatusMsgAndArgumentsByCode(pg_err_code, _status, \
 										   &msg_buf, &msg_nargs, &msg_args, \
 										   &detail_buf, &detail_nargs, \
-										   &detail_args); \
+										   &detail_args, &detail_log_buf, \
+										   &detail_log_nargs, \
+										   &detail_log_args); \
 			YBCFreeStatus(_status); \
 			if (errstart(adjusted_elevel, TEXTDOMAIN)) \
 			{ \
 				Assert(msg_buf); \
 				yb_errmsg_from_status(msg_buf, msg_nargs, msg_args); \
 				if (detail_buf) \
 					yb_errdetail_from_status(detail_buf, detail_nargs, detail_args); \
+				if (detail_log_buf) \
+					yb_errdetail_log_from_status(detail_log_buf, \
+												 detail_log_nargs, \
+												 detail_log_args); \
 				yb_set_pallocd_error_file_and_func(filename, funcname); \
 				errcode(pg_err_code); \
 				errhidecontext(true); \

src/postgres/src/include/utils/elog.h

@@ -508,6 +508,7 @@ extern void yb_errfinish(const char *filename, int lineno, const char *funcname)
 extern int	yb_external_errcode(int sqlerrcode);
 extern int	yb_errmsg_from_status(const char *fmt, const size_t nargs, const char **args);
 extern int	yb_errdetail_from_status(const char *fmt, const size_t nargs, const char **args);
+extern int	yb_errdetail_log_from_status(const char *fmt, const size_t nargs, const char **args);
 extern void yb_set_pallocd_error_file_and_func(const char *filename, const char *funcname);
 extern sigjmp_buf *yb_get_exception_stack(void);
 extern void yb_set_exception_stack(sigjmp_buf *new_sigjmp_buf);

src/yb/client/async_rpc.cc

@@ -471,10 +471,21 @@ bool AsyncRpcBase<Req, Resp>::CommonResponseCheck(const Status& status) {
   auto restart_read_time = ReadHybridTime::FromRestartReadTimePB(resp_);
   if (restart_read_time) {
     auto read_point = batcher_->read_point();
+    auto tablet_id = req_.tablet_id();
+    HybridTime original_read_time;
     if (read_point) {
-      read_point->RestartRequired(req_.tablet_id(), restart_read_time);
+      original_read_time = read_point->GetReadTime(tablet_id).read;
+      read_point->RestartRequired(tablet_id, restart_read_time);
     }
-    Failed(STATUS(TryAgain, Format("Restart read required at: $0", restart_read_time), Slice(),
+    auto leader_uuid = tablet().current_leader_uuid();
+    auto table_name = table()->name().ToString();
+    auto key = resp_.restart_read_key();
+    Failed(STATUS(TryAgain,
+                  Format("restart_read_time: $0, original_read_time: $1"
+                         ", table: $2, tablet: $3, leader_uuid: $4, key: $5",
+                         restart_read_time, original_read_time,
+                         table_name, tablet_id, leader_uuid, key),
+                  Slice(),
                   TransactionError(TransactionErrorCode::kReadRestartRequired)));
     return false;
   }

src/yb/common/common_fwd.h

@@ -32,6 +32,7 @@ class ConstContiguousRow;
 class DocHybridTime;
 class EncodedDocHybridTime;
 class HybridTime;
+struct ReadRestartData;
 class MissingValueProvider;
 class TableProperties;
 class TransactionStatusManager;

src/yb/common/consistent_read_point.cc

@@ -88,7 +88,7 @@ void ConsistentReadPoint::RestartRequired(const TabletId& tablet,
 
 void ConsistentReadPoint::RestartRequiredUnlocked(
     const TabletId& tablet, const ReadHybridTime& restart_time) {
-  DCHECK(read_time_) << "Unexpected restart without a read time set";
+  LOG_IF(DFATAL, !read_time_) << "Unexpected restart without a read time set";
   restart_read_ht_.MakeAtLeast(restart_time.read);
   // We should inherit per-tablet restart time limits before restart, doing it lazily.
   if (restarts_.empty()) {
@@ -199,7 +199,8 @@ void ConsistentReadPoint::SetInTxnLimit(HybridTime value) {
 
 ReadHybridTime ConsistentReadPoint::GetReadTime() const {
   std::lock_guard lock(mutex_);
-  DCHECK_LE(read_time_.read, read_time_.global_limit);
+  LOG_IF(DFATAL, read_time_.read > read_time_.global_limit)
+      << "Read time cannot be higher than the global limit" << read_time_;
   return read_time_;
 }
 

src/yb/common/doc_hybrid_time.h

@@ -205,4 +205,9 @@ inline std::ostream& operator<<(std::ostream& os, const DocHybridTime& ht) {
   return os << ht.ToString();
 }
 
+struct MaxSeenHtData {
+  EncodedDocHybridTime max_seen_ht{DocHybridTime::kMin};
+  std::string max_seen_ht_key;
+};
+
 }  // namespace yb

src/yb/common/hybrid_time.h

@@ -298,4 +298,27 @@ inline HybridTime operator "" _usec_ht(unsigned long long microseconds) { // NOL
 
 using hybrid_time_literals::operator"" _usec_ht;
 
+struct ReadRestartData {
+  HybridTime restart_time;
+  std::string key;
+
+  bool is_valid() const {
+    return restart_time.is_valid();
+  }
+
+  void MakeAtLeast(ReadRestartData rhs) {
+    if (!rhs.restart_time.is_valid()) {
+      return;
+    }
+    if (!restart_time.is_valid() || restart_time < rhs.restart_time) {
+      restart_time = rhs.restart_time;
+      key = rhs.key;
+    }
+  }
+
+  std::string ToString() const {
+    return YB_STRUCT_TO_STRING(restart_time, key);
+  }
+};
+
 }  // namespace yb