Re: psql now shows zero elapsed time after an error - Mailing list pgsql-hackers

From Richard Guo
Subject Re: psql now shows zero elapsed time after an error
Date
Msg-id CAMbWs4_OxtTzkGZtx2Nm+kttsLur=KspJ51ac+r_zRfGtWx0WA@mail.gmail.com
Whole thread Raw
In response to psql now shows zero elapsed time after an error  (Tom Lane <tgl@sss.pgh.pa.us>)
Responses Re: psql now shows zero elapsed time after an error
List pgsql-hackers

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

pgsql-hackers by date:

Previous
From: Justin Pryzby
Date:
Subject: Re: strange slow query - lost lot of time somewhere
Next
From: Amit Kapila
Date:
Subject: Re: Logical replication timeout problem