Potential regression in spilled ORDER BY #16406

findepi · 2023-03-07T11:20:55Z

example from #16400 build https://github.com/trinodb/trino/actions/runs/4351418003/jobs/7603093117

Error:  Tests run: 3957, Failures: 2, Errors: 0, Skipped: 318, Time elapsed: 1,918.51 s <<< FAILURE! - in TestSuite
Error:  io.trino.tests.TestSpilledOrderByQueries.testOrderBy  Time elapsed: 0.165 s  <<< FAILURE!
java.lang.AssertionError: Execution of 'actual' query failed: SELECT orderstatus FROM orders ORDER BY orderstatus
	at org.testng.Assert.fail(Assert.java:83)
	at io.trino.testing.QueryAssertions.assertQuery(QueryAssertions.java:150)
	at io.trino.testing.QueryAssertions.assertQuery(QueryAssertions.java:106)
	at io.trino.testing.AbstractTestQueryFramework.assertQueryOrdered(AbstractTestQueryFramework.java:381)
	at io.trino.testing.AbstractTestQueryFramework.assertQueryOrdered(AbstractTestQueryFramework.java:371)
	at io.trino.testing.AbstractTestQueryFramework.assertQueryOrdered(AbstractTestQueryFramework.java:366)
	at io.trino.testing.AbstractTestOrderByQueries.testOrderBy(AbstractTestOrderByQueries.java:30)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:104)
	at org.testng.internal.Invoker.invokeMethod(Invoker.java:645)
	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:851)
	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1177)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:129)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:112)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: io.trino.testing.QueryFailedException: Index (0) is greater than or equal to list size (0)
	at io.trino.testing.AbstractTestingTrinoClient.execute(AbstractTestingTrinoClient.java:122)
	at io.trino.testing.DistributedQueryRunner.execute(DistributedQueryRunner.java:489)
	at io.trino.testing.QueryAssertions.assertQuery(QueryAssertions.java:147)
	... 18 more
	Suppressed: java.lang.Exception: SQL: SELECT orderstatus FROM orders ORDER BY orderstatus
		at io.trino.testing.DistributedQueryRunner.execute(DistributedQueryRunner.java:492)
		... 19 more
Caused by: java.lang.IndexOutOfBoundsException: Index (0) is greater than or equal to list size (0)
	at it.unimi.dsi.fastutil.longs.LongArrayList.getLong(LongArrayList.java:267)
	at io.trino.operator.PagesIndex.buildPage(PagesIndex.java:306)
	at io.trino.operator.PagesIndex$2.computeNext(PagesIndex.java:631)
	at io.trino.operator.PagesIndex$2.computeNext(PagesIndex.java:624)
	at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:146)
	at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:141)
	at io.trino.operator.WorkProcessorUtils.lambda$fromIterator$0(WorkProcessorUtils.java:103)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$3.process(WorkProcessorUtils.java:347)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$3.process(WorkProcessorUtils.java:347)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.testing.QueryAssertions.assertQuery(QueryAssertions.java:147)
	... 18 more
	Suppressed: java.lang.Exception: SQL: SELECT orderkey, custkey, orderstatus FROM orders ORDER BY nullif(orderkey, 3) ASC NULLS LAST, custkey ASC
		at io.trino.testing.DistributedQueryRunner.execute(DistributedQueryRunner.java:492)
		... 19 more
