matanper opened a new issue, #70145: URL: https://github.com/apache/doris/issues/70145
### Search before asking - [x] I searched the issues and found no similar issue. Related: #67503 (idle reaper for deferred Arrow Flight queries). ### Version master (also 4.1) ### What's wrong For queries over Arrow Flight SQL, the audit log's `query_time` covers only FE parse, plan and dispatch, not execution or the result fetch. The client fetches results from the BEs (DoGet on the endpoints in the FlightInfo), so the FE never sees the query finish. `ConnectProcessor` writes the audit event right after `executor.execute()` returns, which for a deferred Arrow Flight query is right after the fragments are dispatched, and `AuditLogHelper` sets `queryTime = now - startTime`. `scan_rows`, `scan_bytes` and `cpu_time_ms` look right only because `WorkloadRuntimeStatusMgr` later overwrites them from the BE workload reports; `query_time` is never updated. Example (one FE, one BE, same query, 3 runs each): | | client-measured time | audit `query_time` | |---|---|---| | Arrow Flight (ADBC) | 1,230–1,304 ms | 16–20 ms | | MySQL protocol | 1,232–1,246 ms | written after the last row is sent, so it covers the fetch | So dashboards and slow-query analysis built on `audit_log` see Flight queries as almost free. A second symptom of the same gap: a finished deferred Flight query stays registered as RUNNING on the FE (`information_schema.active_queries`, the workload group's running query count) until the session's next statement, the session closing, or the idle reaper from #67503 (`arrow_flight_deferred_query_idle_timeout_second`, floored at the query's execution timeout). With long-lived pooled ADBC connections we saw hundreds of such entries, each a query that had finished in tens of milliseconds. They count toward `running_query_num`, so any concurrency cap would block on them. ### What you expected `query_time` for an Arrow Flight query reflects the query's execution including the result fetch, comparable to the same query over MySQL, and the query leaves the FE's running set once the BEs have finished it. ### How to reproduce Run any SELECT through an ADBC Flight SQL client and over MySQL; compare `query_time` in `__internal_schema.audit_log` (or `fe.audit.log` `Time(ms)`), and `information_schema.active_queries` after the Flight query returns. ### Possible fix We fixed this in our 4.1 fork and are happy to submit a PR for master: - The BE reports, with the per-query statistics it already sends to the FE (`TQueryStatistics`), the time from the query's start to its last pipeline task closing. The result sink blocks until DoGet drains it, so this covers execution and nearly all of the fetch. - The FE marks the audit event of a deferred Arrow Flight query, holds it in `WorkloadRuntimeStatusMgr` until every BE reporting the query has finished it (or a cap), then logs `query_time = FE planning time + the slowest BE's time`. - On the same signal, the FE finalizes the deferred query, so it leaves the running set without waiting for the session. With the fix the Flight `query_time` above becomes 862–984 ms for a client-measured 887–1,003 ms. ### Are you willing to submit PR? - [x] Yes I am willing to submit a PR! -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
