Skip to content

Commit 6988ee2

Browse files
coffeegodddcoffeegoddd
committed
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.
1 parent e24a6e8 commit 6988ee2

File tree

4 files changed

+112
-46
lines changed

4 files changed

+112
-46
lines changed

‎engine.go‎

Lines changed: 24 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -446,14 +446,21 @@ func (e *Engine) QueryWithBindings(ctx *sql.Context, query string, parsed sqlpar
446446
return nil, nil, nil, err
447447
}
448448

449-
iter, err := e.Analyzer.ExecBuilder.Build(ctx, analyzed, nil)
449+
ctx.GetLogger().WithField("planNodeType", fmt.Sprintf("%T", analyzed)).Debug("building exec iterator")
450+
iter, err := e.Analyzer.ExecBuilder.Build(ctx, analyzed, nil)
450451
if err != nil {
452+
ctx.GetLogger().WithError(err).Debug("exec builder returned error")
451453
err2 := clearAutocommitTransaction(ctx)
452454
if err2 != nil {
453455
return nil, nil, nil, errors.Wrap(err, "unable to clear autocommit transaction: "+err2.Error())
454456
}
455457
return nil, nil, nil, err
456458
}
459+
if iter == nil {
460+
ctx.GetLogger().Debug("exec builder returned nil iterator")
461+
} else {
462+
ctx.GetLogger().WithField("iterType", fmt.Sprintf("%T", iter)).Debug("built exec iterator")
463+
}
457464

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

495-
iter, err := e.Analyzer.ExecBuilder.Build(ctx, plan, nil)
502+
ctx.GetLogger().WithField("planNodeType", fmt.Sprintf("%T", plan)).Debug("building exec iterator")
503+
iter, err := e.Analyzer.ExecBuilder.Build(ctx, plan, nil)
496504
if err != nil {
505+
ctx.GetLogger().WithError(err).Debug("exec builder returned error")
497506
err2 := clearAutocommitTransaction(ctx)
498507
if err2 != nil {
499508
return nil, nil, nil, errors.Wrap(err, "unable to clear autocommit transaction: "+err2.Error())
500509
}
501510
return nil, nil, nil, err
502511
}
512+
if iter == nil {
513+
ctx.GetLogger().Debug("exec builder returned nil iterator")
514+
} else {
515+
ctx.GetLogger().WithField("iterType", fmt.Sprintf("%T", iter)).Debug("built exec iterator")
516+
}
503517

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

844858
// Build an iterator to execute the event body
845-
iter, err := e.Analyzer.ExecBuilder.Build(ctx, definitionNode, nil)
859+
ctx.GetLogger().WithField("planNodeType", fmt.Sprintf("%T", definitionNode)).Debug("building exec iterator")
860+
iter, err := e.Analyzer.ExecBuilder.Build(ctx, definitionNode, nil)
846861
if err != nil {
862+
ctx.GetLogger().WithError(err).Debug("exec builder returned error")
847863
clearAutocommitErr := clearAutocommitTransaction(ctx)
848864
if clearAutocommitErr != nil {
849865
return clearAutocommitErr
850866
}
851867
return err
852868
}
869+
if iter == nil {
870+
ctx.GetLogger().Debug("exec builder returned nil iterator")
871+
} else {
872+
ctx.GetLogger().WithField("iterType", fmt.Sprintf("%T", iter)).Debug("built exec iterator")
873+
}
853874

