I am working on debugging an intermittent and possible jvm bug where I am getting the wrong plan in PredicatePushdownTest. Attached are the passing and failing plans. Clearly the failing plan is more expensive. The test sets derby.optimizer.noTimeout so it should come up with the lower cost plan each time. My question is where in the code should I look for possible problems with plan selection. I can't reproduce in the debugger so will need to just use println's to diagnose the problem.

Thanks for any suggestions.

Kathey


Statement Name: 
        null
Statement Text: 
        select count(*) from (select * from t1 union select * from t3) x1 (c, 
d), (select * from t2 union select * from t4) x2 (e, f) where x1.c = x2.e
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: 0
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : null
End Execution Timestamp : null
Statement Execution Plan Text: 
Project-Restrict ResultSet (13):
Number of opens = 1
Rows seen = 1
Rows filtered = 0
restriction = false
projection = true
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count:            1.00
        optimizer estimated cost: 2600186392242.22

Source result set:
        Scalar Aggregate ResultSet:
        Number of opens = 1
        Rows input = 103
                constructor time (milliseconds) = 0
                open time (milliseconds) = 0
                next time (milliseconds) = 0
                close time (milliseconds) = 0
                optimizer estimated row count:     26969766.07
                optimizer estimated cost:     53265756.92

        Index Key Optimization = false
        Source result set:
                Project-Restrict ResultSet (12):
                Number of opens = 1
                Rows seen = 103
                Rows filtered = 0
                restriction = false
                projection = true
                        constructor time (milliseconds) = 0
                        open time (milliseconds) = 0
                        next time (milliseconds) = 0
                        close time (milliseconds) = 0
                        restriction time (milliseconds) = 0
                        projection time (milliseconds) = 0
                        optimizer estimated row count:     26969766.07
                        optimizer estimated cost:     53265756.92

                Source result set:
                        Nested Loop Join ResultSet:
                        Number of opens = 1
                        Rows seen from the left = 97
                        Rows seen from the right = 103
                        Rows filtered = 0
                        Rows returned = 103
                                constructor time (milliseconds) = 0
                                open time (milliseconds) = 0
                                next time (milliseconds) = 0
                                close time (milliseconds) = 0
                                optimizer estimated row count:     26969766.07
                                optimizer estimated cost:     53265756.92

                        Left result set:
                                Sort ResultSet:
                                Number of opens = 1
                                Rows input = 48817
                                Rows returned = 97
                                Eliminate duplicates = true
                                In sorted order = false
                                Sort information: 
                                        Number of rows input=48817
                                        Number of rows output=97
                                        Sort type=internal
                                        constructor time (milliseconds) = 0
                                        open time (milliseconds) = 0
                                        next time (milliseconds) = 0
                                        close time (milliseconds) = 0
                                        optimizer estimated row count:        
48827.00
                                        optimizer estimated cost:        
12712.92

                                Source result set:
                                        Union ResultSet:
                                        Number of opens = 1
                                        Rows seen from the left = 5
                                        Rows seen from the right = 48812
                                        Rows returned = 48817
                                                constructor time (milliseconds) 
= 0
                                                open time (milliseconds) = 0
                                                next time (milliseconds) = 0
                                                close time (milliseconds) = 0
                                                optimizer estimated row count:  
      48827.00
                                                optimizer estimated cost:       
 12712.92

                                        Left result set:
                                                Table Scan ResultSet for T2 at 
read committed isolation level using share row locking chosen by the optimizer
                                                Number of opens = 1
                                                Rows seen = 5
                                                Rows filtered = 0
                                                Fetch Size = 1
                                                        constructor time 
(milliseconds) = 0
                                                        open time 
(milliseconds) = 0
                                                        next time 
(milliseconds) = 0
                                                        close time 
(milliseconds) = 0
                                                        next time in 
milliseconds/row = 0

                                                scan information: 
                                                        Bit set of columns 
fetched=All
                                                        Number of columns 
fetched=2
                                                        Number of pages 
visited=2
                                                        Number of rows 
qualified=5
                                                        Number of rows visited=5
                                                        Scan type=heap
                                                        start position: 
null                                                    stop position: 
null                                                    qualifiers:
None
                                                        optimizer estimated row 
count:           10.00
                                                        optimizer estimated 
cost:           69.48

                                        Right result set:
                                                Table Scan ResultSet for T4 at 
read committed isolation level using share row locking chosen by the optimizer
                                                Number of opens = 1
                                                Rows seen = 48812
                                                Rows filtered = 0
                                                Fetch Size = 1
                                                        constructor time 
