no result for this query #1000
Description
Describe the bug
Recently, our user feedback there are some no result for this query error:
2019-04-23 11:24:21,261 WARN 26719 [Coordinator.getNext():591] query failed: no result for this query
2019-04-23 11:24:21,261 WARN 26719 [StmtExecutor.execute():282] execute Exception
org.apache.doris.common.UserException: no result for this query
at org.apache.doris.qe.Coordinator.getNext(Coordinator.java:598) ~[palo-fe.jar:?]
at org.apache.doris.qe.StmtExecutor.handleQueryStmt(StmtExecutor.java:546) ~[palo-fe.jar:?]
at org.apache.doris.qe.StmtExecutor.execute(StmtExecutor.java:214) [palo-fe.jar:?]
To Reproduce
I don't find a good way to reproduce this bug in my dev env, bug this bug produce in our prod env frequently.
Additional context
After I grep be.WARNING log and watch the git history. I think this bug was introduced by
#208.
The following is the related log in FE and BE:
2019-04-23 11:24:11,633 INFO 26719 [QeProcessorImpl.registerQuery():52] register query id = TUniqueId(hi:5953102834121853984, lo:-
8436326964743801426)
2019-04-23 11:24:21,261 INFO 26719 [Coordinator.cancelRemoteFragmentsAsync():664] cancelRemoteFragments ip=10.25.179.8 port=9060 rpcParams=529dab7c9b344c20:8aec2552b96575f6
2019-04-23 11:24:21,261 WARN 26719 [Coordinator.getNext():591] query failed: no result for this query
2019-04-23 11:24:21,261 WARN 26719 [StmtExecutor.execute():282] execute Exception
org.apache.doris.common.UserException: no result for this query
at org.apache.doris.qe.Coordinator.getNext(Coordinator.java:598) ~[palo-fe.jar:?]
at org.apache.doris.qe.StmtExecutor.handleQueryStmt(StmtExecutor.java:546) ~[palo-fe.jar:?]
at org.apache.doris.qe.StmtExecutor.execute(StmtExecutor.java:214) [palo-fe.jar:?]
2019-04-23 11:24:21,262 INFO 26719 [QeProcessorImpl.unregisterQuery():61] deregister query id = TUniqueId(hi:5953102834121853984,
lo:-8436326964743801426)
I0423 11:24:12.183797 6032 plan_fragment_executor.cpp:257] Open(): instance_id=TUniqueId(hi=5953102834121853984, lo=-843632696474
3801383)
I0423 11:24:12.184618 6023 plan_fragment_executor.cpp:257] Open(): instance_id=TUniqueId(hi=5953102834121853984, lo=-843632696474
3801381)
I0423 11:24:12.186556 6010 plan_fragment_executor.cpp:257] Open(): instance_id=TUniqueId(hi=5953102834121853984, lo=-843632696474
3801382)
I0423 11:24:12.695895 6000 plan_fragment_executor.cpp:547] Fragment 529dab7c9b344c20:8aec2552b96576a1:(Active: 1s062ms, % non-chi
ld: 0.00%)
- AverageThreadTokens: 1.00
- BytesReceived: 639.00 B
- DeserializeRowBatchTimer: 28.511us
- FirstBatchArrivalWaitTime: 0.000ns
- MergeGetNext: 10.529us
- MergeGetNextBatch: 9.634us
- PeakReservation: 0
- PeakUsedReservation: 0
- RowsProduced: 5
- SendersBlockedTimer: 0.000ns
- SendersBlockedTotalTimer(*): 0.000ns
BlockMgr:
- BlockWritesOutstanding: 0
- BlocksCreated: 0
- BlocksRecycled: 0
- BufferedPins: 0
- BytesWritten: 0
- MaxBlockSize: 8.00 MB
- MemoryLimit: 2.00 GB
- TotalBufferWaitTime: 0.000ns
- TotalEncryptionTime: 0.000ns
- TotalIntegrityCheckTime: 0.000ns
- TotalReadBlockTime: 0.000ns
DataBufferSender (dst_id=TUniqueId(hi=5953102834121853984, lo=-8436326964743801183)):
EXCHANGE_NODE (id=15):(Active: 1s062ms, % non-child: 0.00%)
- ConvertRowBatchTime: 0.000ns
- MemoryUsed: 0
- RowsReturned: 5
- RowsReturnedRate: 4.00 /sec
W0423 11:24:20.690606 6152 result_buffer_mgr.cpp:101] no result for this query, id=TUniqueId(hi=5953102834121853984, lo=-8436326964743801183)
2019-04-23 11:24:20,724 INFO 26719 [Coordinator.cancelRemoteFragmentsAsync():664] cancelRemoteFragments ip=10.22.212.5 port=9060 rpcParams=529dab7c9b344c20:8aec2552b96576a1
The unreasonable point is plan_fragment_executor close at 11:24:12.695895, but a fetch_data request process at 11:24:20.690606.