854875
iter, _, err = rowexec.FinalizeIters(ctx, definitionNode, nil, iter)
855876
if err != nil {

‎sql/rowexec/builder.go‎

Lines changed: 23 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -15,10 +15,11 @@
1515
package rowexec
1616

1717
import (
18-
"runtime/trace"
18+
"fmt"
19+
"runtime/trace"
1920

20-
"github.com/dolthub/go-mysql-server/sql"
21-
"github.com/dolthub/go-mysql-server/sql/plan"
21+
"github.com/dolthub/go-mysql-server/sql"
22+
"github.com/dolthub/go-mysql-server/sql/plan"
2223
)
2324

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

3839
func (b *BaseBuilder) Build(ctx *sql.Context, n sql.Node, r sql.Row) (sql.RowIter, error) {
3940
defer trace.StartRegion(ctx, "ExecBuilder.Build").End()
40-
return b.buildNodeExec(ctx, n, r)
41+
logger := ctx.GetLogger().WithField("nodeType", fmt.Sprintf("%T", n))
42+
if b.override != nil {
43+
logger = logger.WithField("override", true)
44+
} else {
45+
logger = logger.WithField("override", false)
46+
}
47+
logger.Debug("building RowIter for node")
48+
49+
iter, err := b.buildNodeExec(ctx, n, r)
50+
if err != nil {
51+
logger.WithError(err).Debug("buildNodeExec returned error")
52+
return nil, err
53+
}
54+
if iter == nil {
55+
logger.Debug("buildNodeExec returned nil iterator")
56+
return nil, nil
57+
}
58+
logger.WithField("iterType", fmt.Sprintf("%T", iter)).Debug("built iterator for node")
59+
return iter, nil
4160
}
4261

4362
func NewOverrideBuilder(override sql.NodeExecBuilder) sql.NodeExecBuilder {

‎sql/rowexec/merge_join.go‎

Lines changed: 36 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -15,13 +15,14 @@
1515
package rowexec
1616

1717
import (
18-
"errors"
19-
"io"
18+
"errors"
19+
"fmt"
20+
"io"
2021

21-
"github.com/dolthub/go-mysql-server/sql/plan"
22+
"github.com/dolthub/go-mysql-server/sql/plan"
2223

23-
"github.com/dolthub/go-mysql-server/sql"
24-
"github.com/dolthub/go-mysql-server/sql/expression"
24+
"github.com/dolthub/go-mysql-server/sql"
25+
"github.com/dolthub/go-mysql-server/sql/expression"
2526
)
2627

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

50+
ctx.GetLogger().WithFields(map[string]any{
51+
"joinOp": fmt.Sprintf("%v", j.Op),
52+
"isReversed": j.IsReversed,
53+
"scopeLen": j.ScopeLen,
54+
"leftSchemaLen": len(j.Left().Schema()),
55+
"rightSchemaLen": len(j.Right().Schema()),
56+
"filterIsNil": j.Filter == nil,
57+
"leftIterType": fmt.Sprintf("%T", l),
58+
"rightIterType": fmt.Sprintf("%T", r),
59+
}).Debug("constructed merge join child iterators")
60+
4961
fullRow := make(sql.Row, len(row)+len(j.Left().Schema())+len(j.Right().Schema()))
5062
fullRow[0] = row
5163
if len(row) > 0 {
@@ -55,21 +67,23 @@ func newMergeJoinIter(ctx *sql.Context, b sql.NodeExecBuilder, j *plan.JoinNode,
5567
// a merge join's first filter provides direction information
5668
// for which iter to update next
5769
filters := expression.SplitConjunction(j.Filter)
58-
cmp, ok := filters[0].(expression.Comparer)
70+
cmp, ok := filters[0].(expression.Comparer)
5971
if !ok {
6072
if equality, ok := filters[0].(expression.Equality); ok {
6173
cmp, err = equality.ToComparer()
6274
if err != nil {
6375
return nil, err
6476
}
6577
} else {
66-
return nil, sql.ErrMergeJoinExpectsComparerFilters.New(filters[0])
78+
ctx.GetLogger().WithField("firstFilterType", fmt.Sprintf("%T", filters[0])).Debug("merge join expected comparer filter")
79+
return nil, sql.ErrMergeJoinExpectsComparerFilters.New(filters[0])
6780
}
6881
}
6982

70-
if len(filters) == 0 {
71-
return nil, sql.ErrNoJoinFilters.New()
72-
}
83+
if len(filters) == 0 {
84+
ctx.GetLogger().Debug("merge join constructed with zero filters")
85+
return nil, sql.ErrNoJoinFilters.New()
86+
}
7387

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

@@ -208,9 +223,10 @@ func (i *mergeJoinIter) Next(ctx *sql.Context) (sql.Row, error) {
208223
} else {
209224
nextState = msCompare
210225
}
211-
case msCompare:
212-
res, err = i.cmp.Compare(ctx, i.fullRow)
213-
if expression.ErrNilOperand.Is(err) {
226+
case msCompare:
227+
res, err = i.cmp.Compare(ctx, i.fullRow)
228+
if expression.ErrNilOperand.Is(err) {
229+
ctx.GetLogger().Debug("merge join comparer produced nil operand; rejecting null")
214230
nextState = msRejectNull
215231
break
216232
} else if err != nil {
@@ -434,6 +450,7 @@ func (i *mergeJoinIter) initIters(ctx *sql.Context) error {
434450
}
435451
i.init = true
436452
i.resetMatchState()
453+
ctx.GetLogger().Debug("merge join iters initialized")
437454
return nil
438455
}
439456

@@ -509,13 +526,14 @@ func (i *mergeJoinIter) incLeft(ctx *sql.Context) error {
509526
i.leftMatched = false
510527
var row sql.Row
511528
var err error
512-
if i.leftPeek != nil {
529+
if i.leftPeek != nil {
513530
row = i.leftPeek
514531
i.leftPeek = nil
515532
} else {
516533
row, err = i.left.Next(ctx)
517534
if errors.Is(err, io.EOF) {
518535
i.leftExhausted = true
536+
ctx.GetLogger().Trace("merge join left iterator exhausted")
519537
return nil
520538
} else if err != nil {
521539
return err
@@ -526,21 +544,22 @@ func (i *mergeJoinIter) incLeft(ctx *sql.Context) error {
526544
for j, v := range row {
527545
i.fullRow[off+j] = v
528546
}
529-
547+
ctx.GetLogger().Trace("merge join advanced left iterator")
530548
return nil
531549
}
532550

533551
// incRight updates |i.fullRow|'s right row
534552
func (i *mergeJoinIter) incRight(ctx *sql.Context) error {
535553
var row sql.Row
536554
var err error
537-
if i.rightPeek != nil {
555+
if i.rightPeek != nil {
538556
row = i.rightPeek
539557
i.rightPeek = nil
540558
} else {
541559
row, err = i.right.Next(ctx)
542560
if errors.Is(err, io.EOF) {
543561
i.rightExhausted = true
562+
ctx.GetLogger().Trace("merge join right iterator exhausted")
544563
return nil
545564
} else if err != nil {
546565
return err
@@ -551,7 +570,7 @@ func (i *mergeJoinIter) incRight(ctx *sql.Context) error {
551570
for j, v := range row {
552571
i.fullRow[off+j] = v
553572
}
554-
573+
ctx.GetLogger().Trace("merge join advanced right iterator")
555574
return nil
556575
}
557576

‎sql/rowexec/rel.go‎

Lines changed: 29 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -15,26 +15,26 @@
1515
package rowexec
1616

1717
import (
18-
"errors"
19-
"fmt"
20-
"io"
21-
"os"
22-
"path/filepath"
23-
"reflect"
24-
"strings"
25-
26-
"github.com/dolthub/jsonpath"
27-
"github.com/shopspring/decimal"
28-
"go.opentelemetry.io/otel/attribute"
29-
"go.opentelemetry.io/otel/trace"
30-
31-
"github.com/dolthub/go-mysql-server/sql"
32-
"github.com/dolthub/go-mysql-server/sql/expression"
33-
"github.com/dolthub/go-mysql-server/sql/expression/function/aggregation"
34-
"github.com/dolthub/go-mysql-server/sql/expression/function/json"
35-
"github.com/dolthub/go-mysql-server/sql/iters"
36-
"github.com/dolthub/go-mysql-server/sql/plan"
37-
"github.com/dolthub/go-mysql-server/sql/types"
18+
"errors"
19+
"fmt"
20+
"io"
21+
"os"
22+
"path/filepath"
23+
"reflect"
24+
"strings"
25+
26+
"github.com/dolthub/jsonpath"
27+
"github.com/shopspring/decimal"
28+
"go.opentelemetry.io/otel/attribute"
29+
"go.opentelemetry.io/otel/trace"
30+
31+
"github.com/dolthub/go-mysql-server/sql"
32+
"github.com/dolthub/go-mysql-server/sql/expression"
33+
"github.com/dolthub/go-mysql-server/sql/expression/function/aggregation"
34+
"github.com/dolthub/go-mysql-server/sql/expression/function/json"
35+
"github.com/dolthub/go-mysql-server/sql/iters"
36+
"github.com/dolthub/go-mysql-server/sql/plan"
37+
"github.com/dolthub/go-mysql-server/sql/types"
3838
)
3939

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

310-
i, err := b.buildNodeExec(ctx, n.Child, row)
310+
i, err := b.buildNodeExec(ctx, n.Child, row)
311311
if err != nil {
312312
span.End()
313313
return nil, err
314314
}
315315

316+
if i == nil {
317+
ctx.GetLogger().WithField("nodeType", "Project").Debug("child iterator is nil")
318+
}
319+
316320
return sql.NewSpanIter(span, &ProjectIter{
317321
projs: n.Projections,
318322
canDefer: n.CanDefer,
@@ -475,11 +479,14 @@ func (b *BaseBuilder) buildLimit(ctx *sql.Context, n *plan.Limit, row sql.Row) (
475479
return nil, err
476480
}
477481

478-
childIter, err := b.buildNodeExec(ctx, n.Child, row)
482+
childIter, err := b.buildNodeExec(ctx, n.Child, row)
479483
if err != nil {
480484
span.End()
481485
return nil, err
482486
}
487+
if childIter == nil {
488+
ctx.GetLogger().WithField("nodeType", "Limit").Debug("child iterator is nil")
489+
}
483490
return sql.NewSpanIter(span, &iters.LimitIter{
484491
CalcFoundRows: n.CalcFoundRows,
485492
Limit: limit,

0 commit comments

Comments
 (0)