Skip to content
Open
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Next Next commit
rowexec: add debug logs for iterator build and merge join nils
Add debug-level logs in ExecBuilder.Build and Engine to trace iterator
construction and types. Add targeted merge join logs to capture child
iter types, filter/comparer assumptions, and nil-operand cases, improving
panic diagnostics surfaced by Dolt when running at debug level.
  • Loading branch information
coffeegoddd committed Oct 8, 2025
commit 6988ee28287f769f9f5d1c593ad70240ebade671
27 changes: 24 additions & 3 deletions engine.go
Original file line number Diff line number Diff line change
Expand Up @@ -446,14 +446,21 @@ func (e *Engine) QueryWithBindings(ctx *sql.Context, query string, parsed sqlpar
return nil, nil, nil, err
}

iter, err := e.Analyzer.ExecBuilder.Build(ctx, analyzed, nil)
ctx.GetLogger().WithField("planNodeType", fmt.Sprintf("%T", analyzed)).Debug("building exec iterator")
iter, err := e.Analyzer.ExecBuilder.Build(ctx, analyzed, nil)
if err != nil {
ctx.GetLogger().WithError(err).Debug("exec builder returned error")
err2 := clearAutocommitTransaction(ctx)
if err2 != nil {
return nil, nil, nil, errors.Wrap(err, "unable to clear autocommit transaction: "+err2.Error())
}
return nil, nil, nil, err
}
if iter == nil {
ctx.GetLogger().Debug("exec builder returned nil iterator")
} else {
ctx.GetLogger().WithField("iterType", fmt.Sprintf("%T", iter)).Debug("built exec iterator")
}

var schema sql.Schema
iter, schema, err = rowexec.FinalizeIters(ctx, analyzed, qFlags, iter)
Expand Down Expand Up @@ -492,14 +499,21 @@ func (e *Engine) PrepQueryPlanForExecution(ctx *sql.Context, _ string, plan sql.
return nil, nil, nil, err
}

iter, err := e.Analyzer.ExecBuilder.Build(ctx, plan, nil)
ctx.GetLogger().WithField("planNodeType", fmt.Sprintf("%T", plan)).Debug("building exec iterator")
iter, err := e.Analyzer.ExecBuilder.Build(ctx, plan, nil)
if err != nil {
ctx.GetLogger().WithError(err).Debug("exec builder returned error")
err2 := clearAutocommitTransaction(ctx)
if err2 != nil {
return nil, nil, nil, errors.Wrap(err, "unable to clear autocommit transaction: "+err2.Error())
}
return nil, nil, nil, err
}
if iter == nil {
ctx.GetLogger().Debug("exec builder returned nil iterator")
} else {
ctx.GetLogger().WithField("iterType", fmt.Sprintf("%T", iter)).Debug("built exec iterator")
}

