Merge cockroachdb#142982 cockroachdb#143007 cockroachdb#143027

142982: kvserver,raft: reduce leader lease logging r=iskettaneh a=miraradeva

Under some circumstances (e.g. successive splitting, overload), certain Raft and store liveness logging is excessive and might appear worrisome even though it is harmless or expected.

This commit pushes some of that logging to a higher verbosity.

Fixes: cockroachdb#141854

Release note: None

143007: upgrades: skip creating defaultdb/postgres dbs during PCR reader tenant startup r=jeffswenson a=msbutler

Informs cockroachdb#142960
Informs: cockroachdb#141592

Release note: none

143027: sqlstats: set session meta fields directly on sqlstats.RecordedTxnStats r=xinhaoz a=xinhaoz

This commit replaces the SessionData pointer field on sqlstas.RecordedTxnStats with direct Application and UserNormalized fields for simpler access to session metadata.

Epic: none
Release note: None

Co-authored-by: Mira Radeva <[email protected]>
Co-authored-by: Michael Butler <[email protected]>
Co-authored-by: Xin Hao Zhang <[email protected]>

Author: 4 people

pkg/kv/kvserver/replica_raft.go

@@ -2220,7 +2220,9 @@ func (r *Replica) maybeMarkReplicaUnavailableInLeaderlessWatcher(
 			err := errors.Errorf("have been leaderless for %.2fs, setting the "+
 				"leaderless watcher replica's state as unavailable",
 				durationSinceLeaderless.Seconds())
-			log.Warningf(ctx, "%s", err)
+			if log.ExpensiveLogEnabled(ctx, 1) {
+				log.VEventf(ctx, 1, "%s", err)
+			}
 			r.LeaderlessWatcher.mu.unavailable = true
 		}
 	}

pkg/kv/kvserver/replica_store_liveness.go

