sql: optimizer scan misestimate logging improvements

This commit is a follow-up to #154370. It changes misestimate logging to
use structured logging on the `SQL_EXEC` log channel with a new
`ScanRowCountMisestimate` event, instead of unstructured logs on DEV. It
also adds an error case to `stats.EstimateStaleness()` when there are 1
or fewer full automatic stats collections, and uses the fully qualified
table name in logs.

Part of: #153748, #153873

Release note (sql change): Changes scan misestimate logging gated behind
`sql.log.scan_row_count_misestimate.enabled` to use structured logging
including the table and index being scanned, the estimated and actual
row counts, the time since the last table stats collection, and the
table's estimated staleness.

Author: Uzair5162

docs/generated/eventlog.md

@@ -948,6 +948,37 @@ and the cluster setting `sql.log.all_statements.enabled` is set.
 | `BulkJobId` | The job id for bulk job (IMPORT/BACKUP/RESTORE). | no |
 | `StmtPosInTxn` | The statement's index in the transaction, starting at 1. | no |
 
+### `scan_row_count_misestimate`
+
+An event of type `scan_row_count_misestimate` is recorded when the optimizer's row count estimate
+for a logical scan differs significantly from the actual number of rows read,
+and cluster setting `sql.log.scan_row_count_misestimate.enabled` is set.
+
+
+| Field | Description | Sensitive |
+|--|--|--|
+| `TableName` | The fully qualified name of the table being scanned. | no |
+| `IndexName` | The name of the index being scanned. | no |
+| `EstimatedRowCount` | The optimizer's estimated row count for the scan. | no |
+| `ActualRowCount` | The actual number of rows read by all processors performing the scan. | no |
+| `NanosSinceStatsCollected` | Time in nanoseconds that have passed since full stats were collected on the table. | no |
+| `EstimatedStaleness` | Estimated fraction of stale rows in the table based on the time since stats were last collected. | no |
+
+
+#### Common fields
+
+| Field | Description | Sensitive |
+|--|--|--|
+| `Timestamp` | The timestamp of the event. Expressed as nanoseconds since the Unix epoch. | no |
+| `EventType` | The type of the event. | no |
+| `Statement` | A normalized copy of the SQL statement that triggered the event. The statement string contains a mix of sensitive and non-sensitive details (it is redactable). | partially |
+| `Tag` | The statement tag. This is separate from the statement string, since the statement string can contain sensitive information. The tag is guaranteed not to. | no |
+| `User` | The user account that triggered the event. The special usernames `root` and `node` are not considered sensitive. | depends |
+| `DescriptorID` | The primary object descriptor affected by the operation. Set to zero for operations that don't affect descriptors. | no |
+| `ApplicationName` | The application name for the session where the event was emitted. This is included in the event to ease filtering of logging output by application. | no |
+| `PlaceholderValues` | The mapping of SQL placeholders to their values, for prepared statements. | yes |
+| `TxnReadTimestamp` | The current read timestamp of the transaction that triggered the event, if in a transaction. | no |
+
 ## SQL Logical Schema Changes
 
 Events in this category pertain to DDL (Data Definition Language)

pkg/sql/distsql_running.go

@@ -49,14 +49,14 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/sql/sessiondatapb"
 	"github.com/cockroachdb/cockroach/pkg/sql/sqlerrors"
 	"github.com/cockroachdb/cockroach/pkg/sql/sqltelemetry"
-	"github.com/cockroachdb/cockroach/pkg/sql/stats"
 	"github.com/cockroachdb/cockroach/pkg/sql/types"
 	"github.com/cockroachdb/cockroach/pkg/util/buildutil"
 	"github.com/cockroachdb/cockroach/pkg/util/errorutil/unimplemented"
 	"github.com/cockroachdb/cockroach/pkg/util/hlc"
-	"github.com/cockroachdb/cockroach/pkg/util/humanizeutil"
 	"github.com/cockroachdb/cockroach/pkg/util/interval"
 	"github.com/cockroachdb/cockroach/pkg/util/log"
+	"github.com/cockroachdb/cockroach/pkg/util/log/eventpb"
+	"github.com/cockroachdb/cockroach/pkg/util/log/severity"
 	"github.com/cockroachdb/cockroach/pkg/util/mon"
 	"github.com/cockroachdb/cockroach/pkg/util/quotapool"
 	"github.com/cockroachdb/cockroach/pkg/util/ring"
