Skip to content

rowexec: add debug logs for iterator build and merge join nils #3257

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 2 commits into
base: main
Choose a base branch
from
+69 −3
Open

rowexec: add debug logs for iterator build and merge join nils #3257

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
6988ee2
rowexec: add debug logs for iterator build and merge join nils
coffeegoddd Oct 8, 2025
d8190ef
[ga-format-pr] Run ./format_repo.sh to fix formatting
coffeegoddd Oct 8, 2025
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
21 changes: 21 additions & 0 deletions engine.go
View file
Open in desktop
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
}

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
}

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
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
21 changes: 20 additions & 1 deletion sql/rowexec/builder.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
package rowexec

import (
"fmt"
"runtime/trace"

"github.com/dolthub/go-mysql-server/sql"
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
23 changes: 21 additions & 2 deletions sql/rowexec/merge_join.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ package rowexec

import (
"errors"
"fmt"
"io"

"github.com/dolthub/go-mysql-server/sql/plan"
Expand Down Expand Up @@ -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 @@ -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()
}

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 @@ -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 {
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 @@ -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
Expand All @@ -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
}

Expand All @@ -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
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
7 changes: 7 additions & 0 deletions sql/rowexec/rel.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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,
Expand Down