Merge #151604

151604: sql: add tracing logs for generic and custom plan costs r=mgartner a=mgartner

Tracing logs have been added to aid in debugging query planning
decisions when `plan_cache_mode` is set to `auto`.

Release note: None


Co-authored-by: Marcus Gartner <[email protected]>

Author: craig[bot]

pkg/sql/plan_opt.go

@@ -635,16 +635,20 @@ func (opc *optPlanningCtx) buildNonIdealGenericPlan() bool {
 // ideal generic query plan is always chosen, if it exists. A non-ideal generic
 // plan is chosen if CustomPlanThreshold custom plans have already been built
 // and the generic plan is optimal or it has not yet been built.
-func (opc *optPlanningCtx) chooseGenericPlan() bool {
+func (opc *optPlanningCtx) chooseGenericPlan(ctx context.Context) bool {
 	ps := opc.p.stmt.Prepared
 	// Always use an ideal generic plan.
 	if ps.IdealGenericPlan {
+		opc.log(ctx, "ideal generic plan")
 		return true
 	}
 	switch opc.p.SessionData().PlanCacheMode {
 	case sessiondatapb.PlanCacheModeForceGeneric:
 		return true
 	case sessiondatapb.PlanCacheModeAuto:
+		if log.ExpensiveLogEnabled(ctx, 1) {
+			log.Eventf(ctx, "%s", ps.Costs.Summary())
+		}
 		return ps.Costs.NumCustom() >= prep.CustomPlanThreshold &&
 			(!ps.Costs.HasGeneric() || ps.Costs.IsGenericOptimal())
 	default:
@@ -706,7 +710,7 @@ func (opc *optPlanningCtx) chooseValidPreparedMemo(ctx context.Context) (*memo.M
 
 	// NOTE: The generic or base memos returned below could be nil if they have
 	// not yet been built.
-	if opc.chooseGenericPlan() {
+	if opc.chooseGenericPlan(ctx) {
 		return prep.GenericMemo, nil
 	}
 	return prep.BaseMemo, nil
@@ -775,7 +779,7 @@ func (opc *optPlanningCtx) fetchPreparedMemo(ctx context.Context) (_ *memo.Memo,
 			prep.Costs.SetGeneric(newMemo.RootExpr().Cost())
 			// Now that the cost of the generic plan is known, we need to
 			// re-evaluate the decision to use a generic or custom plan.
-			if !opc.chooseGenericPlan() {
+			if !opc.chooseGenericPlan(ctx) {
 				// The generic plan that we just built is too expensive, so we need
 				// to build a custom plan. We recursively call fetchPreparedMemo in
 				// case we have a custom plan that can be reused as a starting point

pkg/sql/prep/statement.go

@@ -7,6 +7,8 @@ package prep
 
 import (
 	"context"
+	"fmt"
+	"strings"
 	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/sql/opt/memo"
@@ -213,6 +215,42 @@ func (p *planCosts) avgCustom() memo.Cost {
 	return memo.Cost{C: sum / float64(p.custom.length)}
 }
 
+// Summary returns a single-line string summarizing the custom and generic plan
+// costs and full scan counts. The format for custom costs is:
+//
+//	average_custom_cost [num_custom_costs]{custom_cost_0:full_scan_count ...}
+//
+// The format for generic costs is:
+//
+//	generic_cost:generic_full_scan_count
+//
+// A full example:
+//
+//	custom costs: 1.23 [3]{1.23:0 1.23:0 1.23:0}, generic cost: 4.56:1
+func (p *planCosts) Summary() string {
+	var sb strings.Builder
+	sb.WriteString("custom costs: ")
+	if p.custom.length > 0 {
+		sb.WriteString(fmt.Sprintf("%.9g [%d]{", p.avgCustom().C, p.custom.length))
+		for i := 0; i < p.custom.length; i++ {
+			if i > 0 {
+				sb.WriteByte(' ')
+			}
+			sb.WriteString(fmt.Sprintf("%.9g:%d", p.custom.costs[i].C, p.custom.costs[i].FullScanCount()))
+		}
+		sb.WriteByte('}')
+	} else {
+		sb.WriteString("none")
+	}
+	sb.WriteString(", generic cost: ")
+	if p.HasGeneric() {
+		sb.WriteString(fmt.Sprintf("%.9g:%d", p.generic.C, p.generic.FullScanCount()))
+	} else {
+		sb.WriteString("none")
+	}
+	return sb.String()
+}
+
 // Reset clears any previously set costs.
 func (p *planCosts) Reset() {
 	p.generic = memo.Cost{C: 0}