Final operators stats are not always propagated

[sopel39]

Looking at: io.prestosql.operator.DriverContext#finished, it seems that driver might be set as done while it's stats are still not populated into pipeline stats (pipelineContext.driverFinished(this); happens after). This might mark task as finished (and final task info set) with driver stats lost.

Relates to: #5120

[sopel39]

cc @dain

[findepi]

Question is -- are stats "best effort", or guaranteed?

in tests we would want them to be guaranteed, but maybe it's not necessary in general, and additional synchronisation or latency at comnpletion is not warranted?

[sopel39]

I'm not sure DriverContext is a problem though since it's not marked as @ThreadSafe and it seems to be accessed from thread of TaskExecutor

[dain]

IIRC the DriverContext is supposed to be single threaded. Maybe the problem is on the code that is reading these.

@sopel39 can you describe the problem we are actually seeing in these tests?

[sopel39]

@dain it looks like stats from not all drivers (pipelines?) are propagated back to coordinator before query is finished.
This causes certain assertions to fail (e.g input row count is less than expected).

All linked flaky tests share that characteristic.

[yansun7]

In addition to the risk of losing driver stat, driver context clear up is also skipped in that case (code)
In my test, I've seen cases from heap dump where lots of DriverContext objects are not collected by GC in time due to this issue.

[sopel39]

In addition to the risk of losing driver stat, driver context clear up is also skipped in that case (code)
In my test, I've seen cases from heap dump where lots of DriverContext objects are not collected by GC in time due to this issue.

Would you be able to track the root cause of the issue?

[yansun7]

For my case, it's because DriverContext#failed(..) is called before DriverContext#finished() when query is interrupted by exception (code), thus there's no chance PipelineContext#driverFinished() can be called to remove driverContext.

[atanasenko]

After quite some time of reading code and analyzing logs, I think I figured it out.
There are at least 3 issues that caused test flakiness in stats. All stem from the asynchronous nature of task updates coming from workers to coordinator, and StateMachine listener events which might also race with other code to update TaskInfo instances.

• The most frequent one is because of worker's SqlTask status being transitioned to FINISHED while the initial SqlTaskExecution is still being created, and at that time, the TaskHolder reference is just an empty one, having no stats to provide to the final TaskInfo.
• Second, less frequent, but still prominent is when final TaskInfo on the coordinator is being constructed from a final task status and a partial TaskInfo received previously from the worker which might not have all the stats collected just yet, while the final TaskInfo on the worker is built just a bit later.
• Third one is similar to previous, but in this case the final status of the task is set during substage cancellation on parent's FLUSHING status. Sometimes final TaskInfo (or even TaskStatus) have not yet reached coordinator, meaning it's stage is not yet completed. Upon cancellation of a substage, any stats received by coordinator subsquently are ignored.

I've submitted a pr #9733 with my attempt to fix those issues. I tested it out using a loop with 10K queries in sequence. Without those changes first lost stats happened within the first 100.

[sopel39]

The most frequent one is because of worker's SqlTask status being transitioned to FINISHED while the initial SqlTaskExecution is still being created, and at that time, the TaskHolder reference is just an empty one, having no stats to provide to the final TaskInfo.

Does that happen on early cancellation? Otherwise worker couldn't do any actual work (io.trino.execution.SqlTask#updateTask wasn't called) so stats should be empty.

[sopel39]

Upon cancellation of a substage, any stats received by coordinator subsquently are ignored.

Could you point that in code? I don't think it's the case

[itsinthebag]

Not sure this is totally related, but in my case, there is operatorSummaries, but operatorInfo is missing sometime. This only happened in TableScanOperator and ScanFilterAndProjectOperator.
correct operatorStats:

missing operatorInfo operatorStats:

[dain]

Question is -- are stats "best effort", or guaranteed?

They are best effort. If we can get stats great, but do not add latency to the query.

[findepi]

They are best effort. If we can get stats great, but do not add latency to the query.

i can imagine use-cases where having accurate stats is worth small additional latency. e.g. chargeback.
What additional latency tax this would take?

[findepi]

Additional fix #9913
Follow up cleanup #9898