Subject: Re: Proposal: %T Prompt parameter for psql for current time (like Oracle has)

From: Heikki Linnakangas <[email-masked]>
Date: Thu, 23 Feb 2023 14:09:19 +0200

On 23/02/2023 13:20, Peter Eisentraut wrote:
> On 22.02.23 19:14, Heikki Linnakangas wrote:
>> How about a new backslash command or psql variable to show how long the
>> previous statement took? Something like:
> 
> If you don't have \timing turned on before the query starts, psql won't
> record what the time was before the query, so you can't compute the run
> time afterwards.  This kind of feature would only work if you always
> take the start time, even if \timing is turned off.

Correct. That seems acceptable though? gettimeofday() can be slow on 
some platforms, but I doubt it's *that* slow, that we couldn't call it 
two times per query.

- Heikki

---

From: Tom Lane <[email-masked]>
Date: Thu, 23 Feb 2023 09:52:15 -0500

> some platforms, but I doubt it's *that* slow, that we couldn't call it 

Yeah, you'd need to capture both the start and stop times even if
\timing isn't on, in case you get asked later.  But the backend is
going to call gettimeofday at least once per query, likely more
depending on what features you use.  And there are inherently
multiple kernel calls involved in sending a query and receiving
a response.  I tend to agree with Heikki that this overhead would
be unnoticeable.  (Of course, some investigation proving that
wouldn't be unwarranted.)

			regards, tom lane

---

From: Maciek Sakrejda <[email-masked]>
Date: Thu, 23 Feb 2023 09:04:25 -0800

+1 on solving the general problem of "I forgot to set \timing--how
long did this run?". I could have used that more than once in the
past, and I'm sure it will come up again.

I think Heikki's solution is probably more practical since (1) even if
we add the prompt parameter originally proposed, I don't see it being
included in the default, so it would require users to change their
prompt before they can benefit from it and (2) even if we commit to
never allowing tweaks to the format, I foresee a slow but endless
trickle of requests and patches to do so.

Thanks,
Maciek

---

From: Nikolay Samokhvalov <[email-masked]>
Date: Thu, 23 Feb 2023 09:55:02 -0800

On Thu, Feb 23, 2023 at 9:05 AM Maciek Sakrejda <[email-masked]>
wrote:

> I think Heikki's solution is probably more practical since (1) ..

Note that these ideas target two *different* problems:
- what was the duration of the last query
- when was the last query executed

So, having both solved would be ideal.

---

From: Maciek Sakrejda <[email-masked]>
Date: Thu, 23 Feb 2023 10:15:54 -0800

> So, having both solved would be ideal.

Fair point, but since the duration solution needs to capture two timestamps
anyway, it could print start time as well as duration.

The prompt timestamp could still be handy for more intricate session
forensics, but I don't know if that's a common-enough use case.

Thanks,
Maciek

---

From: Kirk Wolak <[email-masked]>
Date: Thu, 23 Feb 2023 13:52:27 -0500

On Thu, Feb 23, 2023 at 1:16 PM Maciek Sakrejda <[email-masked]>
wrote:

> Fair point, but since the duration solution needs to capture two
> timestamps anyway, it could print start time as well as duration.
>

It's really common during migrations, and forensics.  I often do a bunch of
stuff in 2 systems.  Then check the overlap.
Andrey brought up the value of 2 people separate working on things, being
able to go back and review when did you change that setting? Which has
happened to many of us in support sessions...

Thanks!

---

From: Kirk Wolak <[email-masked]>
Date: Thu, 23 Feb 2023 14:05:33 -0500

> wouldn't be unwarranted.)

Note, for this above feature, I was thinking we have a  ROW_COUNT variable
I use \set to see.
The simplest way to add this is maybe a set variable:  EXEC_TIME
And it's set when ROW_COUNT gets set.
+1

==
Now, since this opened a lively discussion, I am officially submitting my
first patch.
This includes the small change to prompt.c and the documentation.  I had
help from Andrey Borodin,
and Pavel Stehule, who have supported me in how to propose, and use gitlab,
etc.

We are programmers... It's literally our job to sharpen our tools.  And
PSQL is one of my most used.
A small frustration, felt regularly was the motive.

Regards, Kirk
PS: If I am supposed to edit the subject to say there is a patch here, I
did not know
PPS: I appreciate ANY and ALL feedback... This is how we learn!
From eaf6d05028052a3ccaa8d980953ac4fd75255250 Mon Sep 17 00:00:00 2001
From: Kirk Wolak <[email-masked]>
Date: Thu, 23 Feb 2023 17:52:09 +0000
Subject: [PATCH] Time option added to psql prompt

This adds a useful time option to the prompt: %T. Which does not
require a wasteful backquoted shell command which is also not
compatible between operating systems.
The format is simply HH24:MI:SS no other options available by design!

Author: Kirk Wolak <[email-masked]>
Reviewed-By: Andrey Borodin <[email-masked]>
Reviewed-By: Nikolay Samokhvalov <[email-masked]>
Thread: https://postgr.es/m/CACLU5mSRwHr_8z%3DenMj-nXF1tmC7%2BJn5heZQNiKuLyxYUtL2fg%40mail.gmail.com
---
 doc/src/sgml/ref/psql-ref.sgml |  9 +++++++++
 src/bin/psql/prompt.c          | 10 +++++++++-
 2 files changed, 18 insertions(+), 1 deletion(-)

diff --git a/doc/src/sgml/ref/psql-ref.sgml b/doc/src/sgml/ref/psql-ref.sgml
index dc6528dc11d..04ab9eeb8c0 100644
--- a/doc/src/sgml/ref/psql-ref.sgml
+++ b/doc/src/sgml/ref/psql-ref.sgml
@@ -4575,6 +4575,15 @@ testdb=&gt; <userinput>INSERT INTO my_table VALUES (:'content');</userinput>
         </listitem>
       </varlistentry>
 
+      <varlistentry id="app-psql-prompting-t-uc">
+        <term><literal>%T</literal></term>
+        <listitem>
+         <para>
+          The current time on the client in HH24:MI:SS format.
+         </para>
+        </listitem>
+      </varlistentry>
+
       <varlistentry id="app-psql-prompting-x">
         <term><literal>%x</literal></term>
         <listitem>
diff --git a/src/bin/psql/prompt.c b/src/bin/psql/prompt.c
index 969cd9908e5..a590c27389b 100644
--- a/src/bin/psql/prompt.c
+++ b/src/bin/psql/prompt.c
@@ -41,6 +41,7 @@
  *			or a ! if session is not connected to a database;
  *		in prompt2 -, *, ', or ";
  *		in prompt3 nothing
+ * %T - time in HH24:MI:SS format
  * %x - transaction status: empty, *, !, ? (unknown or no connection)
  * %l - The line number inside the current statement, starting from 1.
  * %? - the error code of the last query (not yet implemented)
@@ -223,7 +224,14 @@ get_prompt(promptStatus_t status, ConditionalStack cstack)
 							break;
 					}
 					break;
