Merge #152275 #152348 #152366 #152371

152275: log,*: find and replace log.*Warning* with log.Dev.*Warning* r=kyle-a-wong a=kyle-a-wong

Epic: CRDB-53410
Release note: None

152348: backup: remove mixed-version check for incremental path suffix r=msbutler a=kev-cao

The `start_time` suffix was added to incremental backup paths in 25.2 A mixed version check was added to ensure backups written during the mixed-version state when ugprading to 25.2 would be written correctly. This check is no longer needed.

Epic: None

Release note: None

152366: unsafesql: convert tests to table tests r=angles-n-daemons a=angles-n-daemons

This is just a bit of cleanup in the unsafesql test, many of the existing tests share a similar structure, so I created a table test layout so that they work better.

Fixes: none
Epic: none

Release note: none

152371: jobs: mark a few auto partial stats metrics as essential r=yuzefovich a=yuzefovich

In order to match which metrics we mark as "essential" for AUTO CREATE STATS jobs, we now mark the following AUTO CREATE PARTIAL STATS job metrics:
- `jobs.auto_create_partial_stats.currently_paused`
- `jobs.auto_create_partial_stats.currently_running`
- `jobs.auto_create_partial_stats.resume_failed`.

Epic: CRDB-52656
Release note: None

Co-authored-by: Kyle Wong <[email protected]>
Co-authored-by: Kevin Cao <[email protected]>
Co-authored-by: Brian Dillmann <[email protected]>
Co-authored-by: Yahor Yuzefovich <[email protected]>

Author: 5 people

docs/generated/metrics/metrics.yaml

@@ -330,6 +330,39 @@ layers:
       essential: true
   - name: SQL
     metrics:
+    - name: jobs.auto_create_partial_stats.currently_paused
+      exported_name: jobs_auto_create_partial_stats_currently_paused
+      labeled_name: 'jobs{name: auto_create_partial_stats, status: currently_paused}'
+      description: Number of auto_create_partial_stats jobs currently considered Paused
+      y_axis_label: jobs
+      type: GAUGE
+      unit: COUNT
+      aggregation: AVG
+      derivative: NONE
+      how_to_use: This metric is a high-level indicator that automatically generated partial statistics jobs are paused which can lead to the query optimizer running with stale statistics. Stale statistics can cause suboptimal query plans to be selected leading to poor query performance.
+      essential: true
+    - name: jobs.auto_create_partial_stats.currently_running
+      exported_name: jobs_auto_create_partial_stats_currently_running
+      labeled_name: 'jobs{type: auto_create_partial_stats, status: currently_running}'
+      description: Number of auto_create_partial_stats jobs currently running in Resume or OnFailOrCancel state
+      y_axis_label: jobs
+      type: GAUGE
+      unit: COUNT
+      aggregation: AVG
+      derivative: NONE
+      how_to_use: This metric tracks the number of active automatically generated partial statistics jobs that could also be consuming resources. Ensure that foreground SQL traffic is not impacted by correlating this metric with SQL latency and query volume metrics.
+      essential: true
+    - name: jobs.auto_create_partial_stats.resume_failed
+      exported_name: jobs_auto_create_partial_stats_resume_failed
+      labeled_name: 'jobs.resume{name: auto_create_partial_stats, status: failed}'
+      description: Number of auto_create_partial_stats jobs which failed with a non-retriable error
+      y_axis_label: jobs
+      type: COUNTER
+      unit: COUNT
+      aggregation: AVG
+      derivative: NON_NEGATIVE_DERIVATIVE
+      how_to_use: This metric is a high-level indicator that automatically generated partial table statistics is failing. Failed statistic creation can lead to the query optimizer running with stale statistics. Stale statistics can cause suboptimal query plans to be selected leading to poor query performance.
+      essential: true
     - name: jobs.auto_create_stats.currently_paused
       exported_name: jobs_auto_create_stats_currently_paused
       labeled_name: 'jobs{name: auto_create_stats, status: currently_paused}'
@@ -394,7 +427,7 @@ layers:
       unit: COUNT
       aggregation: AVG
       derivative: NONE