@@ -1358,27 +1358,38 @@ type scanStageEstimate struct {
 	estimatedRowCount uint64
 	statsCreatedAt    time.Time
 	tableID           descpb.ID
-	tableName         string
 	indexName         string
 
 	rowsRead uint64
 }
 
 var misestimateLogLimiter = log.Every(10 * time.Second)
 
-func (s *scanStageEstimate) logMisestimate(ctx context.Context, refresher *stats.Refresher) {
-	var suffix string
+func (s *scanStageEstimate) logMisestimate(ctx context.Context, planner *planner) {
+	tn, err := planner.GetQualifiedTableNameByID(ctx, int64(s.tableID), tree.ResolveAnyTableKind)
+	if err != nil {
+		return
+	}
+	fqTableName := tn.FQString()
+
+	event := &eventpb.ScanRowCountMisestimate{
+		CommonSQLEventDetails: planner.getCommonSQLEventDetails(),
+		TableName:             fqTableName,
+		IndexName:             s.indexName,
+		EstimatedRowCount:     s.estimatedRowCount,
+		ActualRowCount:        s.rowsRead,
+	}
 	if !s.statsCreatedAt.IsZero() {
-		timeSinceStats := timeutil.Since(s.statsCreatedAt)
-		suffix = fmt.Sprintf("; table stats collected %s ago",
-			humanizeutil.LongDuration(timeSinceStats))
-		staleness, err := refresher.EstimateStaleness(ctx, s.tableID)
-		if err == nil {
-			suffix += fmt.Sprintf(" (estimated %.0f%% stale)", staleness*100)
+		nanosSinceStats := timeutil.Since(s.statsCreatedAt).Nanoseconds()
+		event.NanosSinceStatsCollected = nanosSinceStats
+
+		if estimatedStaleness, err :=
+			planner.ExecCfg().StatsRefresher.EstimateStaleness(ctx, s.tableID); err == nil {
+			event.EstimatedStaleness = estimatedStaleness
 		}
 	}
-	log.Dev.Warningf(ctx, "inaccurate estimate for scan on table %q (index %q): estimated=%d actual=%d%s",
-		s.tableName, s.indexName, s.estimatedRowCount, s.rowsRead, suffix)
+
+	log.StructuredEvent(ctx, severity.WARNING, event)
 }
 
 var _ execinfra.RowReceiver = &DistSQLReceiver{}
@@ -1844,7 +1855,6 @@ func (r *DistSQLReceiver) makeScanEstimates(physPlan *PhysicalPlan, st *cluster.
 				estimatedRowCount: p.Spec.EstimatedRowCount,
 				statsCreatedAt:    p.Spec.StatsCreatedAt,
 				tableID:           p.Spec.Core.TableReader.FetchSpec.TableID,
-				tableName:         p.Spec.Core.TableReader.FetchSpec.TableName,
 				indexName:         p.Spec.Core.TableReader.FetchSpec.IndexName,
 			}
 		}
@@ -1883,7 +1893,7 @@ func (r *DistSQLReceiver) maybeLogMisestimates(ctx context.Context, planner *pla
 			}
 			checkedLimiter = true
 		}
-		s.logMisestimate(ctx, planner.ExecCfg().StatsRefresher)
+		s.logMisestimate(ctx, planner)
 	}
 }
 

pkg/sql/stats/automatic_stats.go