-
+					/* output HH24:MI:SS */
+				case 'T':
+					{
+						time_t current_time = time(NULL);
+						struct tm *tm_info = localtime(&current_time);
+						sprintf(buf, "%02d:%02d:%02d", tm_info->tm_hour, tm_info->tm_min, tm_info->tm_sec);				
+					}					
+					break;
 				case 'x':
 					if (!pset.db)
 						buf[0] = '?';
-- 
GitLab

---

From: Kirk Wolak <[email-masked]>
Date: Thu, 23 Feb 2023 14:55:33 -0500

Everyone,
  I love that my proposal for %T in the prompt, triggered some great
conversations.

  This is not instead of that.  That lets me run a query and come back
HOURS later, and know it finished before 7PM like it was supposed to!

  This feature is simple.  We forget to set \timing on...
We run a query, and we WONDER... how long did  that take.

  This, too, should be a trivial problem (the code will tell).

  I am proposing this to get feedback (I don't have a final design in mind,
but I will start by reviewing when and how ROW_COUNT gets set, and what
\timing reports).

  Next up, as I learn (and make mistakes), this toughens me up...

  I am not sure the name is right, but I would like to report it in the
same (ms) units as \timing, since there is an implicit relationship in what
they are doing.

  I think like ROW_COUNT, it should not change because of internal commands.
So, you guys +1 this thing, give additional comments.  When the feedback
settles, I commit to making it happen.

Thanks, Kirk

---

From: Gurjeet Singh <[email-masked]>
Date: Thu, 23 Feb 2023 23:11:38 -0800

On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak <[email-masked]> wrote:
>   I love that my proposal for %T in the prompt, triggered some great conversations.
>
>   This is not instead of that.  That lets me run a query and come back HOURS later, and know it finished before 7PM like it was supposed to!

Neat! I have this info embedded in my Bash prompt [1], but many a
times this is not sufficient to reconstruct the time it took to run
the shell command.

> We run a query, and we WONDER... how long did  that take.

And so I empathize with this need. I have set my Bash prompt to show
me this info [2].This info is very helpful in situations where you
fire a command, get tired of waiting for it and walk away for a few
minutes. Upon return it's very useful to see exactly how long did it
take for the command to finish.

>   I am not sure the name is right, but I would like to report it in the same (ms) units as \timing, since there is an implicit relationship in what they are doing.
>

+1

> So, you guys +1 this thing, give additional comments.  When the feedback settles, I commit to making it happen.

