diff --git a/engine.go b/engine.go index 1b9895e9f6..5eb81a14a5 100644 --- a/engine.go +++ b/engine.go @@ -446,14 +446,21 @@ func (e *Engine) QueryWithBindings(ctx *sql.Context, query string, parsed sqlpar return nil, nil, nil, err } + 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) @@ -492,14 +499,21 @@ func (e *Engine) PrepQueryPlanForExecution(ctx *sql.Context, _ string, plan sql. return nil, nil, nil, err } + 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) @@ -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 + 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 { diff --git a/sql/rowexec/builder.go b/sql/rowexec/builder.go index 9133b1c443..23e32aa959 100644 --- a/sql/rowexec/builder.go +++ b/sql/rowexec/builder.go @@ -15,6 +15,7 @@ package rowexec import ( + "fmt" "runtime/trace" "github.com/dolthub/go-mysql-server/sql" @@ -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 { diff --git a/sql/rowexec/merge_join.go b/sql/rowexec/merge_join.go index 1926697dda..7d861ff1b9 100644 --- a/sql/rowexec/merge_join.go +++ b/sql/rowexec/merge_join.go @@ -16,6 +16,7 @@ package rowexec import ( "errors" + "fmt" "io" "github.com/dolthub/go-mysql-server/sql/plan" @@ -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 { @@ -63,11 +75,13 @@ func newMergeJoinIter(ctx *sql.Context, b sql.NodeExecBuilder, j *plan.JoinNode, return nil, err } } else { + 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 { + ctx.GetLogger().Debug("merge join constructed with zero filters") return nil, sql.ErrNoJoinFilters.New() } @@ -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 } @@ -211,6 +226,7 @@ func (i *mergeJoinIter) Next(ctx *sql.Context) (sql.Row, error) { 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 { @@ -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 } @@ -516,6 +533,7 @@ func (i *mergeJoinIter) incLeft(ctx *sql.Context) error { 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 @@ -526,7 +544,7 @@ 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 } @@ -541,6 +559,7 @@ func (i *mergeJoinIter) incRight(ctx *sql.Context) error { 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 @@ -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 } diff --git a/sql/rowexec/rel.go b/sql/rowexec/rel.go index 8c60e6e023..d7f164b0d5 100644 --- a/sql/rowexec/rel.go +++ b/sql/rowexec/rel.go @@ -313,6 +313,10 @@ func (b *BaseBuilder) buildProject(ctx *sql.Context, n *plan.Project, row sql.Ro 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, @@ -480,6 +484,9 @@ func (b *BaseBuilder) buildLimit(ctx *sql.Context, n *plan.Limit, row sql.Row) ( 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,