var schema sql.Schema
iter, schema, err = rowexec.FinalizeIters(ctx, plan, qFlags, iter)
Expand Down Expand Up @@ -842,14 +856,21 @@ func (e *Engine) executeEvent(ctx *sql.Context, dbName, createEventStatement, us
definitionNode := createEventNode.DefinitionNode

// Build an iterator to execute the event body
iter, err := e.Analyzer.ExecBuilder.Build(ctx, definitionNode, nil)
ctx.GetLogger().WithField("planNodeType", fmt.Sprintf("%T", definitionNode)).Debug("building exec iterator")
iter, err := e.Analyzer.ExecBuilder.Build(ctx, definitionNode, nil)
if err != nil {
ctx.GetLogger().WithError(err).Debug("exec builder returned error")
clearAutocommitErr := clearAutocommitTransaction(ctx)
if clearAutocommitErr != nil {
return clearAutocommitErr
}
return err
}
if iter == nil {
ctx.GetLogger().Debug("exec builder returned nil iterator")
} else {
ctx.GetLogger().WithField("iterType", fmt.Sprintf("%T", iter)).Debug("built exec iterator")
}

iter, _, err = rowexec.FinalizeIters(ctx, definitionNode, nil, iter)
if err != nil {
Expand Down
27 changes: 23 additions & 4 deletions sql/rowexec/builder.go
Original file line number Diff line number Diff line change
Expand Up @@ -15,10 +15,11 @@
package rowexec

import (
"runtime/trace"
"fmt"
"runtime/trace"

"github.com/dolthub/go-mysql-server/sql"
"github.com/dolthub/go-mysql-server/sql/plan"
"github.com/dolthub/go-mysql-server/sql"
"github.com/dolthub/go-mysql-server/sql/plan"
)

var DefaultBuilder = &BaseBuilder{}
Expand All @@ -37,7 +38,25 @@ type BaseBuilder struct {

func (b *BaseBuilder) Build(ctx *sql.Context, n sql.Node, r sql.Row) (sql.RowIter, error) {
defer trace.StartRegion(ctx, "ExecBuilder.Build").End()
return b.buildNodeExec(ctx, n, r)
logger := ctx.GetLogger().WithField("nodeType", fmt.Sprintf("%T", n))
if b.override != nil {
logger = logger.WithField("override", true)
} else {
logger = logger.WithField("override", false)
}
logger.Debug("building RowIter for node")

iter, err := b.buildNodeExec(ctx, n, r)
if err != nil {
logger.WithError(err).Debug("buildNodeExec returned error")
return nil, err
}
if iter == nil {
logger.Debug("buildNodeExec returned nil iterator")
return nil, nil
}
logger.WithField("iterType", fmt.Sprintf("%T", iter)).Debug("built iterator for node")
return iter, nil
}

func NewOverrideBuilder(override sql.NodeExecBuilder) sql.NodeExecBuilder {
Expand Down
53 changes: 36 additions & 17 deletions sql/rowexec/merge_join.go
Original file line number Diff line number Diff line change
Expand Up @@ -15,13 +15,14 @@
package rowexec

import (
"errors"
"io"
"errors"
"fmt"
"io"

"github.com/dolthub/go-mysql-server/sql/plan"
"github.com/dolthub/go-mysql-server/sql/plan"

"github.com/dolthub/go-mysql-server/sql"
"github.com/dolthub/go-mysql-server/sql/expression"
"github.com/dolthub/go-mysql-server/sql"
"github.com/dolthub/go-mysql-server/sql/expression"
)

// NewMergeJoin returns a node that performs a presorted merge join on
Expand All @@ -46,6 +47,17 @@ func newMergeJoinIter(ctx *sql.Context, b sql.NodeExecBuilder, j *plan.JoinNode,
return nil, err
}

ctx.GetLogger().WithFields(map[string]any{
"joinOp": fmt.Sprintf("%v", j.Op),
"isReversed": j.IsReversed,
"scopeLen": j.ScopeLen,
"leftSchemaLen": len(j.Left().Schema()),
"rightSchemaLen": len(j.Right().Schema()),
"filterIsNil": j.Filter == nil,
"leftIterType": fmt.Sprintf("%T", l),
"rightIterType": fmt.Sprintf("%T", r),
}).Debug("constructed merge join child iterators")

fullRow := make(sql.Row, len(row)+len(j.Left().Schema())+len(j.Right().Schema()))
fullRow[0] = row
if len(row) > 0 {
Expand All @@ -55,21 +67,23 @@ func newMergeJoinIter(ctx *sql.Context, b sql.NodeExecBuilder, j *plan.JoinNode,
// a merge join's first filter provides direction information
// for which iter to update next
filters := expression.SplitConjunction(j.Filter)
cmp, ok := filters[0].(expression.Comparer)
cmp, ok := filters[0].(expression.Comparer)
if !ok {
if equality, ok := filters[0].(expression.Equality); ok {
cmp, err = equality.ToComparer()
if err != nil {
return nil, err
}
} else {
return nil, sql.ErrMergeJoinExpectsComparerFilters.New(filters[0])
ctx.GetLogger().WithField("firstFilterType", fmt.Sprintf("%T", filters[0])).Debug("merge join expected comparer filter")
return nil, sql.ErrMergeJoinExpectsComparerFilters.New(filters[0])
}
}

if len(filters) == 0 {
return nil, sql.ErrNoJoinFilters.New()
}
if len(filters) == 0 {
ctx.GetLogger().Debug("merge join constructed with zero filters")
return nil, sql.ErrNoJoinFilters.New()
}

var iter sql.RowIter = &mergeJoinIter{
left: l,
Expand All @@ -84,6 +98,7 @@ func newMergeJoinIter(ctx *sql.Context, b sql.NodeExecBuilder, j *plan.JoinNode,
rightRowLen: len(j.Right().Schema()),
isReversed: j.IsReversed,
}
ctx.GetLogger().WithField("iterType", fmt.Sprintf("%T", iter)).Debug("created merge join iter")
return iter, nil
}

Expand Down Expand Up @@ -208,9 +223,10 @@ func (i *mergeJoinIter) Next(ctx *sql.Context) (sql.Row, error) {
} else {
nextState = msCompare
}
case msCompare:
res, err = i.cmp.Compare(ctx, i.fullRow)
if expression.ErrNilOperand.Is(err) {
case msCompare:
res, err = i.cmp.Compare(ctx, i.fullRow)
if expression.ErrNilOperand.Is(err) {
ctx.GetLogger().Debug("merge join comparer produced nil operand; rejecting null")
nextState = msRejectNull
break
} else if err != nil {
Expand Down Expand Up @@ -434,6 +450,7 @@ func (i *mergeJoinIter) initIters(ctx *sql.Context) error {
}
i.init = true
i.resetMatchState()
ctx.GetLogger().Debug("merge join iters initialized")
return nil
}

Expand Down Expand Up @@ -509,13 +526,14 @@ func (i *mergeJoinIter) incLeft(ctx *sql.Context) error {
i.leftMatched = false
var row sql.Row
var err error
if i.leftPeek != nil {
if i.leftPeek != nil {
row = i.leftPeek
i.leftPeek = nil
} else {
row, err = i.left.Next(ctx)
if errors.Is(err, io.EOF) {
i.leftExhausted = true
ctx.GetLogger().Trace("merge join left iterator exhausted")
return nil
} else if err != nil {
return err
Expand All @@ -526,21 +544,22 @@ func (i *mergeJoinIter) incLeft(ctx *sql.Context) error {
for j, v := range row {
i.fullRow[off+j] = v
}

ctx.GetLogger().Trace("merge join advanced left iterator")
return nil
}

// incRight updates |i.fullRow|'s right row
func (i *mergeJoinIter) incRight(ctx *sql.Context) error {
var row sql.Row
var err error
if i.rightPeek != nil {
if i.rightPeek != nil {
row = i.rightPeek
i.rightPeek = nil
} else {
row, err = i.right.Next(ctx)
if errors.Is(err, io.EOF) {
i.rightExhausted = true
ctx.GetLogger().Trace("merge join right iterator exhausted")
return nil
} else if err != nil {
return err
Expand All @@ -551,7 +570,7 @@ func (i *mergeJoinIter) incRight(ctx *sql.Context) error {
for j, v := range row {
i.fullRow[off+j] = v
}

ctx.GetLogger().Trace("merge join advanced right iterator")
return nil
}

Expand Down
51 changes: 29 additions & 22 deletions sql/rowexec/rel.go
Original file line number Diff line number Diff line change
Expand Up @@ -15,26 +15,26 @@
package rowexec

import (
"errors"
"fmt"
"io"
"os"
"path/filepath"
"reflect"
"strings"

"github.com/dolthub/jsonpath"
"github.com/shopspring/decimal"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/trace"

"github.com/dolthub/go-mysql-server/sql"
"github.com/dolthub/go-mysql-server/sql/expression"
"github.com/dolthub/go-mysql-server/sql/expression/function/aggregation"
"github.com/dolthub/go-mysql-server/sql/expression/function/json"
"github.com/dolthub/go-mysql-server/sql/iters"
"github.com/dolthub/go-mysql-server/sql/plan"
"github.com/dolthub/go-mysql-server/sql/types"
"errors"
"fmt"
"io"
"os"
"path/filepath"
"reflect"
"strings"

"github.com/dolthub/jsonpath"
"github.com/shopspring/decimal"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/trace"

"github.com/dolthub/go-mysql-server/sql"
"github.com/dolthub/go-mysql-server/sql/expression"
"github.com/dolthub/go-mysql-server/sql/expression/function/aggregation"
"github.com/dolthub/go-mysql-server/sql/expression/function/json"
"github.com/dolthub/go-mysql-server/sql/iters"
"github.com/dolthub/go-mysql-server/sql/plan"
"github.com/dolthub/go-mysql-server/sql/types"
)

func (b *BaseBuilder) buildTopN(ctx *sql.Context, n *plan.TopN, row sql.Row) (sql.RowIter, error) {
Expand Down Expand Up @@ -307,12 +307,16 @@ func (b *BaseBuilder) buildProject(ctx *sql.Context, n *plan.Project, row sql.Ro
attribute.Int("projections", len(n.Projections)),
))

i, err := b.buildNodeExec(ctx, n.Child, row)
i, err := b.buildNodeExec(ctx, n.Child, row)
if err != nil {
span.End()
return nil, err
}

if i == nil {
ctx.GetLogger().WithField("nodeType", "Project").Debug("child iterator is nil")
}

return sql.NewSpanIter(span, &ProjectIter{
projs: n.Projections,
canDefer: n.CanDefer,
Expand Down Expand Up @@ -475,11 +479,14 @@ func (b *BaseBuilder) buildLimit(ctx *sql.Context, n *plan.Limit, row sql.Row) (
return nil, err
}

childIter, err := b.buildNodeExec(ctx, n.Child, row)
childIter, err := b.buildNodeExec(ctx, n.Child, row)
if err != nil {
span.End()
return nil, err
}
if childIter == nil {
ctx.GetLogger().WithField("nodeType", "Limit").Debug("child iterator is nil")
}
return sql.NewSpanIter(span, &iters.LimitIter{
CalcFoundRows: n.CalcFoundRows,
Limit: limit,
Expand Down
Loading