This is definitely a useful feature. I agree with everything in the
proposed UI (reporting in milliseconds, don't track internal commands'
timing).

I think 'duration' or 'elapsed' would be a better words in this
context. So perhaps the name could be one of :sql_exec_duration (sql
prefix feels superfluous), :exec_duration, :command_duration, or
:elapsed_time.

By using \timing, the user is explicitly opting into any overhead
caused by time-keeping. With this feature, the timing info will be
collected all the time. So do consider evaluating the performance
impact this can cause on people's workloads. They may not care for the
impact in interactive mode, but in automated scripts, even a moderate
performance overhead would be a deal-breaker.

[1]: https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.bashrc#L278
[2]: https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.bashrc#L262

Best regards,
Gurjeet
http://Gurje.et

---

From: Jim Jones <[email-masked]>
Date: Fri, 24 Feb 2023 13:09:47 +0100

>   This feature is simple.  We forget to set \timing on...
I've been there many times!
>   I am proposing this to get feedback (I don't have a final design in 
> mind, but I will start by reviewing when and how ROW_COUNT gets set, 
> and what \timing reports).
>
>   I am not sure the name is right, but I would like to report it in 
> the same (ms) units as \timing, since there is an implicit 
> relationship in what they are doing.
>
> So, you guys +1 this thing, give additional comments.  When the 
> feedback settles, I commit to making it happen.
>
> Thanks, Kirk
>
I can see it being pretty handy to check if a certain task involving two 
different terminal windows was done in the right order. Basically to see 
what went wrong, e.g. "did I really stop the master database before 
promoting the replica?"

+1 !

Best, Jim

---

From: Kirk Wolak <[email-masked]>
Date: Fri, 24 Feb 2023 22:56:16 -0500

On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh <[email-masked]> wrote:

> ...

I chose that prefix because it sorts near ROW_COUNT (LOL) when you do \SET

I agree that the name wasn't perfect...
I like SQL_EXEC_ELAPSED
keeping the result closer to ROW_COUNT, and it literally ONLY applies to SQL

> performance overhead would be a deal-breaker.
Excellent point.  I run lots of long scripts, but I usually set \timing on,
just because I turn off everything else.
I tested 2,000+ lines of select 1; (Fast sql shouldn't matter, it's the
most impacted)
Honestly, it was imperceptible,  Maybe approximating 0.01 seconds
With timing on:  ~ seconds 0.28
With timing of:   ~ seconds 0.27

The \timing incurs no realistic penalty at this point.  The ONLY penalty we
could face is the time to
write it to the variable, and that cannot be tested until implemented.  But
I will do that.  And I will
report the results of the impact.  But I do not expect a big impact.  We
update SQL_COUNT without an issue.
And that might be much more expensive to get.

Thanks!

>
> [1]:
> https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.bashrc#L278
> [2]:
> https://github.com/gurjeet/home/blob/08f1051fb854f4fc8fbc4f1326f393ed507a55ce/.bashrc#L262
>
> Best regards,
> Gurjeet
> http://Gurje.et
>

---

From: Kirk Wolak <[email-masked]>
Date: Sun, 26 Feb 2023 23:07:45 -0500

> Excellent point.  I run lots of long scripts, but I usually set \timing
> on, just because I turn off everything else.
> The \timing incurs no realistic penalty at this point.  The ONLY penalty
> we could face is the time to
> write it to the variable, and that cannot be tested until implemented.
> But I will do that.  And I will

Okay, I've written and tested this using SQL_EXEC_ELAPSED (suggested name
improvement).
First, the instant you have ANY output, it swamps the impact. (I settled
on: SELECT 1 as v \gset xxx) for no output
Second, the variability of running even a constant script is mind-blowing.
Third, I've limited the output...  I built this in layers (init.sql
initializes the psql variables I use), run_100.sql runs
another file (\i tst_2000.sql) 100 times.  Resulting in 200k selects.

Executive Summary:  1,000,000 statements executed, consumes ~2 - 2.5
seconds of extra time (Total)

So, the per statement cost is: 2.5s / 1,000,000 = 0.000,0025 s per statement
Roughly: 2.5us

Unfortunately, my test lines look like this:
Without Timing
done 0.198215 (500) *total *98.862548 *min* 0.167614 *avg*
0.19772509600000000000 *max *0.290659

With Timing
done 0.191583 (500) *total* 100.729868 *min *0.163280 *avg
*0.20145973600000000000
*max *0.275787

Notice that the With Timing had a lower min, and a lower max.  But a higher
average.
The distance between min - avg  AND min - max, is big (those are for 1,000
selects each)

Are these numbers at the "So What" Level?

While testing, I got the distinct impression that I am measuring something
that changes, or that the
variance in the system itself really swamps this on a per statement basis.
It's only impact is felt
on millions of PSQL queries, and that's a couple of seconds...

