Merge cockroachdb#27397

27397: sql: detail the planning phases in traces r=knz a=knz Needed for cockroachdb#27396. Prior to this patch, it was impossible to observe in a trace why the optimizer would fall back to the heuristic planner. This patch fixes the situation by adding the necessary tracing events. Release note: None Co-authored-by: Raphael 'kena' Poss <[email protected]>
tbg · Jul 11, 2018 · 7a263ea · 7a263ea
2 parents 8665be7 + fc6eb83
commit 7a263ea
Show file tree

Hide file tree

Showing 2 changed files with 13 additions and 0 deletions.
diff --git a/pkg/sql/plan.go b/pkg/sql/plan.go
@@ -294,6 +294,8 @@ func (p *planner) makePlan(ctx context.Context, stmt Statement) error {
 	// Reinitialize.
 	p.curPlan = planTop{AST: stmt.AST}
 
+	log.VEvent(ctx, 1, "heuristic planner starts")
+
 	var err error
 	p.curPlan.plan, err = p.newPlan(ctx, stmt.AST, nil /*desiredTypes*/)
 	if err != nil {
@@ -321,13 +323,17 @@ func (p *planner) makePlan(ctx context.Context, stmt Statement) error {
 		return err
 	}
 
+	log.VEvent(ctx, 1, "heuristic planner optimizes plan")
+
 	needed := allColumns(p.curPlan.plan)
 	p.curPlan.plan, err = p.optimizePlan(ctx, p.curPlan.plan, needed)
 	if err != nil {
 		p.curPlan.close(ctx)
 		return err
 	}
 
+	log.VEvent(ctx, 1, "heuristic planner optimizes subqueries")
+
 	// Now do the same work for all sub-queries.
 	for i := range p.curPlan.subqueryPlans {
 		if err := p.optimizeSubquery(ctx, &p.curPlan.subqueryPlans[i]); err != nil {

diff --git a/pkg/sql/planner.go b/pkg/sql/planner.go
@@ -542,20 +542,27 @@ func (p *planner) optionallyUseOptimizer(
 	ctx context.Context, sd sessiondata.SessionData, stmt Statement,
 ) (bool, error) {
 	if sd.OptimizerMode == sessiondata.OptimizerOff {
+		log.VEvent(ctx, 1, "optimizer disabled")
 		return false, nil
 	}
 	// TODO(radu): for now, the experimental force lookup join flag does not work
 	// with the optimizer. Turn the optimizer off for the query so the flag can
 	// still function.
 	if sd.OptimizerMode != sessiondata.OptimizerAlways && sd.LookupJoinEnabled {
+		log.VEvent(ctx, 1, "lookup join requested; not using optimizer")
 		return false, nil
 	}
 
+	log.VEvent(ctx, 1, "generating optimizer plan")
+
 	err := p.makeOptimizerPlan(ctx, stmt)
 	if err == nil {
+		log.VEvent(ctx, 1, "optimizer plan succeeded")
 		return true, nil
 	}
+	log.VEventf(ctx, 1, "optimizer plan failed: %v", err)
 	if canFallbackFromOpt(err, sd.OptimizerMode, stmt) {
+		log.VEvent(ctx, 1, "optimizer falls back on heuristic planner")
 		return false, nil
 	}
 	return false, err