Postgres Pro
Downloads
Home   >   mailing lists

Thread: psql now shows zero elapsed time after an error

psql now shows zero elapsed time after an error

From
Tom Lane
Date:
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

From
Richard Guo
Date:

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

From
Fabien COELHO
Date:
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.
Attachment

Re: psql now shows zero elapsed time after an error

From
Peter Eisentraut
Date:
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

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

Thanks!

-- 
Fabien.