(milliseconds) = 0
                                                        open time 
(milliseconds) = 0
                                                        next time 
(milliseconds) = 0
                                                        close time 
(milliseconds) = 0
                                                        next time in 
milliseconds/row = 0

                                                scan information: 
                                                        Bit set of columns 
fetched=All
                                                        Number of columns 
fetched=2
                                                        Number of pages 
visited=389
                                                        Number of rows 
qualified=48812
                                                        Number of rows 
visited=48812
                                                        Scan type=heap
                                                        start position: 
null                                                    stop position: 
null                                                    qualifiers:
None
                                                        optimizer estimated row 
count:        48817.00
                                                        optimizer estimated 
cost:        12643.44



                        Right result set:
                                Sort ResultSet:
                                Number of opens = 97
                                Rows input = 54583
                                Rows returned = 103
                                Eliminate duplicates = true
                                In sorted order = false
                                Sort information: 
                                        Number of rows input=987
                                        Number of rows output=1
                                        Sort type=internal
                                        constructor time (milliseconds) = 0
                                        open time (milliseconds) = 0
                                        next time (milliseconds) = 0
                                        close time (milliseconds) = 0
                                        optimizer estimated row count:     
26969766.07
                                        optimizer estimated cost:     
53253044.00

                                Source result set:
                                        Union ResultSet:
                                        Number of opens = 97
                                        Rows seen from the left = 7
                                        Rows seen from the right = 54576
                                        Rows returned = 54583
                                                constructor time (milliseconds) 
= 0
                                                open time (milliseconds) = 0
                                                next time (milliseconds) = 0
                                                close time (milliseconds) = 0
                                                optimizer estimated row count:  
   26969766.07
                                                optimizer estimated cost:     
53253044.00

                                        Left result set:
                                                Table Scan ResultSet for T1 at 
read committed isolation level using share row locking chosen by the optimizer
                                                Number of opens = 97
                                                Rows seen = 7
                                                Rows filtered = 0
                                                Fetch Size = 1
                                                        constructor time 
(milliseconds) = 0
                                                        open time 
(milliseconds) = 0
                                                        next time 
(milliseconds) = 0
                                                        close time 
(milliseconds) = 0
                                                        next time in 
milliseconds/row = 0

                                                scan information: 
                                                        Bit set of columns 
fetched=All
                                                        Number of columns 
fetched=2
                                                        Number of pages 
visited=2
                                                        Number of rows 
qualified=0
                                                        Number of rows visited=5
                                                        Scan type=heap
                                                        start position: 
null                                                    stop position: 
null                                                    qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false

                                                        optimizer estimated row 
count:        48827.00
                                                        optimizer estimated 
cost:      3392499.96

                                        Right result set:
                                                Index Row to Base Row ResultSet 
for T3:
                                                Number of opens = 97
                                                Rows seen = 54576
                                                Columns accessed from heap = {1}
                                                        constructor time 
(milliseconds) = 0
                                                        open time 
(milliseconds) = 0
                                                        next time 
(milliseconds) = 0
                                                        close time 
(milliseconds) = 0
                                                        optimizer estimated row 
count:     26920939.07
                                                        optimizer estimated 
cost:     49860544.04

                                                        Index Scan ResultSet 
for T3 using index T3_IX1 at read committed isolation level using share row 
locking chosen by the optimizer
                                                        Number of opens = 97
                                                        Rows seen = 54576
                                                        Rows filtered = 0
                                                        Fetch Size = 1
                                                                constructor 
time (milliseconds) = 0
                                                                open time 
(milliseconds) = 0
                                                                next time 
(milliseconds) = 0
                                                                close time 
(milliseconds) = 0
                                                                next time in 
milliseconds/row = 0

                                                        scan information: 
                                                                Bit set of 
columns fetched=All
                                                                Number of 
columns fetched=2
                                                                Number of 
deleted rows visited=0
                                                                Number of pages 
visited=8
                                                                Number of rows 
qualified=987
                                                                Number of rows 
visited=987
                                                                Scan type=btree
                                                                Tree height=3
                                                                start position: 
        >= on first 1 column(s).
        Ordered null semantics on the following columns: 

                                                                stop position: 
        > on first 1 column(s).
        Ordered null semantics on the following columns: 

                                                                qualifiers:
None
                                                                optimizer 
estimated row count:     26920939.07
                                                                optimizer 
estimated cost:     49860544.04






