Thread

Commits

psql: Update \timing also in case of an error
- 9520f8d92a86 15.0 landed

psql now shows zero elapsed time after an error

Tom Lane <tgl@sss.pgh.pa.us> — 2022-05-09T15:56:05Z

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.

			regards, tom lane

Re: psql now shows zero elapsed time after an error

Richard Guo <guofenglinux@gmail.com> — 2022-05-10T02:54:57Z

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

Re: psql now shows zero elapsed time after an error

Fabien COELHO <coelho@cri.ensmp.fr> — 2022-05-10T13:42:41Z

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.

Re: psql now shows zero elapsed time after an error

Peter Eisentraut <peter.eisentraut@enterprisedb.com> — 2022-05-23T08:13:40Z

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

Re: psql now shows zero elapsed time after an error

Fabien COELHO <coelho@cri.ensmp.fr> — 2022-05-23T08:49:22Z

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

Thanks!

-- 
Fabien.