Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
On Sun, Feb 26, 2023 at 11:45 PM Pavel Stehule wrote: > po 27. 2. 2023 v 5:08 odesílatel Kirk Wolak napsal: > >> On Fri, Feb 24, 2023 at 10:56 PM Kirk Wolak wrote: >> >>> On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh wrote: >>> On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak 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(20); > commit; > *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? > > 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.197725096000 *max *0.290659 >> >> With Timing >> done 0.191583 (500) *total* 100.729868 *min *0.163280 *avg >> *0.201459736000 >> *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 >>>
Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
po 27. 2. 2023 v 5:08 odesílatel Kirk Wolak napsal: > On Fri, Feb 24, 2023 at 10:56 PM Kirk Wolak wrote: > >> On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh wrote: >> >>> On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak 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. > 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(20); 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.197725096000 *max *0.290659 > > With Timing > done 0.191583 (500) *total* 100.729868 *min *0.163280 *avg > *0.201459736000 > *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 >>> >>
Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
On Fri, Feb 24, 2023 at 10:56 PM Kirk Wolak wrote: > On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh wrote: > >> On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak 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.197725096000 *max *0.290659 With Timing done 0.191583 (500) *total* 100.729868 *min *0.163280 *avg *0.201459736000 *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 >> >
Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
On Fri, Feb 24, 2023 at 7:09 AM Jim Jones wrote:
> 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
>
Jim, thanks, here is that patch for the %T option, but I think you did a +1
for the new psql variable :SQL_EXEC_TIME.
I realized my communication style needs to be cleaner, I caused that with
the lead in.
I created this proposal because I felt it was an excellent suggestion, and
I think it will be trivial to implement, although
it will involve a lot more testing... MANY times, I have run a query that
took a touch too long, and I was wondering how long EXACTLY did that take.
This makes it easy \echo :SQL_EXEC_TIME (Well, I think it will be
SQL_EXEC_ELAPSED)
regards, kirk
From eaf6d05028052a3ccaa8d980953ac4fd75255250 Mon Sep 17 00:00:00 2001
From: Kirk Wolak
Date: Thu, 23 Feb 2023 17:52:09 +
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
Reviewed-By: Andrey Borodin
Reviewed-By: Nikolay Samokhvalov
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= INSERT INTO my_table VALUES
(:'content');
+
+%T
+
+
+ The current time on the client in HH24:MI:SS format.
+
+
+
+
%x
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(_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
Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
On Fri, Feb 24, 2023 at 2:11 AM Gurjeet Singh wrote: > On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak 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. > 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 > 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 >
Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
On 23.02.23 20:55, Kirk Wolak wrote: 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... I've been there many times! 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 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
Re: Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
On Thu, Feb 23, 2023 at 8:42 PM Kirk Wolak 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. > This feature is simple. We forget to set \timing on... > 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. > > 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
Proposal: :SQL_EXEC_TIME (like :ROW_COUNT) Variable (psql)
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