@@ -63,7 +63,9 @@ func (r *replicaRLockedStoreLiveness) SupportFor(replicaID raftpb.PeerID) (raftp
 	storeID, ok := r.getStoreIdent(replicaID)
 	if !ok {
 		ctx := r.AnnotateCtx(context.TODO())
-		log.Warningf(ctx, "store not found for replica %d in SupportFor", replicaID)
+		if log.ExpensiveLogEnabled(ctx, 1) {
+			log.VEventf(ctx, 1, "store not found for replica %d in SupportFor", replicaID)
+		}
 		return 0, false
 	}
 	epoch, ok := r.store.storeLiveness.SupportFor(storeID)
@@ -77,7 +79,9 @@ func (r *replicaRLockedStoreLiveness) SupportFrom(
 	storeID, ok := r.getStoreIdent(replicaID)
 	if !ok {
 		ctx := r.AnnotateCtx(context.TODO())
-		log.Warningf(ctx, "store not found for replica %d in SupportFrom", replicaID)
+		if log.ExpensiveLogEnabled(ctx, 1) {
+			log.VEventf(ctx, 1, "store not found for replica %d in SupportFrom", replicaID)
+		}
 		return 0, hlc.Timestamp{}
 	}
 	epoch, exp := r.store.storeLiveness.SupportFrom(storeID)

pkg/raft/raft.go

@@ -2356,7 +2356,7 @@ func (r *raft) checkQuorumActive() {
 		r.logger.Debugf("%x does not have store liveness support from a quorum of peers", r.id)
 	}
 	if !quorumActiveByHeartbeats && !quorumActiveByFortification {
-		r.logger.Warningf("%x stepped down to follower since quorum is not active", r.id)
+		r.logger.Infof("%x stepped down to follower since quorum is not active", r.id)
 		r.becomeFollower(r.Term, None)
 	}
 	// Mark everyone (but ourselves) as inactive in preparation for the next

pkg/raft/testdata/de_fortification_checkquorum.txt

@@ -68,7 +68,7 @@ INFO 1 leader at term 1 does not support itself in the liveness fabric
 INFO 1 leader at term 1 does not support itself in the liveness fabric
 DEBUG 1 has not received messages from a quorum of peers in the last election timeout
 DEBUG 1 does not have store liveness support from a quorum of peers
-WARN 1 stepped down to follower since quorum is not active
+INFO 1 stepped down to follower since quorum is not active
 DEBUG 1 setting election elapsed to start from 3 ticks after store liveness support expired
 INFO 1 became follower at term 1
 DEBUG 1 reset election elapsed to 0
@@ -232,7 +232,7 @@ INFO 2 leader at term 2 does not support itself in the liveness fabric
 INFO 2 leader at term 2 does not support itself in the liveness fabric
 DEBUG 2 has not received messages from a quorum of peers in the last election timeout
 DEBUG 2 does not have store liveness support from a quorum of peers
-WARN 2 stepped down to follower since quorum is not active
+INFO 2 stepped down to follower since quorum is not active
 DEBUG 2 setting election elapsed to start from 3 ticks after store liveness support expired
 INFO 2 became follower at term 2
 DEBUG 2 reset election elapsed to 0

pkg/raft/testdata/fortification_checkquorum.txt

@@ -84,7 +84,7 @@ INFO 1 leader at term 1 does not support itself in the liveness fabric
 INFO 1 leader at term 1 does not support itself in the liveness fabric
 DEBUG 1 has not received messages from a quorum of peers in the last election timeout
 DEBUG 1 does not have store liveness support from a quorum of peers
-WARN 1 stepped down to follower since quorum is not active
+INFO 1 stepped down to follower since quorum is not active
 DEBUG 1 setting election elapsed to start from 3 ticks after store liveness support expired
 INFO 1 became follower at term 1
 DEBUG 1 reset election elapsed to 0

pkg/raft/testdata/liveness_recovered_after_temporary_loss_of_quorum.txt

@@ -65,7 +65,7 @@ tick-election 1
 ----
 INFO 1 leader at term 1 does not support itself in the liveness fabric
 INFO 1 leader at term 1 does not support itself in the liveness fabric
-WARN 1 stepped down to follower since quorum is not active
+INFO 1 stepped down to follower since quorum is not active
 INFO 1 became follower at term 1
 
 stabilize

pkg/sql/conn_executor_exec.go

@@ -4356,8 +4356,9 @@ func (ex *connExecutor) recordTransactionFinish(
 		// TODO(107318): add qos
 		// TODO(107318): add asoftime or ishistorical
 		// TODO(107318): add readonly
-		SessionData: ex.sessionData(),
-		TxnErr:      txnErr,
+		TxnErr:         txnErr,
+		Application:    ex.applicationName.Load().(string),
+		UserNormalized: ex.sessionData().User().Normalized(),
 	}
 
 	if ex.server.cfg.TestingKnobs.OnRecordTxnFinish != nil {

pkg/sql/exec_log.go

@@ -471,8 +471,8 @@ func (p *planner) logTransaction(
 
 	*sampledTxn = eventpb.SampledTransaction{
 		SkippedTransactions:      int64(skippedTransactions),
-		User:                     txnStats.SessionData.SessionUser().Normalized(),
-		ApplicationName:          txnStats.SessionData.ApplicationName,
+		User:                     txnStats.UserNormalized,
+		ApplicationName:          txnStats.Application,
 		TxnCounter:               uint32(txnCounter),
 		SessionID:                txnStats.SessionID.String(),
 		TransactionID:            txnStats.TransactionID.String(),

pkg/sql/instrumentation_test.go

@@ -215,7 +215,7 @@ func TestSampledStatsCollectionOnNewFingerprint(t *testing.T) {
 				OnRecordTxnFinish: func(isInternal bool, _ *sessionphase.Times, stmt string, txnStats sqlstats.RecordedTxnStats) {
 					// We won't run into a race here because we'll only observe
 					// txns from a single connection.
-					if txnStats.SessionData.ApplicationName == testApp {
+					if txnStats.Application == testApp {
 						if strings.Contains(stmt, `SET application_name`) {
 							return
 						}

pkg/sql/sqlstats/BUILD.bazel

@@ -20,7 +20,6 @@ go_library(
         "//pkg/sql/clusterunique",
         "//pkg/sql/execstats",
         "//pkg/sql/sem/tree",
-        "//pkg/sql/sessiondata",
         "//pkg/sql/sqlstats/persistedsqlstats/sqlstatsutil",
         "//pkg/util/log",
         "//pkg/util/metric",

pkg/sql/sqlstats/insights/util.go

@@ -36,12 +36,6 @@ func MakeTxnInsight(value sqlstats.RecordedTxnStats) *Transaction {
 		status = Transaction_Completed
 	}
 
-	var user, appName string
-	if value.SessionData != nil {
-		user = value.SessionData.User().Normalized()
-		appName = value.SessionData.ApplicationName
-	}
-
 	insight := &Transaction{
 		ID:              value.TransactionID,
 		FingerprintID:   value.FingerprintID,
@@ -50,8 +44,8 @@ func MakeTxnInsight(value sqlstats.RecordedTxnStats) *Transaction {
 		Contention:      &value.ExecStats.ContentionTime,
 		StartTime:       value.StartTime,
 		EndTime:         value.EndTime,
-		User:            user,
-		ApplicationName: appName,
+		User:            value.UserNormalized,
+		ApplicationName: value.Application,
 		RowsRead:        value.RowsRead,
 		RowsWritten:     value.RowsWritten,
 		RetryCount:      value.RetryCount,

pkg/sql/sqlstats/sslocal/BUILD.bazel

@@ -63,7 +63,6 @@ go_test(
         "//pkg/sql/sem/catconstants",
         "//pkg/sql/sem/tree",
         "//pkg/sql/sessiondata",
-        "//pkg/sql/sessiondatapb",
         "//pkg/sql/sessionphase",
         "//pkg/sql/sqlstats",
         "//pkg/sql/sqlstats/insights",

pkg/sql/sqlstats/sslocal/sql_stats_test.go

@@ -30,7 +30,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/sql/sem/catconstants"
 	"github.com/cockroachdb/cockroach/pkg/sql/sem/tree"
 	"github.com/cockroachdb/cockroach/pkg/sql/sessiondata"
-	"github.com/cockroachdb/cockroach/pkg/sql/sessiondatapb"
 	"github.com/cockroachdb/cockroach/pkg/sql/sessionphase"
 	"github.com/cockroachdb/cockroach/pkg/sql/sqlstats"
 	"github.com/cockroachdb/cockroach/pkg/sql/sqlstats/insights"
@@ -474,17 +473,11 @@ func TestExplicitTxnFingerprintAccounting(t *testing.T) {
 		defer func() {
 			statsCollector.EndTransaction(ctx, txnFingerprintID)
 			require.NoError(t,
-				statsCollector.
-					RecordTransaction(ctx, sqlstats.RecordedTxnStats{
-						FingerprintID: txnFingerprintID,
-						SessionData: &sessiondata.SessionData{
-							SessionData: sessiondatapb.SessionData{
-								UserProto:       username.RootUserName().EncodeProto(),
-								Database:        "defaultdb",
-								ApplicationName: "appname_findme",
-							},
-						},
-					}))
+				statsCollector.RecordTransaction(ctx, sqlstats.RecordedTxnStats{
+					FingerprintID:  txnFingerprintID,
+					UserNormalized: username.RootUser,
+					Application:    "appname_findme",
+				}))
 		}()
 		for _, fingerprint := range testCase.fingerprints {
 			stmtFingerprintID := appstatspb.ConstructStatementFingerprintID(fingerprint, testCase.implicit, "defaultdb")
@@ -609,14 +602,9 @@ func TestAssociatingStmtStatsWithTxnFingerprint(t *testing.T) {
 			transactionFingerprintID := appstatspb.TransactionFingerprintID(txnFingerprintIDHash.Sum())
 			statsCollector.EndTransaction(ctx, transactionFingerprintID)
 			err := statsCollector.RecordTransaction(ctx, sqlstats.RecordedTxnStats{
-				FingerprintID: transactionFingerprintID,
-				SessionData: &sessiondata.SessionData{
-					SessionData: sessiondatapb.SessionData{
-						UserProto:       username.RootUserName().EncodeProto(),
-						Database:        "defaultdb",
-						ApplicationName: "appname_findme",
-					},
-				},
+				FingerprintID:  transactionFingerprintID,
+				UserNormalized: username.RootUser,
+				Application:    "appname_findme",
 			})
 			require.NoError(t, err)
 

pkg/sql/sqlstats/ssprovider.go

@@ -17,7 +17,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/sql/clusterunique"
 	"github.com/cockroachdb/cockroach/pkg/sql/execstats"
 	"github.com/cockroachdb/cockroach/pkg/sql/sem/tree"
-	"github.com/cockroachdb/cockroach/pkg/sql/sessiondata"
 	"github.com/cockroachdb/cockroach/pkg/util/uuid"
 )
 
@@ -119,8 +118,10 @@ type RecordedTxnStats struct {
 	RowsWritten             int64
 	BytesRead               int64
 	Priority                roachpb.UserPriority
-	SessionData             *sessiondata.SessionData
 	TxnErr                  error
+	Application             string
+	// Normalized user name.
+	UserNormalized string
 }
 
 // SSDrainer is the interface for draining or resetting sql stats.

pkg/upgrade/upgrades/permanent_maybe_setup_pcr_reader.go

@@ -23,7 +23,7 @@ func maybeSetupPCRStandbyReader(
 	if d.TenantInfoAccessor == nil {
 		return nil
 	}
-	id, ts, err := d.TenantInfoAccessor.ReadFromTenantInfo(ctx)
+	id, ts, err := readerTenantInfo(ctx, d)
 	if err != nil {
 		return err
 	}

pkg/upgrade/upgrades/permanent_upgrades.go

@@ -20,6 +20,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/sql/sem/tree"
 	"github.com/cockroachdb/cockroach/pkg/sql/sessiondata"
 	"github.com/cockroachdb/cockroach/pkg/upgrade"
+	"github.com/cockroachdb/cockroach/pkg/util/hlc"
 	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/protoutil"
 	"github.com/cockroachdb/errors"
@@ -254,6 +255,12 @@ func createDefaultDbs(
 	// already.
 	const createDbStmt = `CREATE DATABASE IF NOT EXISTS "%s" WITH OWNER root`
 
+	id, _, _ := readerTenantInfo(ctx, deps)
+	if id.IsSet() {
+		// Don't create the default databases for read from standby tenants.
+		return nil
+	}
+
 	var err error
 	for _, dbName := range []string{catalogkeys.DefaultDatabaseName, catalogkeys.PgDatabaseName} {
 		stmt := fmt.Sprintf(createDbStmt, dbName)
@@ -265,3 +272,21 @@ func createDefaultDbs(
 	}
 	return nil
 }
+
+// readerTenantInfo returns the tenant ID and timestamp if we're spinning up a
+// read from standby tenant.
+func readerTenantInfo(
+	ctx context.Context, d upgrade.TenantDeps,
+) (roachpb.TenantID, hlc.Timestamp, error) {
+	if d.TenantInfoAccessor == nil {
+		return roachpb.TenantID{}, hlc.Timestamp{}, nil
+	}
+	id, ts, err := d.TenantInfoAccessor.ReadFromTenantInfo(ctx)
+	if err != nil {
+		return roachpb.TenantID{}, hlc.Timestamp{}, err
+	}
+	if !id.IsSet() {
+		return roachpb.TenantID{}, hlc.Timestamp{}, nil
+	}
+	return id, ts, nil
+}