Caused by: java.lang.IndexOutOfBoundsException: Index (0) is greater than or equal to list size (0)
	at it.unimi.dsi.fastutil.longs.LongArrayList.getLong(LongArrayList.java:267)
	at io.trino.operator.PagesIndex.buildPage(PagesIndex.java:306)
	at io.trino.operator.PagesIndex$2.computeNext(PagesIndex.java:631)
	at io.trino.operator.PagesIndex$2.computeNext(PagesIndex.java:624)
	at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:146)
	at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:141)
	at io.trino.operator.WorkProcessorUtils.lambda$fromIterator$0(WorkProcessorUtils.java:103)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$3.process(WorkProcessorUtils.java:347)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$3.process(WorkProcessorUtils.java:347)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$2.process(WorkProcessorUtils.java:126)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils.getNextState(WorkProcessorUtils.java:262)
	at io.trino.operator.WorkProcessorUtils$YieldingProcess.process(WorkProcessorUtils.java:182)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$3.process(WorkProcessorUtils.java:347)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$YieldingIterator.computeNext(WorkProcessorUtils.java:81)
	at io.trino.operator.WorkProcessorUtils$YieldingIterator.computeNext(WorkProcessorUtils.java:67)
	at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:146)
	at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:141)
	at io.trino.operator.OrderByOperator.getOutput(OrderByOperator.java:275)
	at io.trino.operator.Driver.processInternal(Driver.java:394)
	at io.trino.operator.Driver.lambda$process$8(Driver.java:297)
	at io.trino.operator.Driver.tryWithLock(Driver.java:689)
	at io.trino.operator.Driver.process(Driver.java:289)
	at io.trino.operator.Driver.processForDuration(Driver.java:260)
	at io.trino.execution.SqlTaskExecution$DriverSplitRunner.processFor(SqlTaskExecution.java:773)
	at io.trino.execution.executor.PrioritizedSplitRunner.process(PrioritizedSplitRunner.java:165)
	at io.trino.execution.executor.TaskExecutor$TaskRunner.run(TaskExecutor.java:523)
	at io.trino.$gen.Trino_testversion____20230307_070445_4328.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)

Error:  Failures: 
Error:    TestSpilledOrderByQueries>AbstractTestOrderByQueries.testOrderBy:30->AbstractTestQueryFramework.assertQueryOrdered:366->AbstractTestQueryFramework.assertQueryOrdered:371->AbstractTestQueryFramework.assertQueryOrdered:381 Execution of 'actual' query failed: SELECT orderstatus FROM orders ORDER BY orderstatus
Error:    TestSpilledOrderByQueries>AbstractTestOrderByQueries.testOrderByWithNulls:149->AbstractTestQueryFramework.assertQueryOrdered:366->AbstractTestQueryFramework.assertQueryOrdered:371->AbstractTestQueryFramework.assertQueryOrdered:381 Execution of 'actual' query failed: SELECT orderkey, custkey, orderstatus FROM orders ORDER BY nullif(orderkey, 3) ASC NULLS LAST, custkey ASC
[INFO]

The text was updated successfully, but these errors were encountered:

findepi · 2023-03-07T11:22:08Z

Marked release-blocker, because it looks like a regression after 409.

findepi · 2023-03-07T11:26:29Z

https://nineinchnick.github.io/trino-cicd/reports/flaky/ currently doesn't include "spilled" (like in TestSpilledOrderByQueries)

cc @nineinchnick

nineinchnick · 2023-03-07T11:36:03Z

The annotation processing job has been failing recently, and we're relying on these annotations to create that report. We do have all the test reports downloaded from GHA artifacts, but there are no XML functions in Trino to process them. We'd have to create another job to convert them to JSON.

I just opened ScaCap/action-surefire-report#138 to address failures in annotation processing.

aczajkowski · 2023-03-07T11:47:13Z

This error can be seen in man test's and in different combinations:

TestDistributedSpilledQueries.testOrderByWithAgregation
TestDistributedSpilledQueries.testPredicate
TestSpilledJoinQueries.testSemiJoin
TestSpilledOrderByQueries.testOrderByWithOutputColumnReference

Root cause stack trace is always the same