used 101295 ms F
Time: 119.604
There was 1 failure:
1) 
test_predicatePushdown(org.apache.derbyTesting.functionTests.tests.lang.PredicatePushdownTest)junit.framework.AssertionFailedError:
 Expected Table Scan ResultSet for T3
        at 
org.apache.derbyTesting.functionTests.tests.lang.PredicatePushdownTest.test_predicatePushdown(PredicatePushdownTest.java:1373)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45)
        at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at 
org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:104)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at 
org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)

FAILURES!!!
Tests run: 1,  Failures: 1,  Errors: 0

Statement Name: 
        null
Statement Text: 
        select count(*) from (select * from t1 union select * from t3) x1 (c, 
d), (select * from t2 union select * from t4) x2 (e, f) where x1.c = x2.e
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: 0
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : null
End Execution Timestamp : null
Statement Execution Plan Text: 
Project-Restrict ResultSet (13):
Number of opens = 1
Rows seen = 1
Rows filtered = 0
restriction = false
projection = true
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count:            1.00
        optimizer estimated cost:    693678957.04

Source result set:
        Scalar Aggregate ResultSet:
        Number of opens = 1
        Rows input = 103
                constructor time (milliseconds) = 0
                open time (milliseconds) = 0
                next time (milliseconds) = 0
                close time (milliseconds) = 0
                optimizer estimated row count:        54594.00
                optimizer estimated cost:        26919.53

        Index Key Optimization = false
        Source result set:
                Project-Restrict ResultSet (12):
                Number of opens = 1
                Rows seen = 103
                Rows filtered = 0
                restriction = false
                projection = true
                        constructor time (milliseconds) = 0
                        open time (milliseconds) = 0
                        next time (milliseconds) = 0
                        close time (milliseconds) = 0
                        restriction time (milliseconds) = 0
                        projection time (milliseconds) = 0
                        optimizer estimated row count:        54594.00
                        optimizer estimated cost:        26919.53

                Source result set:
                        Hash Join ResultSet:
                        Number of opens = 1
                        Rows seen from the left = 97
                        Rows seen from the right = 103
                        Rows filtered = 0
                        Rows returned = 103
                                constructor time (milliseconds) = 0
                                open time (milliseconds) = 0
                                next time (milliseconds) = 0
                                close time (milliseconds) = 0
                                optimizer estimated row count:        54594.00
                                optimizer estimated cost:        26919.53

                        Left result set:
                                Sort ResultSet:
                                Number of opens = 1
                                Rows input = 48817
                                Rows returned = 97
                                Eliminate duplicates = true
                                In sorted order = false
                                Sort information: 
                                        Number of rows input=48817
                                        Number of rows output=97
                                        Sort type=internal
                                        constructor time (milliseconds) = 0
                                        open time (milliseconds) = 0
                                        next time (milliseconds) = 0
                                        close time (milliseconds) = 0
                                        optimizer estimated row count:        
48827.00
                                        optimizer estimated cost:        
12712.92

                                Source result set:
                                        Union ResultSet:
                                        Number of opens = 1
                                        Rows seen from the left = 5
                                        Rows seen from the right = 48812
                                        Rows returned = 48817
                                                constructor time (milliseconds) 
= 0
                                                open time (milliseconds) = 0
                                                next time (milliseconds) = 0
                                                close time (milliseconds) = 0
                                                optimizer estimated row count:  
      48827.00
                                                optimizer estimated cost:       
 12712.92

                                        Left result set:
                                                Table Scan ResultSet for T2 at 
read committed isolation level using share row locking chosen by the optimizer
                                                Number of opens = 1
                                                Rows seen = 5
                                                Rows filtered = 0
                                                Fetch Size = 1
                                                        constructor time 
(milliseconds) = 0
                                                        open time 
(milliseconds) = 0
                                                        next time 
(milliseconds) = 0
                                                        close time 
(milliseconds) = 0
                                                        next time in 
milliseconds/row = 0

                                                scan information: 
                                                        Bit set of columns 
fetched=All
                                                        Number of columns 
fetched=2
                                                        Number of pages 
visited=2
                                                        Number of rows 
qualified=5
                                                        Number of rows visited=5
                                                        Scan type=heap
                                                        start position: 
null                                                    stop position: 
null                                                    qualifiers:
None
                                                        optimizer estimated row 
count:           10.00
                                                        optimizer estimated 
cost:           69.48

                                        Right result set:
                                                Table Scan ResultSet for T4 at 