@@ -936,6 +936,9 @@ func (r *Refresher) EstimateStaleness(ctx context.Context, tableID descpb.ID) (f
 	staleTargetFraction := r.autoStatsFractionStaleRows(explicitSettings)
 
 	avgRefreshTime := avgFullRefreshTime(tableStats)
+	if avgRefreshTime == defaultAverageTimeBetweenRefreshes {
+		return 0, errors.New("insufficient auto stats history to estimate staleness")
+	}
 	statsAge := timeutil.Since(stat.CreatedAt)
 	if r.knobs != nil && r.knobs.StubTimeNow != nil {
 		statsAge = r.knobs.StubTimeNow().Sub(stat.CreatedAt)

pkg/sql/stats/automatic_stats_test.go

@@ -9,6 +9,7 @@ import (
 	"context"
 	"fmt"
 	"math"
+	"strings"
 	"testing"
 	"time"
 
@@ -1146,7 +1147,7 @@ func TestEstimateStaleness(t *testing.T) {
 		return err
 	}
 
-	overwriteFullStats := func(startOffsetHours, intervalHours int) error {
+	overwriteFullStats := func(startOffsetHours, intervalHours, numStats int) error {
 		return s.DB().Txn(ctx, func(ctx context.Context, txn *kv.Txn) error {
 			_, err := internalDB.Executor().Exec(
 				ctx, "delete-stats", txn,
@@ -1157,7 +1158,7 @@ func TestEstimateStaleness(t *testing.T) {
 				return err
 			}
 
-			for i := 0; i < 5; i++ {
+			for i := 0; i < numStats; i++ {
 				columnIDsVal := tree.NewDArray(types.Int)
 				if err := columnIDsVal.Append(tree.NewDInt(tree.DInt(1))); err != nil {
 					return err
@@ -1190,10 +1191,33 @@ func TestEstimateStaleness(t *testing.T) {
 	require.Error(t, err)
 	require.Contains(t, err.Error(), "automatic stats collection is not allowed for this table")
 
+	// Ensure that we return an error if estimating staleness with insufficient
+	// auto stats history.
+	if err = overwriteFullStats(
+		5, /* startOffsetHours */
+		0, /* intervalHours */
+		1, /* numStats */
+	); err != nil {
+		t.Fatal(err)
+	}
+
+	err = testutils.SucceedsSoonError(func() error {
+		_, err := refresher.EstimateStaleness(ctx, table.GetID())
+		if err == nil {
+			return fmt.Errorf("expected error but got nil")
+		}
+		if !strings.Contains(err.Error(), "insufficient auto stats history to estimate staleness") {
+			return fmt.Errorf("expected 'insufficient auto stats history to estimate staleness' but got: %w", err)
+		}
+		return nil
+	})
+	require.NoError(t, err)
+
 	// Create stats with 10-hour intervals, the most recent being 5 hours old.
 	if err = overwriteFullStats(
 		5,  /* startOffsetHours */
 		10, /* intervalHours */
+		5,  /* numStats */
 	); err != nil {
 		t.Fatal(err)
 	}
@@ -1223,6 +1247,7 @@ func TestEstimateStaleness(t *testing.T) {
 	if err = overwriteFullStats(
 		15, /* startOffsetHours */
 		3,  /* intervalHours */
+		5,  /* numStats */
 	); err != nil {
 		t.Fatal(err)
 	}
@@ -1239,6 +1264,7 @@ func TestEstimateStaleness(t *testing.T) {
 	if err = overwriteFullStats(
 		15, /* startOffsetHours */
 		2,  /* intervalHours */
+		5,  /* numStats */
 	); err != nil {
 		t.Fatal(err)
 	}

pkg/util/log/eventpb/eventlog_channels_generated.go

@@ -269,3 +269,31 @@ message QueryExecute {
   CommonSQLEventDetails sql = 2 [(gogoproto.nullable) = false, (gogoproto.jsontag) = "", (gogoproto.embed) = true];
   CommonSQLExecDetails exec = 3 [(gogoproto.nullable) = false, (gogoproto.jsontag) = "", (gogoproto.embed) = true];
 }
+
+// ScanRowCountMisestimate is recorded when the optimizer's row count estimate
+// for a logical scan differs significantly from the actual number of rows read,
+// and cluster setting `sql.log.scan_row_count_misestimate.enabled` is set.
+message ScanRowCountMisestimate {
+  CommonEventDetails common = 1 [(gogoproto.nullable) = false, (gogoproto.jsontag) = "", (gogoproto.embed) = true];
+  CommonSQLEventDetails sql = 2 [(gogoproto.nullable) = false, (gogoproto.jsontag) = "", (gogoproto.embed) = true];
+
+  // The fully qualified name of the table being scanned.
+  string table_name = 3 [(gogoproto.jsontag) = ",omitempty", (gogoproto.moretags) = "redact:\"nonsensitive\""];
+
+  // The name of the index being scanned.
+  string index_name = 4 [(gogoproto.jsontag) = ",omitempty", (gogoproto.moretags) = "redact:\"nonsensitive\""];
+
+  // The optimizer's estimated row count for the scan.
+  uint64 estimated_row_count = 5 [(gogoproto.jsontag) = ",omitempty"];
+
+  // The actual number of rows read by all processors performing the scan.
+  uint64 actual_row_count = 6 [(gogoproto.jsontag) = ",omitempty"];
+
+  // Time in nanoseconds that have passed since full stats were collected on
+  // the table.
+  int64 nanos_since_stats_collected = 7 [(gogoproto.jsontag) = ",omitempty"];
+
+  // Estimated fraction of stale rows in the table based on the time since stats
+  // were last collected.
+  double estimated_staleness = 8 [(gogoproto.jsontag) = ",omitempty"];
+}