Caused by: java.lang.IndexOutOfBoundsException: Index (0) is greater than or equal to list size (0)
	at it.unimi.dsi.fastutil.longs.LongArrayList.getLong(LongArrayList.java:267)
	at io.trino.operator.PagesIndex.buildPage(PagesIndex.java:306)
	at io.trino.operator.PagesIndex$2.computeNext(PagesIndex.java:631)
	at io.trino.operator.PagesIndex$2.computeNext(PagesIndex.java:624)
	at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:146)
	at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:141)
	at io.trino.operator.WorkProcessorUtils.lambda$fromIterator$0(WorkProcessorUtils.java:103)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$3.process(WorkProcessorUtils.java:347)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$3.process(WorkProcessorUtils.java:347)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$2.process(WorkProcessorUtils.java:126)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils.getNextState(WorkProcessorUtils.java:262)
	at io.trino.operator.WorkProcessorUtils$YieldingProcess.process(WorkProcessorUtils.java:182)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$3.process(WorkProcessorUtils.java:347)
	at io.trino.operator.WorkProcessorUtils$ProcessWorkProcessor.process(WorkProcessorUtils.java:413)
	at io.trino.operator.WorkProcessorUtils$YieldingIterator.computeNext(WorkProcessorUtils.java:81)
	at io.trino.operator.WorkProcessorUtils$YieldingIterator.computeNext(WorkProcessorUtils.java:67)
	at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:146)
	at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:141)
	at io.trino.operator.OrderByOperator.getOutput(OrderByOperator.java:275)
	at io.trino.operator.Driver.processInternal(Driver.java:394)
	at io.trino.operator.Driver.lambda$process$8(Driver.java:297)
	at io.trino.operator.Driver.tryWithLock(Driver.java:689)
	at io.trino.operator.Driver.process(Driver.java:289)
	at io.trino.operator.Driver.processForDuration(Driver.java:260)
	at io.trino.execution.SqlTaskExecution$DriverSplitRunner.processFor(SqlTaskExecution.java:773)
	at io.trino.execution.executor.PrioritizedSplitRunner.process(PrioritizedSplitRunner.java:165)
	at io.trino.execution.executor.TaskExecutor$TaskRunner.run(TaskExecutor.java:523)
	at io.trino.$gen.Trino_testversion____20230305_044615_29138.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)

findepi · 2023-03-07T15:35:36Z

I added some debug prints into OrderByOperator and run TestSpilledOrderByQueries locally (it fails quite consistently locally, failing method varies)