read committed isolation level using share row locking chosen by the optimizer
                                                Number of opens = 1
                                                Rows seen = 48812
                                                Rows filtered = 0
                                                Fetch Size = 1
                                                        constructor time 
(milliseconds) = 0
                                                        open time 
(milliseconds) = 0
                                                        next time 
(milliseconds) = 0
                                                        close time 
(milliseconds) = 0
                                                        next time in 
milliseconds/row = 0

                                                scan information: 
                                                        Bit set of columns 
fetched=All
                                                        Number of columns 
fetched=2
                                                        Number of pages 
visited=389
                                                        Number of rows 
qualified=48812
                                                        Number of rows 
visited=48812
                                                        Scan type=heap
                                                        start position: 
null                                                    stop position: 
null                                                    qualifiers:
None
                                                        optimizer estimated row 
count:        48817.00
                                                        optimizer estimated 
cost:        12643.44



                        Right result set:
                                Hash Table ResultSet (11):
                                Number of opens = 97
                                Hash table size = 100
                                Hash key is column number 0
                                Rows seen = 104
                                Rows filtered = 0
                                        constructor time (milliseconds) = 0
                                        open time (milliseconds) = 0
                                        next time (milliseconds) = 0
                                        close time (milliseconds) = 0
                                        optimizer estimated row count:        
54594.00
                                        optimizer estimated cost:    
693666244.12

                                        next time in milliseconds/row = 0

                                        next qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false

                                Source result set:
                                        Sort ResultSet:
                                        Number of opens = 1
                                        Rows input = 54584
                                        Rows returned = 104
                                        Eliminate duplicates = true
                                        In sorted order = false
                                        Sort information: 
                                                Number of rows input=54584
                                                Number of rows output=104
                                                Sort type=internal
                                                constructor time (milliseconds) 
= 0
                                                open time (milliseconds) = 0
                                                next time (milliseconds) = 0
                                                close time (milliseconds) = 0
                                                optimizer estimated row count:  
 2665661238.00
                                                optimizer estimated cost:    
693666244.12

                                        Source result set:
                                                Union ResultSet:
                                                Number of opens = 1
                                                Rows seen from the left = 5
                                                Rows seen from the right = 54579
                                                Rows returned = 54584
                                                        constructor time 
(milliseconds) = 0
                                                        open time 
(milliseconds) = 0
                                                        next time 
(milliseconds) = 0
                                                        close time 
(milliseconds) = 0
                                                        optimizer estimated row 
count:   2665661238.00
                                                        optimizer estimated 
cost:    693666244.12

                                                Left result set:
                                                        Table Scan ResultSet 
for T1 at read committed isolation level using share row locking chosen by the 
optimizer
                                                        Number of opens = 1
                                                        Rows seen = 5
                                                        Rows filtered = 0
                                                        Fetch Size = 1
                                                                constructor 
time (milliseconds) = 0
                                                                open time 
(milliseconds) = 0
                                                                next time 
(milliseconds) = 0
                                                                close time 
(milliseconds) = 0
                                                                next time in 
milliseconds/row = 0

                                                        scan information: 
                                                                Bit set of 
columns fetched=All
                                                                Number of 
columns fetched=2
                                                                Number of pages 
visited=2
                                                                Number of rows 
qualified=5
                                                                Number of rows 
visited=5
                                                                Scan type=heap
                                                                start position: 
null                                                            stop position: 
null                                                            qualifiers:
None
                                                                optimizer 
estimated row count:       488270.00
                                                                optimizer 
estimated cost:      3392499.96

                                                Right result set:
                                                        Table Scan ResultSet 
for T3 at read committed isolation level using share row locking chosen by the 
optimizer
                                                        Number of opens = 1
                                                        Rows seen = 54579
                                                        Rows filtered = 0
                                                        Fetch Size = 1
                                                                constructor 
time (milliseconds) = 0
                                                                open time 
(milliseconds) = 0
                                                                next time 
(milliseconds) = 0
                                                                close time 
(milliseconds) = 0
                                                                next time in 
milliseconds/row = 0

                                                        scan information: 
                                                                Bit set of 
columns fetched=All
                                                                Number of 
columns fetched=2
                                                                Number of pages 
visited=435
                                                                Number of rows 
qualified=54579
                                                                Number of rows 
visited=54579
                                                                Scan type=heap
                                                                start position: 
null                                                            stop position: 
null                                                            qualifiers:
None
                                                                optimizer 
estimated row count:   2665172968.00
                                                                optimizer 
estimated cost:    690273744.16

Reply via email to