psql now shows zero elapsed time after an error

On Mon, May 9, 2022 at 11:56 PM Tom Lane <tgl@sss.pgh.pa.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

Hello,

Thanks for the catch and the proposed fix! Indeed, on errors the timing is
not updated appropriately.

ISTM that the best course is to update the elapsed time whenever a result
is obtained, so that a sensible value is always available.

See attached patch which is a variant of Richard's version.

fabien=# SELECT 1 as one \; SELECT 1/0 \; SELECT 2 as two;
┌─────┐
│ one │
├─────┤
│ 1 │
└─────┘
(1 row)

ERROR: division by zero
Time: 0,352 ms

Probably it would be appropriate to add a test case. I'll propose
something later.

--
Fabien.

On 10.05.22 15:42, Fabien COELHO wrote:

Hello,

Thanks for the catch and the proposed fix! Indeed, on errors the timing
is not updated appropriately.

ISTM that the best course is to update the elapsed time whenever a
result is obtained, so that a sensible value is always available.

See attached patch which is a variant of Richard's version.

 fabien=# SELECT 1 as one \; SELECT 1/0 \; SELECT 2 as two;
 ┌─────┐
 │ one │
 ├─────┤
 │   1 │
 └─────┘
 (1 row)

 ERROR:  division by zero
 Time: 0,352 ms

Probably it would be appropriate to add a test case. I'll propose
something later.

committed with a test

Probably it would be appropriate to add a test case. I'll propose something
later.

committed with a test

Thanks!

--
Fabien.