Example failure gave me the log (i've filtered this down to a single operator instance based in identity hash code)

OrderByOperator.OrderByOperator created pagesIndex 1620083669
OrderByOperator.getOutput
OrderByOperator.addInput
OrderByOperator.updateMemoryUsage
OrderByOperator.getOutput
OrderByOperator.addInput
OrderByOperator.updateMemoryUsage
OrderByOperator.getOutput
OrderByOperator.getOutput
OrderByOperator.startMemoryRevoke
OrderByOperator.finishMemoryRevoke
OrderByOperator (finishMemoryRevoke) pagesIndex.clear 1620083669
OrderByOperator.updateMemoryUsage
OrderByOperator.addInput
OrderByOperator.updateMemoryUsage
OrderByOperator.getOutput
OrderByOperator.addInput
OrderByOperator.updateMemoryUsage
OrderByOperator.getOutput
OrderByOperator.startMemoryRevoke
OrderByOperator.finishMemoryRevoke
OrderByOperator (finishMemoryRevoke) pagesIndex.clear 1620083669
OrderByOperator.updateMemoryUsage
OrderByOperator.addInput
OrderByOperator.updateMemoryUsage
OrderByOperator.getOutput
OrderByOperator.startMemoryRevoke
OrderByOperator.finishMemoryRevoke
OrderByOperator (finishMemoryRevoke) pagesIndex.clear 1620083669
OrderByOperator.updateMemoryUsage
OrderByOperator.addInput
OrderByOperator.updateMemoryUsage
OrderByOperator.getOutput
OrderByOperator.addInput
OrderByOperator.updateMemoryUsage
OrderByOperator.getOutput
OrderByOperator.getOutput
OrderByOperator.startMemoryRevoke
OrderByOperator.finish: still spilling
OrderByOperator.finish: state NEEDS_INPUT
OrderByOperator.finish: pageIndex.getSortedPages
OrderByOperator.finishMemoryRevoke
OrderByOperator (finishMemoryRevoke) pagesIndex.clear 1620083669
OrderByOperator.updateMemoryUsage
OrderByOperator.finish: state HAS_OUTPUT
OrderByOperator.getOutput
OrderByOperator.getOutput failed: java.lang.IndexOutOfBoundsException: Index (0) is greater than or equal to list size (0)

It's clear the operator spilled multiple time, the last one between finish and getOutput

OrderByOperator.startMemoryRevoke
...
OrderByOperator.finish: pageIndex.getSortedPages
OrderByOperator.finishMemoryRevoke
OrderByOperator (finishMemoryRevoke) pagesIndex.clear 1620083669
OrderByOperator.updateMemoryUsage
OrderByOperator.finish: state HAS_OUTPUT
OrderByOperator.getOutput

in finish we create iterator over PagesIndex ("pageIndex.getSortedPages"), but later, in finishMemoryRevoke we clear pagesIndex, invalidating the iterator.

As described in #16409, before #15575 such iterator would not fail (would return 0 pages).
After #15575, it fails.

Question: why is finish called before we finish spilling (finishMemoryRevoke)?
I think after startMemoryRevoke the next operation expected by the operator should be finishMemoryRevoke?
did i remember wrong?
cc @sopel39 @losipiuk

findinpath · 2023-03-07T19:06:55Z

https://github.com/trinodb/trino/actions/runs/4352631358/jobs/7606785752

ebyhr · 2023-03-08T06:37:14Z

https://github.com/trinodb/trino/actions/runs/4361360110/jobs/7625221510

findepi · 2023-03-08T08:29:57Z

This will be fixed by #16411 or #16431

kasiafi · 2023-03-08T11:15:18Z

@findepi is this a potential correctness issue? could getOutput() potentially be called before the PagesIndex is cleared by finishMemoryRevoke? If so, we would have duplicate page on output, both from the PagesIndex and spilled.

findepi · 2023-03-08T12:31:40Z

I don't think so. Per

trino/core/trino-main/src/main/java/io/trino/operator/Operator.java

Line 66 in 7c1a277

* processing methods on it (isBlocked/needsInput/addInput/getOutput) until

getOutput() cannot be called before finishMemoryRevoke is run.

findepi added the bug Something isn't working label Mar 7, 2023

findepi mentioned this issue Mar 7, 2023

Update Aircompressor to 0.24 #16400

Merged

findepi added the RELEASE-BLOCKER label Mar 7, 2023

findepi mentioned this issue Mar 7, 2023

Fix Partition Projection storage location #16349

Merged

kasiafi mentioned this issue Mar 7, 2023

Fix sorted pages iterator #16409

Closed

findepi mentioned this issue Mar 7, 2023

Fix Driver not to finish operator which is revoking memory #16411

Closed

findinpath mentioned this issue Mar 7, 2023

Test: Add CI infrastructure for trino-redshift #16301

Closed

ebyhr mentioned this issue Mar 8, 2023

Filter information_schema within engine #16080

Merged

findepi mentioned this issue Mar 8, 2023

Fix OrderByOperator.finish to wait for finishMemoryRevoke #16431

Merged

Dith3r mentioned this issue Mar 8, 2023

Expose rule stats in QueryStats #16365

Merged

This was referenced Mar 8, 2023

Set DriverYieldSignal in Driver#close() #16395

Merged

More string format removals #15316

Merged

findepi closed this as completed in #16431 Mar 8, 2023

krvikash mentioned this issue Mar 9, 2023

Support partitioning on nested ROW fields in Iceberg #15712

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Potential regression in spilled ORDER BY #16406

Potential regression in spilled ORDER BY #16406

findepi commented Mar 7, 2023 •

edited

Loading

findepi commented Mar 7, 2023

findepi commented Mar 7, 2023

nineinchnick commented Mar 7, 2023

aczajkowski commented Mar 7, 2023

findepi commented Mar 7, 2023

findinpath commented Mar 7, 2023

ebyhr commented Mar 8, 2023

findepi commented Mar 8, 2023

kasiafi commented Mar 8, 2023

findepi commented Mar 8, 2023

Potential regression in spilled ORDER BY #16406

Potential regression in spilled ORDER BY #16406

Comments

findepi commented Mar 7, 2023 • edited Loading

findepi commented Mar 7, 2023

findepi commented Mar 7, 2023

nineinchnick commented Mar 7, 2023

aczajkowski commented Mar 7, 2023

findepi commented Mar 7, 2023

findinpath commented Mar 7, 2023

ebyhr commented Mar 8, 2023

findepi commented Mar 8, 2023

kasiafi commented Mar 8, 2023

findepi commented Mar 8, 2023

findepi commented Mar 7, 2023 •

edited

Loading