-      how_to_use: This metric tracks the number of active create statistics jobs that may be consuming resources. Ensure that foreground SQL traffic is not impacted by correlating this metric with SQL latency and query volume metrics.
+      how_to_use: This metric tracks the number of active create statistics jobs that could also be consuming resources. Ensure that foreground SQL traffic is not impacted by correlating this metric with SQL latency and query volume metrics.
       essential: true
     - name: schedules.BACKUP.failed
       exported_name: schedules_BACKUP_failed
@@ -4055,24 +4088,6 @@ layers:
       unit: COUNT
       aggregation: AVG
       derivative: NONE
-    - name: jobs.auto_create_partial_stats.currently_paused
-      exported_name: jobs_auto_create_partial_stats_currently_paused
-      labeled_name: 'jobs{name: auto_create_partial_stats, status: currently_paused}'
-      description: Number of auto_create_partial_stats jobs currently considered Paused
-      y_axis_label: jobs
-      type: GAUGE
-      unit: COUNT
-      aggregation: AVG
-      derivative: NONE
-    - name: jobs.auto_create_partial_stats.currently_running
-      exported_name: jobs_auto_create_partial_stats_currently_running
-      labeled_name: 'jobs{type: auto_create_partial_stats, status: currently_running}'
-      description: Number of auto_create_partial_stats jobs currently running in Resume or OnFailOrCancel state
-      y_axis_label: jobs
-      type: GAUGE
-      unit: COUNT
-      aggregation: AVG
-      derivative: NONE
     - name: jobs.auto_create_partial_stats.expired_pts_records
       exported_name: jobs_auto_create_partial_stats_expired_pts_records
       labeled_name: 'jobs.expired_pts_records{type: auto_create_partial_stats}'
@@ -4136,15 +4151,6 @@ layers:
       unit: COUNT
       aggregation: AVG
       derivative: NON_NEGATIVE_DERIVATIVE
-    - name: jobs.auto_create_partial_stats.resume_failed
-      exported_name: jobs_auto_create_partial_stats_resume_failed
-      labeled_name: 'jobs.resume{name: auto_create_partial_stats, status: failed}'
-      description: Number of auto_create_partial_stats jobs which failed with a non-retriable error
-      y_axis_label: jobs
-      type: COUNTER
-      unit: COUNT
-      aggregation: AVG
-      derivative: NON_NEGATIVE_DERIVATIVE
     - name: jobs.auto_create_partial_stats.resume_retry_error
       exported_name: jobs_auto_create_partial_stats_resume_retry_error
       labeled_name: 'jobs.resume{name: auto_create_partial_stats, status: retry_error}'

pkg/acceptance/cluster/docker.go

