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

Proposal:  Simply add the %T (PROMPT variable) to output the current time (HH24:MI:SS) into the prompt.  This has been in sqlplus since I can remember, and I find it really useful when I forgot to time something, or to review for Time spent on a problem, or for how old my session is...

On the whole I'd rather not eat more of the limited namespace for
psql prompt codes for this.

Kirk Wolak <wolakk@gmail.com> writes:
> Proposal:  Simply add the %T (PROMPT variable) to output the current time
> (HH24:MI:SS) into the prompt.

I'm not really convinced that %`date` isn't a usable solution for this,
especially since it seems like a very niche requirement.  The next
person who wants it might well have a different desire than you
for exactly what gets shown.  The output of date can be customized,
but a hard-wired prompt.c feature not so much.

On the whole I'd rather not eat more of the limited namespace for
psql prompt codes for this.

                        regards, tom lane

On 22/02/2023 19:59, Nikolay Samokhvalov wrote:
> On Wed, Feb 22, 2023 at 9:55 AM Tom Lane <tgl@sss.pgh.pa.us
> <mailto:tgl@sss.pgh.pa.us>> wrote:
>
>     On the whole I'd rather not eat more of the limited namespace for
>     psql prompt codes for this.
>
>
> It depends on personal preferences. When I work on a large screen, I can
> afford to spend some characters in prompts, if it gives convenience –
> and many do (looking, for example, at modern tmux/zsh prompts showing
> git branch context, etc).
>
> Default behavior might remain short – it wouldn't make sense to extend
> it for everyone.

I have no objections to adding a %T option, although deciding what
format to use is a hassle. -1 for changing the default.

But let's look at the original request:

> This has been in sqlplus since I can remember, and I find it really
> useful when I forgot to time something, or to review for Time spent
> on a problem, or for how old my session is...
I've felt that pain too. You run a query, and it takes longer than I
expected. How long did it actually take? Too bad I didn't enable \timing
beforehand..

How about a new backslash command or psql variable to show how long the
previous statement took? Something like:

postgres=# select <unexpectedly slow query>
  ?column?
----------
       123
(1 row)

postgres=# \time

Time: 14011.975 ms (00:14.012)

This would solve the "I forgot to time something" problem.

- Heikki

Kirk Wolak <wolakk@gmail.com> writes:
> Proposal:  Simply add the %T (PROMPT variable) to output the current time
> (HH24:MI:SS) into the prompt.

I'm not really convinced that %`date` isn't a usable solution for this,
especially since it seems like a very niche requirement.  The next
person who wants it might well have a different desire than you
for exactly what gets shown.  The output of date can be customized,
but a hard-wired prompt.c feature not so much.

On the whole I'd rather not eat more of the limited namespace for
psql prompt codes for this.

                        regards, tom lane

On 22/02/2023 19:59, Nikolay Samokhvalov wrote:
> On Wed, Feb 22, 2023 at 9:55 AM Tom Lane <tgl@sss.pgh.pa.us
> <mailto:tgl@sss.pgh.pa.us>> wrote:
>
>     On the whole I'd rather not eat more of the limited namespace for
>     psql prompt codes for this.
>
>
> It depends on personal preferences. When I work on a large screen, I can
> afford to spend some characters in prompts, if it gives convenience –
> and many do (looking, for example, at modern tmux/zsh prompts showing
> git branch context, etc).
>
> Default behavior might remain short – it wouldn't make sense to extend
> it for everyone.

I have no objections to adding a %T option, although deciding what
format to use is a hassle. -1 for changing the default.

But let's look at the original request:

> This has been in sqlplus since I can remember, and I find it really
> useful when I forgot to time something, or to review for Time spent
> on a problem, or for how old my session is...
I've felt that pain too. You run a query, and it takes longer than I
expected. How long did it actually take? Too bad I didn't enable \timing
beforehand..

How about a new backslash command or psql variable to show how long the
previous statement took? Something like:

postgres=# select <unexpectedly slow query>
  ?column?
----------
       123
(1 row)

postgres=# \time

Time: 14011.975 ms (00:14.012)

This would solve the "I forgot to time something" problem.

- Heikki

On Wed, Feb 22, 2023 at 9:55 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

On the whole I'd rather not eat more of the limited namespace for
psql prompt codes for this.

It depends on personal preferences. When I work on a large screen, I can afford to spend some characters in prompts, if it gives convenience – and many do (looking, for example, at modern tmux/zsh prompts showing git branch context, etc).

Default behavior might remain short – it wouldn't make sense to extend it for everyone.

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

On Thu, Feb 23, 2023, 09:55 Nikolay Samokhvalov <samokhvalov@gmail.com> wrote:

On Thu, Feb 23, 2023 at 9:05 AM Maciek Sakrejda <m.sakrejda@gmail.com> 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.

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

On Thu, Feb 23, 2023, 09:55 Nikolay Samokhvalov <samokhvalov@gmail.com> wrote:

On Thu, Feb 23, 2023 at 9:05 AM Maciek Sakrejda <m.sakrejda@gmail.com> 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.

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

Heikki Linnakangas <hlinnaka@iki.fi> writes:
> On 23/02/2023 13:20, Peter Eisentraut wrote:
>> 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.

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

On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak <wolakk@gmail.com> 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.
...
>   I think like ROW_COUNT, it should not change because of internal commands.

+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

On 23.02.23 20:55, Kirk Wolak wrote:
> Everyone,
... SQL_EXEC_TIME
>   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
>
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

On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh <gurjeet@singh.im> wrote:

On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak <wolakk@gmail.com> wrote:

>   I think like ROW_COUNT, it should not change because of internal commands.
...

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.

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

On Fri, Feb 24, 2023 at 10:56 PM Kirk Wolak <wolakk@gmail.com> wrote:

On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh <gurjeet@singh.im> wrote:

On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak <wolakk@gmail.com> wrote:

... 

>   I think like ROW_COUNT, it should not change because of internal commands.
...

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.

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.

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 

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

po 27. 2. 2023 v 5:08 odesílatel Kirk Wolak <wolakk@gmail.com> napsal:

On Fri, Feb 24, 2023 at 10:56 PM Kirk Wolak <wolakk@gmail.com> wrote:

On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh <gurjeet@singh.im> wrote:

On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak <wolakk@gmail.com> wrote:

... 

...

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.

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

 

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 

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

On Thu, Feb 23, 2023 at 9:52 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Heikki Linnakangas <hlinnaka@iki.fi> writes:
> On 23/02/2023 13:20, Peter Eisentraut wrote:
>> 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.

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

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!

Greg Stark <stark@mit.edu> writes:
> I'm not sure if the *prompt* is a sensible place for it though. The
> place it seems like it would be most useful is reading the output of
> script executions where there would be no prompts. Perhaps it's the
> command tags and \echo statements that should be timestamped.

Hmm, that is an interesting idea.  I kind of like it, not least because
it eliminates most of the tension between wanting a complete timestamp
and wanting a short prompt.  Command tags are short enough that there's
plenty of room.