Merge #154028 #154162 #154201 #154262

154028: sql: Fix idle latency tracking r=alyshanjahani-crl a=alyshanjahani-crl

Previously idle latencies were not being tracked accurately in two situations.

First, there was massive over counting of idle latencies in transactions that had INSERTs with placeholders (more generally statement that executed a prepare/bind before running). See issue #146116.

In these situations we had missed setting the QueryServiced time for the statements within the transaction, resulting in all the intermediate idle latencies calulating their `waitingSince` from the transaction start time.

The control flow of the conn executor can be difficult to track and through adding print statements, the difference between a transaction with `INSERT INTO ... VALUES (1)` vs `INSERT INTO ... VALUES ($1)` highlighted that setting QueryServiced at the end of the `ExecStmt` case in `execCmd` meant that for the prepare/bind version of the INSERT statements, we never set QueryServiced.

Simple statements:
```
execCmd ExecStmt
execStmtInOpenState INSERT INTO test_idle VALUES (1)
execCmd Setting QueryServiced
execCmd ExecStmt
execStmtInOpenState INSERT INTO test_idle VALUES (1)
execCmd Setting QueryServiced
execCmd ExecStmt
execStmtInOpenState INSERT INTO test_idle VALUES (1)
execCmd Setting QueryServiced
```

Notice how after every `execStmtInOpenState`, the flow returns to `execCmd`. Whereas in the case below, we just flow back into `execStmtInOpenState`.

Prepare/bind statements:
```
prepare statsCollector.Reset
bind statsCollector.Reset
execStmtInOpenState INSERT INTO test_idle VALUES ($1)
prepare statsCollector.Reset
bind statsCollector.Reset
execStmtInOpenState INSERT INTO test_idle VALUES ($1)
prepare statsCollector.Reset
bind statsCollector.Reset
execStmtInOpenState INSERT INTO test_idle VALUES ($1)
```

The second situation in which idle latencies were not tracked correctly was when observer statements were run in between statements in the transaction. This is a situation that occurs when using the `cockroach sql` cli. In this case, idle latencies were severely undercounted because we'd reset the stats collector before running the observer statement, and then when the non observer statement ran and we recorded the statement summary, the idle latency would be calculated from the previous observer statement time.

This commit fixes the first situation by additionally setting QueryServiced after `execStmt`.

This commit fixes the second situation by accumulating idle latencies in between observer statements.

Lastly this commit removes the existing TestSQLStatsIdleLatencies as it evidently had poor coverage and replaces it with TestTransactionLatencies which enforces invariants like:
totalTxnTime >= txnServiceLatency >= txnIdleLatency

p.s debugging session phase times is really tedious and we should consider refactoring.

Fixes: #146116
Release note (bug fix): Fixes discrepencies between idle and service latencies.

154162: sql: fix `COPY` with hidden and inaccessible columns r=mgartner a=mgartner

Fixes #119524

Release note (bug fix): A bug has been fixed that caused panics when
executing `COPY` into a table with hidden columns and expression
indexes. The panic only occurred when the
`expect_and_ignore_not_visible_columns_in_copy` setting was enabled.
This bug has been present since
`expect_and_ignore_not_visible_columns_in_copy` was introduced in
v22.1.0.


154201: external connection: deflake privs test r=jeffswenson a=msbutler

Informs #154141

Release note: none

154262: retry: deflake TestRetryWithMaxDurationAndMaxRetries r=jeffswenson a=jeffswenson

Previously, the time bound for the retry test was quite small. So an overloaded or slow test runner may hit the timeout before the goroutine was scheduled for max retries.

Fixes: #154160
Release note: none

Co-authored-by: Alyshan Jahani <alyshan@cockroachlabs.com>
Co-authored-by: Marcus Gartner <marcus@cockroachlabs.com>
Co-authored-by: Michael Butler <butler@cockroachlabs.com>
Co-authored-by: Jeff Swenson <jeffswenson@betterthannull.com>

Author: 5 people

pkg/ccl/cloudccl/externalconn/testdata/privileges_external_connection

@@ -63,11 +63,11 @@ GRANT DROP ON EXTERNAL CONNECTION "drop-privileged" TO testuser;
 
 # Verify that the privileges exist.
 query-sql
-SELECT * FROM system.privileges
+SELECT username, path, privileges  FROM system.privileges order by user_id
 ----
-root /externalconn/drop-privileged {ALL} {} 1
-root /externalconn/drop-privileged-dup {ALL} {} 1
-testuser /externalconn/drop-privileged {DROP} {} 100
+root /externalconn/drop-privileged {ALL}
+root /externalconn/drop-privileged-dup {ALL}
+testuser /externalconn/drop-privileged {DROP}
 
 exec-sql user=testuser
 DROP EXTERNAL CONNECTION "drop-privileged"
@@ -131,11 +131,11 @@ CREATE EXTERNAL CONNECTION 'not-root' AS 'userfile:///bar'
 
 # Verify that the privileges exist.
 query-sql
-SELECT * FROM system.privileges
+SELECT username, path, privileges FROM system.privileges order by user_id
 ----