@@ -307,7 +307,7 @@ func (c *Container) WaitUntilNotRunning(ctx context.Context) error {
 
 		out := io.MultiWriter(cmdLog, os.Stderr)
 		if err := c.Logs(ctx, out); err != nil {
-			log.Warningf(ctx, "%v", err)
+			log.Dev.Warningf(ctx, "%v", err)
 		}
 
 		if exitCode := waitOKBody.StatusCode; exitCode != 0 {
@@ -405,7 +405,7 @@ func (cli resilientDockerClient) ContainerStart(
 		// Keep going if ContainerStart timed out, but client's context is not
 		// expired.
 		if errors.Is(err, context.DeadlineExceeded) && clientCtx.Err() == nil {
-			log.Warningf(clientCtx, "ContainerStart timed out, retrying")
+			log.Dev.Warningf(clientCtx, "ContainerStart timed out, retrying")
 			continue
 		}
 		return err
@@ -452,7 +452,7 @@ func (cli resilientDockerClient) ContainerCreate(
 				return cli.ContainerCreate(ctx, config, hostConfig, networkingConfig, platformSpec, containerName)
 			}
 		}
-		log.Warningf(ctx, "error indicated existing container %s, "+
+		log.Dev.Warningf(ctx, "error indicated existing container %s, "+
 			"but none found:\nerror: %s\ncontainers: %+v",
 			containerName, err, containers)
 		// We likely raced with a previous (late) removal of the container.

pkg/acceptance/cluster/dockercluster.go

@@ -303,7 +303,7 @@ func (l *DockerCluster) createNetwork(ctx context.Context) {
 	})
 	maybePanic(err)
 	if resp.Warning != "" {
-		log.Warningf(ctx, "creating network: %s", resp.Warning)
+		log.Dev.Warningf(ctx, "creating network: %s", resp.Warning)
 	}
 	l.networkID = resp.ID
 }
@@ -920,7 +920,7 @@ func (l *DockerCluster) ExecCLI(ctx context.Context, i int, cmd []string) (strin
 func (l *DockerCluster) Cleanup(ctx context.Context, preserveLogs bool) {
 	volumes, err := os.ReadDir(l.volumesDir)
 	if err != nil {
-		log.Warningf(ctx, "%v", err)
+		log.Dev.Warningf(ctx, "%v", err)
 		return
 	}
 	for _, v := range volumes {
@@ -929,7 +929,7 @@ func (l *DockerCluster) Cleanup(ctx context.Context, preserveLogs bool) {
 			continue
 		}
 		if err := os.RemoveAll(filepath.Join(l.volumesDir, v.Name())); err != nil {
-			log.Warningf(ctx, "%v", err)
+			log.Dev.Warningf(ctx, "%v", err)
 		}
 	}
 }

pkg/acceptance/localcluster/cluster.go

@@ -564,10 +564,10 @@ func (n *Node) startAsyncInnerLocked(ctx context.Context, joins ...string) error
 
 	if err := n.cmd.Start(); err != nil {
 		if err := stdout.Close(); err != nil {
-			log.Warningf(ctx, "%v", err)
+			log.Dev.Warningf(ctx, "%v", err)
 		}
 		if err := stderr.Close(); err != nil {
-			log.Warningf(ctx, "%v", err)
+			log.Dev.Warningf(ctx, "%v", err)
 		}
 		return errors.Wrapf(err, "running %s %v", n.cmd.Path, n.cmd.Args)
 	}
@@ -577,13 +577,13 @@ func (n *Node) startAsyncInnerLocked(ctx context.Context, joins ...string) error
 	go func(cmd *exec.Cmd) {
 		waitErr := cmd.Wait()
 		if waitErr != nil {
-			log.Warningf(ctx, "%v", waitErr)
+			log.Dev.Warningf(ctx, "%v", waitErr)
 		}
 		if err := stdout.Close(); err != nil {
-			log.Warningf(ctx, "%v", err)
+			log.Dev.Warningf(ctx, "%v", err)
 		}
 		if err := stderr.Close(); err != nil {
-			log.Warningf(ctx, "%v", err)
+			log.Dev.Warningf(ctx, "%v", err)
 		}
 
 		log.Dev.Infof(ctx, "process %d: %s", cmd.Process.Pid, cmd.ProcessState)
@@ -795,7 +795,7 @@ func (n *Node) Signal(s os.Signal) {
 		return
 	}
 	if err := n.cmd.Process.Signal(s); err != nil {
-		log.Warningf(context.Background(), "%v", err)
+		log.Dev.Warningf(context.Background(), "%v", err)
 	}
 }
 
@@ -806,7 +806,7 @@ func (n *Node) Wait() *exec.ExitError {
 	ch := n.notRunning
 	n.Unlock()
 	if ch == nil {
-		log.Warning(context.Background(), "(*Node).Wait called when node was not running")
+		log.Dev.Warning(context.Background(), "(*Node).Wait called when node was not running")
 		return nil
 	}
 	<-ch

pkg/backup/backup_job.go

@@ -478,7 +478,7 @@ func releaseProtectedTimestamp(
 	if errors.Is(err, protectedts.ErrNotExists) {
 		// No reason to return an error which might cause problems if it doesn't
 		// seem to exist.
-		log.Warningf(ctx, "failed to release protected which seems not to exist: %v", err)
+		log.Dev.Warningf(ctx, "failed to release protected which seems not to exist: %v", err)
 		err = nil
 	}
 	return err
@@ -500,7 +500,7 @@ func getTableStatsForBackup(
 			tableDesc := tabledesc.NewBuilder(tbl).BuildImmutableTable()
 			tableStatisticsAcc, err := stats.GetTableStatsProtosFromDB(ctx, tableDesc, executor)
 			if err != nil {
-				log.Warningf(
+				log.Dev.Warningf(
 					ctx, "failed to collect stats for table: %s, table ID: %d during a backup: %s",
 					tableDesc.GetName(), tableDesc.GetID(), err,
 				)
@@ -771,7 +771,7 @@ func (b *backupResumer) Resume(ctx context.Context, execCtx interface{}) error {
 			return jobs.MarkAsRetryJobError(errors.Wrapf(err, "job encountered retryable error on draining node"))
 		}
 
-		log.Warningf(ctx, "encountered retryable error: %+v", err)
+		log.Dev.Warningf(ctx, "encountered retryable error: %+v", err)
 
 		// Reload the backup manifest to pick up any spans we may have completed on
 		// previous attempts.
@@ -789,7 +789,7 @@ func (b *backupResumer) Resume(ctx context.Context, execCtx interface{}) error {
 			if ctx.Err() != nil {
 				return ctx.Err()
 			}
-			log.Warningf(ctx, "BACKUP job %d could not reload job progress when retrying: %+v",
+			log.Dev.Warningf(ctx, "BACKUP job %d could not reload job progress when retrying: %+v",
 				b.job.ID(), reloadErr)
 		} else {
 			curProgress := reloadedJob.FractionCompleted()
@@ -1947,7 +1947,7 @@ func (b *backupResumer) processScheduledBackupCompletion(
 		if _, err := maybeStartCompactionJob(
 			ctx, execCtx.ExecCfg(), execCtx.User(), details,
 		); err != nil {
-			log.Warningf(ctx, "failed to trigger backup compaction for schedule %d: %v", scheduleID, err)
+			log.Dev.Warningf(ctx, "failed to trigger backup compaction for schedule %d: %v", scheduleID, err)
 		}
 	}
 	return nil
@@ -2028,19 +2028,19 @@ func (b *backupResumer) deleteCheckpoint(
 		// backups, and then from the progress directory.
 		err = exportStore.Delete(ctx, backupinfo.BackupManifestCheckpointName)
 		if err != nil {
-			log.Warningf(ctx, "unable to delete checkpointed backup descriptor file in base directory: %+v", err)
+			log.Dev.Warningf(ctx, "unable to delete checkpointed backup descriptor file in base directory: %+v", err)
 		}
 		err = exportStore.Delete(ctx, backupinfo.BackupManifestCheckpointName+backupinfo.BackupManifestChecksumSuffix)
 		if err != nil {
-			log.Warningf(ctx, "unable to delete checkpoint checksum file in base directory: %+v", err)
+			log.Dev.Warningf(ctx, "unable to delete checkpoint checksum file in base directory: %+v", err)
 		}
 		// Delete will not delete a nonempty directory, so we have to go through
 		// all files and delete each file one by one.
 		return exportStore.List(ctx, backupinfo.BackupProgressDirectory, "", func(p string) error {
 			return exportStore.Delete(ctx, backupinfo.BackupProgressDirectory+p)
 		})
 	}(); err != nil {
-		log.Warningf(ctx, "unable to delete checkpointed backup descriptor file in progress directory: %+v", err)
+		log.Dev.Warningf(ctx, "unable to delete checkpointed backup descriptor file in progress directory: %+v", err)
 	}
 }
 

pkg/backup/backup_processor.go

@@ -232,7 +232,7 @@ func (bp *backupDataProcessor) constructProgressProducerMeta(
 	// Annotate the progress with the fraction completed by this backupDataProcessor.
 	progDetails := backuppb.BackupManifest_Progress{}
 	if err := gogotypes.UnmarshalAny(&prog.ProgressDetails, &progDetails); err != nil {
-		log.Warningf(bp.Ctx(), "failed to unmarshal progress details %v", err)
+		log.Dev.Warningf(bp.Ctx(), "failed to unmarshal progress details %v", err)
 	} else {
 		totalSpans := int32(len(bp.spec.Spans) + len(bp.spec.IntroducedSpans))
 		bp.completedSpans += progDetails.CompletedSpans
@@ -464,7 +464,7 @@ func runBackupProcessor(
 		sink := backupsink.MakeFileSSTSink(sinkConf, storage, pacer)
 		defer func() {
 			if err := sink.Flush(ctx); err != nil {
-				log.Warningf(ctx, "failed to flush SST sink: %s", err)
+				log.Dev.Warningf(ctx, "failed to flush SST sink: %s", err)
 			}
 			logClose(ctx, sink, "SST sink")
 		}()
@@ -561,7 +561,7 @@ func runBackupProcessor(
 									tracer = flowCtx.Cfg.Tracer
 								}
 								if tracer == nil {
-									log.Warning(ctx, "nil tracer in backup processor")
+									log.Dev.Warning(ctx, "nil tracer in backup processor")
 								}
 								opts := make([]tracing.SpanOption, 0)
 								opts = append(opts, tracing.WithParent(sp))
@@ -657,7 +657,7 @@ func runBackupProcessor(
 						}
 
 						if len(resp.Files) > 1 {
-							log.Warning(ctx, "unexpected multi-file response using header.TargetBytes = 1")
+							log.Dev.Warning(ctx, "unexpected multi-file response using header.TargetBytes = 1")
 						}
 
 						// Even if the ExportRequest did not export any data we want to report
@@ -756,7 +756,7 @@ func reserveWorkerMemory(
 	workerCount := minimumWorkerCount
 	for i := 0; i < (maxWorkerCount - minimumWorkerCount); i++ {
 		if err := memAcc.Grow(ctx, perWorkerMemory); err != nil {
-			log.Warningf(ctx, "backup worker count restricted by memory limit")
+			log.Dev.Warningf(ctx, "backup worker count restricted by memory limit")
 			break
 		}
 		workerCount++
@@ -766,7 +766,7 @@ func reserveWorkerMemory(
 
 func logClose(ctx context.Context, c io.Closer, desc string) {
 	if err := c.Close(); err != nil {
-		log.Warningf(ctx, "failed to close %s: %s", redact.SafeString(desc), err.Error())
+		log.Dev.Warningf(ctx, "failed to close %s: %s", redact.SafeString(desc), err.Error())
 	}
 }
 

pkg/backup/backup_telemetry.go

@@ -119,12 +119,12 @@ func createBackupRecoveryEvent(
 	storageTypes := make(map[string]struct{})
 	defaultURI, urisByLocalityKV, err := backupdest.GetURIsByLocalityKV(initialDetails.Destination.To, "")
 	if err != nil {
-		log.Warningf(ctx, "failed to get URIs by locality: %v", err)
+		log.Dev.Warningf(ctx, "failed to get URIs by locality: %v", err)
 	}
 
 	if defaultURI != "" {
 		if storageType, authType, err := parseStorageAndAuth(defaultURI); err != nil {
-			log.Warningf(ctx, "failed to parse backup default URI: %v", err)
+			log.Dev.Warningf(ctx, "failed to parse backup default URI: %v", err)
 		} else {
 			storageTypes[storageType] = struct{}{}
 			authTypes[authType] = struct{}{}
@@ -133,7 +133,7 @@ func createBackupRecoveryEvent(
 
 	for _, uri := range urisByLocalityKV {
 		if storageType, authType, err := parseStorageAndAuth(uri); err != nil {
-			log.Warningf(ctx, "failed to parse locality URI: %v", err)
+			log.Dev.Warningf(ctx, "failed to parse locality URI: %v", err)
 		} else {
 			storageTypes[storageType] = struct{}{}
 			authTypes[authType] = struct{}{}
@@ -218,7 +218,7 @@ func getPassphraseAndKMS(
 			if enc.KMSInfo != nil {
 				parsedKMSURI, err := url.ParseRequestURI(enc.KMSInfo.Uri)
 				if err != nil {
-					log.Warningf(ctx, "failed to parse KMS URI %s: %v", enc.KMSInfo.Uri, err)
+					log.Dev.Warningf(ctx, "failed to parse KMS URI %s: %v", enc.KMSInfo.Uri, err)
 				} else {
 					kms = parsedKMSURI.Scheme
 				}
@@ -348,7 +348,7 @@ func logRestoreTelemetry(
 
 	for _, uri := range details.URIs {
 		if storage, auth, err := parseStorageAndAuth(uri); err != nil {
-			log.Warningf(ctx, "failed to parse URI: %v", err)
+			log.Dev.Warningf(ctx, "failed to parse URI: %v", err)
 		} else {
 			authTypes[auth] = struct{}{}
 			storageTypes[storage] = struct{}{}
@@ -362,7 +362,7 @@ func logRestoreTelemetry(
 
 		for _, uri := range localityInfo.URIsByOriginalLocalityKV {
 			if storage, auth, err := parseStorageAndAuth(uri); err != nil {
-				log.Warningf(ctx, "failed to parse URI: %v", err)
+				log.Dev.Warningf(ctx, "failed to parse URI: %v", err)
 			} else {
 				authTypes[auth] = struct{}{}
 				storageTypes[storage] = struct{}{}