Re: psql now shows zero elapsed time after an error
Probably it would be appropriate to add a test case. I'll propose something later. committed with a test Thanks! -- Fabien.
Re: psql now shows zero elapsed time after an error
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
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.diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index feb1d547d4..773673cc62 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1560,6 +1560,16 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
else
result = PQgetResult(pset.db);
+ /*
+ * Get current timing measure in case an error occurs
+ */
+ if (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)
@@ -1612,7 +1622,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
last = (next_result == NULL);
/*
- * Get timing measure before printing the last result.
+ * Update current timing measure.
*
* It will include the display of previous results, if any.
* This cannot be helped because the server goes on processing
@@ -1623,7 +1633,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
* With combined queries, timing must be understood as an upper bound
* of the time spent processing them.
*/
- if (last && timing)
+ if (timing)
{
INSTR_TIME_SET_CURRENT(after);
INSTR_TIME_SUBTRACT(after, before);
Re: psql now shows zero elapsed time after an error
On Mon, May 9, 2022 at 11:56 PM Tom Lane 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
psql now shows zero elapsed time after an error
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