-root /externalconn/root {ALL} {} 1
-testuser /externalconn/not-root {ALL} {} 101
-testuser /global/ {EXTERNALCONNECTION} {} 101
+root /externalconn/root {ALL}
+testuser /externalconn/not-root {ALL}
+testuser /global/ {EXTERNALCONNECTION}
 
 exec-sql user=testuser
 BACKUP TABLE foo INTO 'external://not-root'

pkg/sql/conn_executor_exec.go

@@ -135,6 +135,8 @@ func (ex *connExecutor) execStmt(
 	if _, ok := ast.(tree.ObserverStatement); ok {
 		ex.statsCollector.Reset(ex.applicationStats, ex.phaseTimes)
 		err := ex.runObserverStatement(ctx, ast, res)
+		ex.extraTxnState.idleLatency += ex.phaseTimes.GetIdleLatency(ex.statsCollector.PreviousPhaseTimes())
+		ex.phaseTimes.SetSessionPhaseTime(sessionphase.SessionQueryServiced, crtime.NowMono())
 		// Note that regardless of res.Err(), these observer statements don't
 		// generate error events; transactions are always allowed to continue.
 		return nil, nil, err
@@ -178,6 +180,7 @@ func (ex *connExecutor) execStmt(
 		case eventNonRetryableErrPayload:
 			ex.recordFailure(p)
 		}
+		ex.phaseTimes.SetSessionPhaseTime(sessionphase.SessionQueryServiced, crtime.NowMono())
 
 	case stateAborted:
 		ev, payload = ex.execStmtInAbortedState(ctx, ast, res)

pkg/sql/copy_from.go

@@ -343,9 +343,15 @@ func newCopyMachine(
 	// to have field data then we have to populate the expectedHiddenColumnIdxs
 	// field with the columns indexes we expect to be hidden.
 	if c.p.SessionData().ExpectAndIgnoreNotVisibleColumnsInCopy && len(n.Columns) == 0 {
+		numInaccessibleCols := 0
 		for i, col := range tableDesc.PublicColumns() {
 			if col.IsHidden() {
-				c.expectedHiddenColumnIdxs = append(c.expectedHiddenColumnIdxs, i)
+				// Offset the index by the number of preceding inaccessible
+				// columns, which are never expected in the input.
+				c.expectedHiddenColumnIdxs = append(c.expectedHiddenColumnIdxs, i-numInaccessibleCols)
+			}
+			if col.IsInaccessible() {
+				numInaccessibleCols++
 			}
 		}
 	}

pkg/sql/pgwire/testdata/pgtest/copy

@@ -199,6 +199,52 @@ ReadyForQuery
 {"Type":"CommandComplete","CommandTag":"SELECT 3"}
 {"Type":"ReadyForQuery","TxStatus":"I"}
 
+# Regression test for #119524. expect_and_ignore_not_visible_columns_in_copy
+# should behave correctly with inaccessible columns.
+send
+Query {"String": "CREATE TABLE t119524 (x INT PRIMARY KEY, y INT, INDEX ((x + y)))"}
+----
+
+until
+ReadyForQuery
+----
+{"Type":"CommandComplete","CommandTag":"CREATE TABLE"}
+{"Type":"ReadyForQuery","TxStatus":"I"}
+
+send
+Query {"String": "ALTER TABLE t119524 ADD COLUMN z INT NOT VISIBLE"}
+----
+
+until
+ReadyForQuery
+----
+{"Type":"CommandComplete","CommandTag":"ALTER TABLE"}
+{"Type":"ReadyForQuery","TxStatus":"I"}
+
+send crdb_only
+Query {"String": "COPY t119524 FROM STDIN"}
+CopyData {"Data": "1\t2\t3\n"}
+CopyDone
+----
+
+until crdb_only
+ReadyForQuery
+----
+{"Type":"CopyInResponse","ColumnFormatCodes":[0,0]}
+{"Type":"CommandComplete","CommandTag":"COPY 1"}
+{"Type":"ReadyForQuery","TxStatus":"I"}
+
+send crdb_only
+Query {"String": "SELECT *, z FROM t119524"}
+----
+
+until ignore=RowDescription crdb_only
+ReadyForQuery
+----
+{"Type":"DataRow","Values":[{"text":"1"},{"text":"2"},null]}
+{"Type":"CommandComplete","CommandTag":"SELECT 1"}
+{"Type":"ReadyForQuery","TxStatus":"I"}
+
 send crdb_only
 Query {"String": "SET expect_and_ignore_not_visible_columns_in_copy = false"}
 ----

pkg/sql/sessionphase/session_phase.go

@@ -114,6 +114,9 @@ func NewTimes() *Times {
 }
 
 // SetSessionPhaseTime sets the time for a given SessionPhase.
+// TODO(alyshan): Session Phase Times are set throughout the conn executor, it is
+// a tedious process to track when and where these times are set.
+// Found a bug again? Consider refactoring.
 func (t *Times) SetSessionPhaseTime(sp SessionPhase, time crtime.Mono) {
 	t.times[sp] = time
 }