Curious what others think before I take this any further.

regards, Kirk

---

From: Pavel Stehule <[email-masked]>
Date: Mon, 27 Feb 2023 05:45:04 +0100

> another file (\i tst_2000.sql) 100 times.  Resulting in 200k selects.

This is the very worst case.

But nobody will run from psql 200K selects - can you try little bit more
real but still synthetic test case?

create table foo(a int);
begin
  insert into foo values(1);
 ...
  insert into foo values(200000);
commit;

Regards

Pavel

> done 0.191583 (500) *total* 100.729868 *min *0.163280 *avg *0.20145973600000000000
> *max *0.275787
>
> Notice that the With Timing had a lower min, and a lower max.  But a
> higher average.
> variance in the system itself really swamps this on a per statement
> basis.  It's only impact is felt

---

From: Kirk Wolak <[email-masked]>
Date: Mon, 27 Feb 2023 17:26:01 -0500

On Sun, Feb 26, 2023 at 11:45 PM Pavel Stehule <[email-masked]>
wrote:

>>> Okay, I've written and tested this using SQL_EXEC_ELAPSED (suggested
>> name improvement).

*Without timing:*
postgres=# \i ins.sql
Elapsed Time: 29.518647 (seconds)
postgres=# \i ins.sql
Elapsed Time: 24.973943 (seconds)
postgres=# \i ins.sql
Elapsed Time: 21.916432 (seconds)
postgres=# \i ins.sql
Elapsed Time: 25.440978 (seconds)
postgres=# \i ins.sql
Elapsed Time: 24.848986 (seconds)

-- Because that was slower than expected, I exited, and tried again...
Getting really different results
postgres=# \i ins.sql
Elapsed Time: 17.763167 (seconds)
postgres=# \i ins.sql
Elapsed Time: 19.210436 (seconds)
postgres=# \i ins.sql
Elapsed Time: 19.903553 (seconds)
postgres=# \i ins.sql
Elapsed Time: 21.687750 (seconds)
postgres=# \i ins.sql
Elapsed Time: 19.046642 (seconds)

*With timing:*
\i ins.sql
Elapsed Time: 20.479442 (seconds)
postgres=# \i ins.sql
Elapsed Time: 21.493303 (seconds)
postgres=# \i ins.sql
Elapsed Time: 22.732409 (seconds)
postgres=# \i ins.sql
Elapsed Time: 20.246637 (seconds)
postgres=# \i ins.sql
Elapsed Time: 20.493607 (seconds)

Again, it's really hard to measure the difference as the impact, again, is
a bit below the variance.
In this case, I could see about a 1s - 2s (max)  difference in total time.
for 200k statements.
Run 5 times (for 1 million).

It's a little worse than noise.  But if I used the first run, the timing
version would have seemed faster.

I think this is sufficiently fast, and the patch simplifies the code.  We
end up only checking "if (timing)"
in the few places that we print the timing...

Anything else to provide?

>> The distance between min - avg  AND min - max, is big (those are for
>> 1,000 selects each)
>>
>> While testing, I got the distinct impression that I am measuring
>> something that changes, or that the

---

From: Kirk Wolak <[email-masked]>
Date: Tue, 28 Feb 2023 19:47:15 -0500

On Thu, Feb 23, 2023 at 2:05 PM Kirk Wolak <[email-masked]> wrote:

> and Pavel Stehule, who have supported me in how to propose, and use
> gitlab, etc.
>

Patch Posted with one edit, for line editings (Thanks Jim!)
From b9db157177bbdeeeb6d35c3623ca9355141419d7 Mon Sep 17 00:00:00 2001
From: Jim Jones <[email-masked]>
Date: Wed, 1 Mar 2023 00:07:55 +0100
Subject: [PATCH v2] Time option added to psql prompt

index dc6528dc11..04ab9eeb8c 100644
 
index 969cd9908e..0c0c725df5 100644
2.25.1

---

From: Jim Jones <[email-masked]>
Date: Wed, 1 Mar 2023 10:29:06 +0100

> Patch Posted with one edit, for line editings (Thanks Jim!)

The patch didn't pass the SanityCheck:

https://cirrus-ci.com/task/5445242183221248?logs=build#L1337

missing a header perhaps?

#include "time.h"

Best, Jim

---

From: Daniel Gustafsson <[email-masked]>
Date: Mon, 3 Jul 2023 18:18:38 +0200

> On 1 Mar 2023, at 10:29, Jim Jones <[email-masked]> wrote:
> 

This patch spent the March commitfest not building and still doesn't build, so
I'm marking this returned with feedback.  Please feel free to resubmit to the
next commitfest if there is renewed interest in the patch.

--
Daniel Gustafsson