The dolt sql-client query timings always show 0.00 sec

[dphil]

I'm running some queries (select statements) that ostensibly take around 0.5-1 second to run, but the sql-client always reports a query time of 0.00 sec.

Using dolt 0.52.13, but as far as I know it's always been this way.

[timsehn]

Do you mind sharing the exact command line? sql-client is a bit ambiguous to me.

For instance, when trying to repro:

$ dolt sql-client -u root -q "select * from user_counts limit 5";
+------------+-----+-----+
| count_date | dau | mau |
+------------+-----+-----+
| 2023-01-05 | 1   | 2   |
| 2023-01-06 | 1   | 2   |
| 2023-01-07 | 2   | 2   |
| 2023-01-09 | 5   | 5   |
| 2023-01-01 | 0   | 0   |
+------------+-----+-----+

No timing information.

[dphil]

Oh, I guess when I ues sql-client it's always for the interactive session via dolt sql-client with no args. And for one-off queries I do dolt sql -q "..."

So my workflow was:

$ dolt sql-client -u root
mysql> use mydb;
mysql> select * from ...;
// result set here
N rows in set (0.00 sec)

Estimated real time was averaging roughly 500ms, maybe a bit less.

[timsehn]

OK. Great. I can repro. Should be an easy fix.

[stephkyou]

Hi @dphil, I tried to repro and couldn't see the same thing. I followed the steps above and got a select statement with a non-zero duration:

2113 rows in set (0.15 sec)

To clarify, is the bug you're seeing that the duration being displayed isn't accurate (i.e. you expect a time of 0.5 sec but are seeing 0 sec) or is it that all queries are displaying 0.00 sec regardless of the actual time it took to run?

[dphil]

Hm, actually you're right, I am seeing non-zero times displayed for other long-running queries.
It seems to be specific to a particular query I'm working with of the format:

select colA from table where ((colB = ... and colC = ...) or (colB = ... and colC= ...) or ...)

This query appears to take roughly 0.5s to run, but reports 0.00 sec. @timsehn this is the one we spoke about with a collation-related performance hit.
To rule out that the apparent time (0.5s) I'm seeing might be related to other factors like displaying the results output, I ran other queries that should be very fast but produce a lot more output, and they're basically instantaneous and show 0.00 sec (which to that precision is probably correct in those cases).

[stephkyou]

Hi @dphil, I investigated some more and I think I understand what the issue is now. It seems like we're printing out the time to print results instead of the actual time of the query. For example, select sleep(2); returns 1 row in set (0.00 sec) whereas select * from ... limit 1000 returns 1000 rows in set (0.07 sec). I'll work on a fix and keep you updated. Thanks for opening up an issue on this!

[stephkyou]

Hi @dphil, query timing should be working as expected now, displaying the time to execute a query. Let me know if you notice any further issues with this. Thanks!