Re: psql now shows zero elapsed time after an error

On Mon, May 9, 2022 at 11:56 PM Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> Example (you need up-to-the-minute HEAD for this particular test
> case, but anything that runs a little while before failing will do):
>
> regression=# \timing
> Timing is on.
> regression=# select * from generate_series('2022-01-01 00:00'::timestamptz,
> 'infinity'::timestamptz,
> '1 month'::interval) limit 10;
> ERROR: timestamp out of range
> Time: 0.000 ms
>
> That timing is wrong. It visibly takes more-or-less half a second
> on my machine, and v14 psql reports that accurately:
>
> regression=# \timing
> Timing is on.
> regression=# select * from generate_series('2022-01-01 00:00'::timestamptz,
> 'infinity'::timestamptz,
> '1 month'::interval) limit 10;
> ERROR: timestamp out of range
> Time: 662.107 ms
>
> While I've not bisected, I think it's a dead cinch that 7844c9918
> is what broke this.
>

That's true. It happens in ExecQueryAndProcessResults(), when we try to
show all query results. If some error occured for a certain result, we
failed to check whether this is the last result and if so get timing
measure before printing that result.

Maybe something like below would do the fix.

--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1560,6 +1560,18 @@ ExecQueryAndProcessResults(const char *query, double
*elapsed_msec, bool *svpt_g
else
result = PQgetResult(pset.db);

+ last = (result == NULL);
+
+ /*
+ * Get timing measure before printing the last
result.
+ */
+ if (last && timing)
+ {
+ INSTR_TIME_SET_CURRENT(after);
+ INSTR_TIME_SUBTRACT(after, before);
+ *elapsed_msec =
INSTR_TIME_GET_MILLISEC(after);
+ }
+
continue;
}
else if (svpt_gone_p && !*svpt_gone_p)

Thanks
Richard