Fix wall time printed on CLI

[aaneja]

For queries with large number of results, the wall time reported on the CLI is misleading since it includes query execution + time spent iterating through the pager. Using the server side elapsed time makes more sense

Testing done

Run on CLI :
select * from tpch.sf100.lineitem limit 10000;
... < Wait 10-12 s on less pager> ..

Before

0:12 [52.1K rows, 0B] [4.5K rows/s, 0B/s]

After

[Latency: client-side: 413ms, server-side: 317ms] [24.4K rows, 0B] [76.8K rows/s, 0B/s]

== RELEASE NOTES ==

General Changes
* Report both client-side and server-side latency in presto-cli result summary. With this change, the client-side latency is the wall time presto-cli spends for this query to finish, but no longer includes the time spent by user paging through results. The server side latency is acquired from the Presto server which represents the wall time the engine uses to finish executing this query.

[fgwang7w]

LGTM, minor change in update of the comment in presto-cli/src/main/java/com/facebook/presto/cli/StatusPrinter.java#L86

[yingsu00]

Anant, thanks for the fix. Based on my previous knowledge, I think the "Release Notes" line can be removed from the PR message, just have the "No release notes" line stay. Not sure if the release bot would be confused seeing both lines.

[yingsu00]

@aaneja I actually think it might make sense to introduce a new metric for just the execution time. So we have 2 elapsed times: execution + result retrieval, and execution only. When the result is very large, the query may be blocked by the output buffer being full and the client not retrieving the data fast enough. For such cases how is the "execution only" time be evaluated?

[aaneja]

@aaneja I actually think it might make sense to introduce a new metric for just the execution time. So we have 2 elapsed times: execution + result retrieval, and execution only. When the result is very large, the query may be blocked by the output buffer being full and the client not retrieving the data fast enough. For such cases how is the "execution only" time be evaluated?

@yingsu00 If you look at the current stats being reported, we're computing all of them from server reported StatementStats. So IMO the execution time reported here should also be the server side execution time.
I agree that we should also capture the client side wall time. IMO we are better of reporting this in the 'debug' stats. I can take this up in a separate PR. WDYT ?

[yingsu00]

current stats being reported

Hi @aaneja, I think this change might make the users get confused and make mistakes if we just silently replace the wall time to the serverSideWallTime. They may observe big difference on query's wall time in the next release and mistakenly think it's big perf improvement, but it's actually not. Maybe it'll safer to output both on the CLI.

[yingsu00]

Actually I think the release note is needed since this is directly user facing. Would you please add a "general change" for it?

[aaneja]

Okay let me compute client side time separately as well; note that this different from the currently computed time since that includes time spent in the pager as well.

[yingsu00]

@aaneja Anant, if you're uncertain about the way how to pass the client stop time to the printer, you could also split this PR into two PRs, with the first keep the way the client time as is, and the second PR to address passing it from the client itself. Then we can approve the first PR first. If you do agree the way I suggested inline, you can just update the PR.

Also please make sure the tests are all green. Thanks.

[yingsu00]

Mostly looks good, just some nits.

[aaneja]

@yingsu00 I fixed your final comments. Test failures are unrelated to this change. I'm observing identical failures in other PRs