\timing interval
\timing is great.
\timing is helpful.
\timing has made me really good at mentally estimating numbers modulo
3600000.
Wouldn't it be great if we had a way of printing timing in more human
friendly formats?
Attached is a patch that allows the following (new/interesting bits in
bold):
# \timing off
Timing is off.
# select pg_sleep(1);
pg_sleep
----------
(1 row)
# \timing
Timing is on.
# select pg_sleep(1);
pg_sleep
----------
(1 row)
Time: 1002.959 ms
*# \timing interval*
*Timing is interval.*
# select pg_sleep(1);
pg_sleep
----------
(1 row)
*Time: 00:00:01.003*
# \timing
Timing is off.
As demonstrated, "interval" toggles to "off". There is no way to toggle to
"interval".
I'm pretty flexible on how something like this gets invoked. We could leave
timing alone and create a format variable. We could actually leverage the
pre-existing interval-to-string code, etc.
Note: the current patch includes no doc changes. I'd figure I'd wait to do
that after this patch or another gains some traction.
Attachments:
0001-psql-timing-interval.difftext/plain; charset=US-ASCII; name=0001-psql-timing-interval.diffDownload
diff --git a/src/bin/psql/command.c b/src/bin/psql/command.c
index 3f2cebf..1e6686f 100644
--- a/src/bin/psql/command.c
+++ b/src/bin/psql/command.c
@@ -1516,12 +1516,23 @@ exec_command(const char *cmd,
OT_NORMAL, NULL, false);
if (opt)
- pset.timing = ParseVariableBool(opt, "\\timing");
+ if (strcmp(opt,"interval") == 0)
+ pset.timing = PSQL_TIMING_INTERVAL;
+ else if (ParseVariableBool(opt, "\\timing"))
+ pset.timing = PSQL_TIMING_ON;
+ else
+ pset.timing = PSQL_TIMING_OFF;
else
- pset.timing = !pset.timing;
+ if (pset.timing == PSQL_TIMING_OFF)
+ pset.timing = PSQL_TIMING_ON;
+ else
+ pset.timing = PSQL_TIMING_OFF;
+
if (!pset.quiet)
{
- if (pset.timing)
+ if (pset.timing == PSQL_TIMING_INTERVAL)
+ puts(_("Timing is interval."));
+ else if (pset.timing == PSQL_TIMING_ON)
puts(_("Timing is on."));
else
puts(_("Timing is off."));
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 2450b9c..c79843f 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -587,6 +587,47 @@ PSQLexec(const char *query)
return res;
}
+/*
+ * PrintTimingInterval
+ *
+ * Output timing an interval format
+ */
+static void
+PrintTimingInterval(double elapsed_msec)
+{
+ double seconds = elapsed_msec / 1000.0;
+ int minutes;
+ int hours;
+ int days;
+
+ if (seconds < 60.0)
+ {
+ printf(_("Time: 00:00:%06.3f\n"), seconds);
+ return;
+ }
+
+ minutes = (int)seconds / 60;
+ seconds = seconds - (60.0 * minutes);
+ if (minutes < 60)
+ {
+ printf(_("Time: 00:%02d:%06.3f\n"), minutes, seconds);
+ return;
+ }
+
+ hours = minutes / 60;
+ minutes = minutes % 60;
+
+ if (hours < 24)
+ {
+ printf(_("Time: %2d:%02d:%06.3f\n"), hours, minutes, seconds);
+ return;
+ }
+
+ days = hours / 24;
+ hours = hours % 24;
+
+ printf(_("Time: %d, %2d:%02d:%06.3f\n"), days, hours, minutes, seconds);
+}
/*
* PSQLexecWatch
@@ -613,7 +654,7 @@ PSQLexecWatch(const char *query, const printQueryOpt *opt)
SetCancelConn();
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
INSTR_TIME_SET_CURRENT(before);
res = PQexec(pset.db, query);
@@ -626,7 +667,7 @@ PSQLexecWatch(const char *query, const printQueryOpt *opt)
return 0;
}
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
{
INSTR_TIME_SET_CURRENT(after);
INSTR_TIME_SUBTRACT(after, before);
@@ -677,7 +718,9 @@ PSQLexecWatch(const char *query, const printQueryOpt *opt)
fflush(pset.queryFout);
/* Possible microtiming output */
- if (pset.timing)
+ if (pset.timing == PSQL_TIMING_INTERVAL)
+ PrintTimingInterval(elapsed_msec);
+ else if (pset.timing == PSQL_TIMING_ON)
printf(_("Time: %.3f ms\n"), elapsed_msec);
return 1;
@@ -1228,7 +1271,7 @@ SendQuery(const char *query)
instr_time before,
after;
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
INSTR_TIME_SET_CURRENT(before);
results = PQexec(pset.db, query);
@@ -1237,7 +1280,7 @@ SendQuery(const char *query)
ResetCancelConn();
OK = ProcessResult(&results);
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
{
INSTR_TIME_SET_CURRENT(after);
INSTR_TIME_SUBTRACT(after, before);
@@ -1327,7 +1370,9 @@ SendQuery(const char *query)
ClearOrSaveResult(results);
/* Possible microtiming output */
- if (pset.timing)
+ if (pset.timing == PSQL_TIMING_INTERVAL)
+ PrintTimingInterval(elapsed_msec);
+ else if (pset.timing == PSQL_TIMING_ON)
printf(_("Time: %.3f ms\n"), elapsed_msec);
/* check for events that may occur during query execution */
@@ -1412,7 +1457,7 @@ ExecQueryUsingCursor(const char *query, double *elapsed_msec)
my_popt.topt.stop_table = false;
my_popt.topt.prior_records = 0;
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
INSTR_TIME_SET_CURRENT(before);
/* if we're not in a transaction, start one */
@@ -1440,7 +1485,7 @@ ExecQueryUsingCursor(const char *query, double *elapsed_msec)
if (!OK)
goto cleanup;
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
{
INSTR_TIME_SET_CURRENT(after);
INSTR_TIME_SUBTRACT(after, before);
@@ -1482,13 +1527,13 @@ ExecQueryUsingCursor(const char *query, double *elapsed_msec)
for (;;)
{
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
INSTR_TIME_SET_CURRENT(before);
/* get fetch_count tuples at a time */
results = PQexec(pset.db, fetch_cmd);
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
{
INSTR_TIME_SET_CURRENT(after);
INSTR_TIME_SUBTRACT(after, before);
@@ -1583,7 +1628,7 @@ ExecQueryUsingCursor(const char *query, double *elapsed_msec)
}
cleanup:
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
INSTR_TIME_SET_CURRENT(before);
/*
@@ -1609,7 +1654,7 @@ cleanup:
ClearOrSaveResult(results);
}
- if (pset.timing)
+ if (pset.timing != PSQL_TIMING_OFF)
{
INSTR_TIME_SET_CURRENT(after);
INSTR_TIME_SUBTRACT(after, before);
diff --git a/src/bin/psql/help.c b/src/bin/psql/help.c
index 9e6d67b..1e2a229 100644
--- a/src/bin/psql/help.c
+++ b/src/bin/psql/help.c
@@ -45,6 +45,7 @@
*/
#define ON(var) (var ? _("on") : _("off"))
+
void
usage(unsigned short int pager)
{
@@ -288,8 +289,8 @@ slashUsage(unsigned short int pager)
fprintf(output, _("Operating System\n"));
fprintf(output, _(" \\cd [DIR] change the current working directory\n"));
fprintf(output, _(" \\setenv NAME [VALUE] set or unset environment variable\n"));
- fprintf(output, _(" \\timing [on|off] toggle timing of commands (currently %s)\n"),
- ON(pset.timing));
+ fprintf(output, _(" \\timing [on|off|interval] toggle timing of commands (currently %s)\n"),
+ ( (pset.timing == PSQL_TIMING_INTERVAL) ? _("interval") : ON(pset.timing)));
fprintf(output, _(" \\! [COMMAND] execute command in shell or start interactive shell\n"));
fprintf(output, "\n");
diff --git a/src/bin/psql/settings.h b/src/bin/psql/settings.h
index 8cfe9d2..cc4e5eb 100644
--- a/src/bin/psql/settings.h
+++ b/src/bin/psql/settings.h
@@ -64,6 +64,13 @@ typedef enum
typedef enum
{
+ PSQL_TIMING_OFF,
+ PSQL_TIMING_ON,
+ PSQL_TIMING_INTERVAL
+} PSQL_TIMING;
+
+typedef enum
+{
hctl_none = 0,
hctl_ignorespace = 1,
hctl_ignoredups = 2,
@@ -108,7 +115,7 @@ typedef struct _psqlSettings
uint64 lineno; /* also for error reporting */
uint64 stmt_lineno; /* line number inside the current statement */
- bool timing; /* enable timing of all queries */
+ PSQL_TIMING timing; /* enable timing of all queries */
FILE *logfile; /* session log file handle */
On Thu, Jul 7, 2016 at 2:52 PM, Corey Huinker <corey.huinker@gmail.com> wrote:
Wouldn't it be great if we had a way of printing timing in more human
friendly formats?
Yes, it would. I've thought about doing this myself. So, +1 to the idea from me.
--
Peter Geoghegan
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
2016-07-08 0:13 GMT+02:00 Peter Geoghegan <pg@heroku.com>:
On Thu, Jul 7, 2016 at 2:52 PM, Corey Huinker <corey.huinker@gmail.com>
wrote:Wouldn't it be great if we had a way of printing timing in more human
friendly formats?Yes, it would. I've thought about doing this myself. So, +1 to the idea
from me.
+1
Pavel
Show quoted text
--
Peter Geoghegan--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 7/7/16 5:52 PM, Corey Huinker wrote:
Wouldn't it be great if we had a way of printing timing in more human
friendly formats?
Something like what you are proposing might as well be the default and
only format.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
On 7/7/16 5:52 PM, Corey Huinker wrote:
Wouldn't it be great if we had a way of printing timing in more human
friendly formats?
Something like what you are proposing might as well be the default and
only format.
NAK --- if you're trying to do arithmetic on the numbers, converting
them to hh:mm:ss notation isn't the best first step. I think a separate
setting somewhere to select the format would be good. Please *don't*
do "\timing interval" as that confuses the on/off state with the
formatting selection. Maybe a \pset option?
Also, might I suggest that leading zeroes in such a format are not
helpful? That is, I'd want to see "1:02.345" not "00:01:02.345".
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Sat, Jul 9, 2016 at 5:59 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Also, might I suggest that leading zeroes in such a format are not
helpful? That is, I'd want to see "1:02.345" not "00:01:02.345".
Or 1m 2s 345ms
--
greg
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
2016-07-09 18:59 GMT+02:00 Tom Lane <tgl@sss.pgh.pa.us>:
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
On 7/7/16 5:52 PM, Corey Huinker wrote:
Wouldn't it be great if we had a way of printing timing in more human
friendly formats?Something like what you are proposing might as well be the default and
only format.NAK --- if you're trying to do arithmetic on the numbers, converting
them to hh:mm:ss notation isn't the best first step. I think a separate
setting somewhere to select the format would be good. Please *don't*
do "\timing interval" as that confuses the on/off state with the
formatting selection. Maybe a \pset option?
\pset is good idea
Also, might I suggest that leading zeroes in such a format are not
helpful? That is, I'd want to see "1:02.345" not "00:01:02.345".
the value without units and without leading zeroes is not clear
Regards
Pavel
Show quoted text
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 7/9/16 12:59 PM, Tom Lane wrote:
NAK --- if you're trying to do arithmetic on the numbers, converting
them to hh:mm:ss notation isn't the best first step. I think a separate
setting somewhere to select the format would be good. Please *don't*
do "\timing interval" as that confuses the on/off state with the
formatting selection. Maybe a \pset option?
I'm not quite sure what you mean by wanting to do arithmetic on the
numbers. My phrasing of the problem is that after a long query, you
might get output like this:
Time: 1234567.666 ms
which is pretty useless.
So I would like to have a format that is a bit more sensitive to the
scale of the numbers. And I would like that by default, because I don't
really want to have to fiddle with the format and then have to re-run
the long query. (Then I'd just do the division by 3600 or whatever
myself, and we haven't really improved usability.)
I'm not wedded to any particular format, but I think we can come up with
one that works in most situations.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
I'm not quite sure what you mean by wanting to do arithmetic on the
numbers. My phrasing of the problem is that after a long query, you
might get output like this:
Time: 1234567.666 ms
which is pretty useless.
What I mean by that is that not infrequently, I'll run the same query
several times and then want to average the results. That's easy with awk
or similar scripts as long as the numbers are in straight decimal.
I don't mind if we provide a way to print in Babylonian-inspired
notation(s) as well, but I'm going to be seriously annoyed if that's
the only way to get the output.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
"Tom" == Tom Lane <tgl@sss.pgh.pa.us> writes:
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
I'm not quite sure what you mean by wanting to do arithmetic on the
numbers. My phrasing of the problem is that after a long query, you
might get output like this:
Time: 1234567.666 ms
which is pretty useless.
Tom> What I mean by that is that not infrequently, I'll run the same
Tom> query several times and then want to average the results. That's
Tom> easy with awk or similar scripts as long as the numbers are in
Tom> straight decimal.
Tom> I don't mind if we provide a way to print in Babylonian-inspired
Tom> notation(s) as well, but I'm going to be seriously annoyed if
Tom> that's the only way to get the output.
How about
Time: 1234567.666 ms (20m 34.6s)
?
--
Andrew (irc:RhodiumToad)
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Andrew Gierth <andrew@tao11.riddles.org.uk> writes:
How about
Time: 1234567.666 ms (20m 34.6s)
Hmm ... worksforme.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Sat, Jul 9, 2016 at 3:35 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
I'm not quite sure what you mean by wanting to do arithmetic on the
numbers. My phrasing of the problem is that after a long query, you
might get output like this:
Time: 1234567.666 ms
which is pretty useless.What I mean by that is that not infrequently, I'll run the same query
several times and then want to average the results. That's easy with awk
or similar scripts as long as the numbers are in straight decimal.I don't mind if we provide a way to print in Babylonian-inspired
notation(s) as well, but I'm going to be seriously annoyed if that's
the only way to get the output.regards, tom lane
I thought about a pset option as well, and I'd be fine with that, and I
don't think it'd be any harder to do it that way.
As for the leading zeros, I was following the format of the namesake
interval, adjusting for psql's existing max-3 decimal points on the
milliseconds.
# select INTERVAL '1 hours 2 minutes 3 seconds 4.567 milliseconds';
interval
-----------------
01:02:03.004567
# select INTERVAL '112345689 milliseconds';
interval
--------------
31:12:25.689
# select INTERVAL '1123456890 milliseconds';
interval
--------------
312:04:16.89
I'm not wild about the leading zero either, but I see where it's needed for
context absent d/h/m/s units, and I had concerns about internationalization
issues with unit abbreviations.
A quick googling of "iso time duration format" yielded more heat than
light. My one takeaway was that they require the leading zeros.
So what's everybody think of this?:
Keep \timing as-is.
Add \pset timing_format (or a better name, please suggest one), which can
have at least some of these options:
- milliseconds - this would be the default value with current behavior, and
an unset pset would assume this value.
- seconds - current ms value / 1000 and re-labeld s
- minutes - current ms value / 60000 and re-labeled m
- interval - follows the output format that we already use for INTERVAL
types.
- short - just like "interval" but trimming leading zeros and places.
Precision is kept at .xxx ms for context
- pretty - 4d, 3h, 2m, 11s, 45.678ms
The actual act of printing the timing value only happens in two places, so
replacing each with a single function is trivial.
On Sat, Jul 9, 2016 at 4:00 PM, Andrew Gierth <andrew@tao11.riddles.org.uk>
wrote:
"Tom" == Tom Lane <tgl@sss.pgh.pa.us> writes:
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
I'm not quite sure what you mean by wanting to do arithmetic on the
numbers. My phrasing of the problem is that after a long query, you
might get output like this:
Time: 1234567.666 ms
which is pretty useless.Tom> What I mean by that is that not infrequently, I'll run the same
Tom> query several times and then want to average the results. That's
Tom> easy with awk or similar scripts as long as the numbers are in
Tom> straight decimal.Tom> I don't mind if we provide a way to print in Babylonian-inspired
Tom> notation(s) as well, but I'm going to be seriously annoyed if
Tom> that's the only way to get the output.How about
Time: 1234567.666 ms (20m 34.6s)
That'd be fine too, it's not like we're doing anything with the rest of
that line.
Andrew Gierth wrote:
How about
Time: 1234567.666 ms (20m 34.6s)
?
+1 LGTM
--
�lvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Sat, Jul 9, 2016 at 1:48 PM, Alvaro Herrera <alvherre@2ndquadrant.com> wrote:
How about
Time: 1234567.666 ms (20m 34.6s)
?
+1 LGTM
+1
--
Peter Geoghegan
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 10/07/16 08:00, Andrew Gierth wrote:
"Tom" == Tom Lane <tgl@sss.pgh.pa.us> writes:
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
I'm not quite sure what you mean by wanting to do arithmetic on the
numbers. My phrasing of the problem is that after a long query, you
might get output like this:
Time: 1234567.666 ms
which is pretty useless.Tom> What I mean by that is that not infrequently, I'll run the same
Tom> query several times and then want to average the results. That's
Tom> easy with awk or similar scripts as long as the numbers are in
Tom> straight decimal.Tom> I don't mind if we provide a way to print in Babylonian-inspired
Tom> notation(s) as well, but I'm going to be seriously annoyed if
Tom> that's the only way to get the output.How about
Time: 1234567.666 ms (20m 34.6s)
?
I like that, but I think the human form should retain the 3 decimal places.
In a few years, we may well have enormously multiprocessor computers
with massive very fast permanent 'RAM' where the entire database is
always in memory, so timing to the nearest microsecond could be useful.
Obviously microsecond precision would be silly now, and would probably
never warrant being the default (I'd be happy to be proved wrong here!),
but it might be worthwhile putting in as an option - while people are
looking at the relevant areas of the code.
Am inspired by the man page for 'ls': [...] The SIZE argument is an
integer and optional unit (example: 10K is 10*1024). Units are
K,M,G,T,P,E,Z,Y (powers of 1024) [...]" Obviously learnt from the
lessons of "640KB should be enough for everyone" stupidity!
Cheers,
Gavin
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
"Gavin" == Gavin Flower <GavinFlower@archidevsys.co.nz> writes:
How about
Time: 1234567.666 ms (20m 34.6s)
Gavin> I like that, but I think the human form should retain the 3
Gavin> decimal places.
Scale it.
Time: 12.345 ms (0.012345s)
Time: 1234.567 ms (1.235s)
Time: 98765.432 ms (98.8s)
Time: 123456.789 ms (2m 3.5s)
Time: 12345678.666 ms (3h 24m 46s)
Gavin> In a few years, we may well have enormously multiprocessor
Gavin> computers with massive very fast permanent 'RAM' where the
Gavin> entire database is always in memory, so timing to the nearest
Gavin> microsecond could be useful.
But the original microsecond-resolution value is still right there, so I
don't see the issue.
--
Andrew (irc:RhodiumToad)
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 10/07/16 12:08, Andrew Gierth wrote:
"Gavin" == Gavin Flower <GavinFlower@archidevsys.co.nz> writes:
How about
Time: 1234567.666 ms (20m 34.6s)
Gavin> I like that, but I think the human form should retain the 3
Gavin> decimal places.Scale it.
Time: 12.345 ms (0.012345s)
Time: 1234.567 ms (1.235s)
Time: 98765.432 ms (98.8s)
Time: 123456.789 ms (2m 3.5s)
Time: 12345678.666 ms (3h 24m 46s)
Gavin> In a few years, we may well have enormously multiprocessor
Gavin> computers with massive very fast permanent 'RAM' where the
Gavin> entire database is always in memory, so timing to the nearest
Gavin> microsecond could be useful.But the original microsecond-resolution value is still right there, so I
don't see the issue.
Sorry misunderstood, thought it was milliseconds!
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 7/9/16 4:00 PM, Andrew Gierth wrote:
How about
Time: 1234567.666 ms (20m 34.6s)
That's similar to what I had in mind, so I'd be happy with that.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Mon, Jul 11, 2016 at 8:35 AM, Peter Eisentraut <
peter.eisentraut@2ndquadrant.com> wrote:
On 7/9/16 4:00 PM, Andrew Gierth wrote:
How about
Time: 1234567.666 ms (20m 34.6s)
That's similar to what I had in mind, so I'd be happy with that.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Ok, here's what I came up with (with time to test it).
If the query took less than a second, timing display is unchanged.
Otherwise, print the ms time, followed by a more human readable form
accurate to 0.001s.
# select 1; select pg_sleep(1); select pg_sleep(71); select pg_sleep
(3601); select pg_sleep(24*3601);
?column?
----------
1
(1 row)
Time: 1.575 ms
pg_sleep
----------
(1 row)
Time: 1002.568 ms (1.003s)
pg_sleep
----------
(1 row)
Time: 71041.022 ms (1m 11.041s)
pg_sleep
----------
(1 row)
Time: 3601083.544 ms (1h 0m 1.084s)
pg_sleep
----------
(1 row)
Time: 86424018.416 ms (1d 0h 0m 24.018s)
As-is, there isn't much that could be done for regression or documentation
changes, so I'll just leave this here.
Attachments:
0001-print-timing-verbose.difftext/plain; charset=US-ASCII; name=0001-print-timing-verbose.diffDownload
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 2450b9c..7a87314 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -529,6 +529,58 @@ ClearOrSaveResult(PGresult *result)
}
}
+/*
+ * Print the time elapsed in both raw milliseconds and if the time elapsed
+ * was at least 1 second, also print a format normalized to days, hours,
+ * minutes, and seconds.
+ */
+static void
+PrintTiming(double elapsed_msec)
+{
+ double seconds;
+ int minutes;
+ int hours;
+ int days;
+
+ if (elapsed_msec < 1000.0)
+ {
+ printf(_("Time: %.3f ms\n"), elapsed_msec);
+ return;
+ }
+
+ seconds = elapsed_msec / 1000.0;
+ if (seconds < 60.0)
+ {
+ printf(_("Time: %.3f ms (%.3fs)\n"), elapsed_msec, seconds);
+ return;
+ }
+
+ minutes = (int)seconds / 60;
+ seconds = seconds - (60.0 * minutes);
+ if (minutes < 60)
+ {
+ printf(_("Time: %.3f ms (%dm %.3fs)\n"),
+ elapsed_msec, minutes, seconds);
+ return;
+ }
+
+ hours = minutes / 60;
+ minutes = minutes % 60;
+
+ if (hours < 24)
+ {
+ printf(_("Time: %.3f ms (%dh %dm %.3fs)\n"),
+ elapsed_msec, hours, minutes, seconds);
+ return;
+ }
+
+ days = hours / 24;
+ hours = hours % 24;
+
+ printf(_("Time: %.3f ms (%dd %dh %dm %.3fs)\n"),
+ days, elapsed_msec, hours, minutes, seconds);
+}
+
/*
* PSQLexec
@@ -678,7 +730,7 @@ PSQLexecWatch(const char *query, const printQueryOpt *opt)
/* Possible microtiming output */
if (pset.timing)
- printf(_("Time: %.3f ms\n"), elapsed_msec);
+ PrintTiming(elapsed_msec);
return 1;
}
@@ -1328,7 +1380,7 @@ SendQuery(const char *query)
/* Possible microtiming output */
if (pset.timing)
- printf(_("Time: %.3f ms\n"), elapsed_msec);
+ PrintTiming(elapsed_msec);
/* check for events that may occur during query execution */
On 7/13/16 2:06 PM, Corey Huinker wrote:
Time: 71041.022 ms (1m 11.041s)
pg_sleep
----------(1 row)
Time: 3601083.544 ms (1h 0m 1.084s)
pg_sleep
----------(1 row)
That works for me, except that the abbreviation for minute is "min".
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
On 7/13/16 2:06 PM, Corey Huinker wrote:
Time: 3601083.544 ms (1h 0m 1.084s)
That works for me, except that the abbreviation for minute is "min".
Meh ... if we're using one-letter abbreviations for hour and second,
using three letters for minute seems just arbitrarily inconsistent.
There is zero possibility that anyone would misunderstand what unit
the "m" stands for. See also the typical output of time(1):
$ time sleep 1
real 0m1.002s
user 0m0.001s
sys 0m0.002s
(Well, I guess that's bash's builtin rather than /usr/bin/time,
but the point stands: "m" is widely accepted in this context.)
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
* Tom Lane (tgl@sss.pgh.pa.us) wrote:
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
On 7/13/16 2:06 PM, Corey Huinker wrote:
Time: 3601083.544 ms (1h 0m 1.084s)
That works for me, except that the abbreviation for minute is "min".
Meh ... if we're using one-letter abbreviations for hour and second,
using three letters for minute seems just arbitrarily inconsistent.
There is zero possibility that anyone would misunderstand what unit
the "m" stands for. See also the typical output of time(1):$ time sleep 1
real 0m1.002s
user 0m0.001s
sys 0m0.002s(Well, I guess that's bash's builtin rather than /usr/bin/time,
but the point stands: "m" is widely accepted in this context.)
Agreed.
Thanks!
Stephen
On 7/15/16 11:23 AM, Tom Lane wrote:
Meh ... if we're using one-letter abbreviations for hour and second,
using three letters for minute seems just arbitrarily inconsistent.
Well, it's the SI abbreviation.
We also need to think through localization options.
Using the 01:02:03.004 format would sidestep most of that.
Or we can still give users the option to set it to whatever they want.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
The following review has been posted through the commitfest application:
make installcheck-world: tested, failed
Implements feature: tested, failed
Spec compliant: tested, failed
Documentation: tested, failed
I could not find a way to disable this functionality , I see that the impact can be big as it is changed the output structure \timing without a mode to disable it. I even finding great functionality but need a way to set to default.
The new status of this patch is: Waiting on Author
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: tested, passed
Documentation: tested, passed
Sorry, my mistake!
I could not find a way to disable this functionality , I see that the impact can be big as it is changed the output structure \timing without a mode to disable it. I even finding great functionality but need a way to set to default.
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Wed, Aug 24, 2016 at 10:36 PM, Gerdan Santos <gerdan@gmail.com> wrote:
The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: tested, passed
Documentation: tested, passedSorry, my mistake!
I could not find a way to disable this functionality , I see that the
impact can be big as it is changed the output structure \timing without a
mode to disable it. I even finding great functionality but need a way to
set to default.
Thanks for reviewing! I'm not really sure how to proceed, so I'll try to
summarize where it stands. Apologies if I
mischaracterize/misattribute/misremember someone's position.
Generally speaking, people disliked the third mode for \timing, and were
generally fine with AndrewG's idea of printing the timing in both raw
milliseconds and a more human-digestible format, which means that we can:
1. keep the format exactly as is, ignoring locale issues
+ It's already done
+ lightweight
+TomL believes there will be no confusion
- others disagree
2. we fish out the proper locale-specific abbreviations for
days/hours/minutes/seconds
+ no additional settings
+ locale stuff can't be that hard
- I've never dealt with it (American, surprise)
3. ignore locales and fall back to a left-trimmed DDD HH:MM:SS.mmm format
+ Easy to revert to that code
+ My original format and one PeterE advocated
- others disliked
4. we have a \pset that sets fixed scale (seconds, minutes, hours, days),
sliding scale (what's displayed now), or interval
+ some flexibility with some easy config values
- still have the locale issue
- likely will miss a format somebody wanted
4. The \pset option is a time format string like "%d %h:%m:%s".
+ maximum flexibility
+ sidesteps the locale issue by putting it in the user's hands
- those format strings are sometimes tough for users to grok
- ISO 8601 isn't much of a help as it doesn't handle milliseconds
- additional config variable
- documentation changes
- debate about what the default should be. GOTO 1.I personally would be happy with any of these options, so I think we get
some more feedback to see if a consensus emerges. It's a tiny patch and
trivial to test, so we have time(ing) on our side.
OK. as I said just got confused if there was any way to disable. anyway the
code is ok, does what it says and is well formatted.
I will change now!
So sorry, for my confused.
Thnks!
Em quinta-feira, 25 de agosto de 2016, Corey Huinker <
corey.huinker@gmail.com> escreveu:
On Wed, Aug 24, 2016 at 10:36 PM, Gerdan Santos <gerdan@gmail.com
<javascript:_e(%7B%7D,'cvml','gerdan@gmail.com');>> wrote:The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: tested, passed
Documentation: tested, passedSorry, my mistake!
I could not find a way to disable this functionality , I see that the
impact can be big as it is changed the output structure \timing without a
mode to disable it. I even finding great functionality but need a way to
set to default.Thanks for reviewing! I'm not really sure how to proceed, so I'll try to
summarize where it stands. Apologies if I mischaracterize/misattribute/misremember
someone's position.Generally speaking, people disliked the third mode for \timing, and were
generally fine with AndrewG's idea of printing the timing in both raw
milliseconds and a more human-digestible format, which means that we can:1. keep the format exactly as is, ignoring locale issues + It's already done + lightweight +TomL believes there will be no confusion - others disagree 2. we fish out the proper locale-specific abbreviations for days/hours/minutes/seconds + no additional settings + locale stuff can't be that hard - I've never dealt with it (American, surprise) 3. ignore locales and fall back to a left-trimmed DDD HH:MM:SS.mmm format + Easy to revert to that code + My original format and one PeterE advocated - others disliked 4. we have a \pset that sets fixed scale (seconds, minutes, hours, days), sliding scale (what's displayed now), or interval + some flexibility with some easy config values - still have the locale issue - likely will miss a format somebody wanted 4. The \pset option is a time format string like "%d %h:%m:%s". + maximum flexibility + sidesteps the locale issue by putting it in the user's hands - those format strings are sometimes tough for users to grok - ISO 8601 isn't much of a help as it doesn't handle milliseconds - additional config variable - documentation changes - debate about what the default should be. GOTO 1.I personally would be happy with any of these options, so I think we get
some more feedback to see if a consensus emerges. It's a tiny patch and
trivial to test, so we have time(ing) on our side.
--
*Gerdan Rezende dos Santos *
*Po*stgreSQL & EnterpriseDB Specialist, Support, Training & Services
+55 (61) 9645-1525
The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: tested, passed
Documentation: tested, passed
I did some tests and found nothing special. The stated resource is implemented correctly.
He passes all regression tests and enables the use of the new features specified.
The new status of this patch is: Ready for Committer
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
[ This patch is marked Ready For Committer, and discussion seems to have
died off, so let's get on with committing something ... ]
Corey Huinker <corey.huinker@gmail.com> writes:
Generally speaking, people disliked the third mode for \timing, and were
generally fine with AndrewG's idea of printing the timing in both raw
milliseconds and a more human-digestible format, which means that we can:
Yeah, there seemed to be general agreement on just appending a more human
readable format to the existing printout.
3. ignore locales and fall back to a left-trimmed DDD HH:MM:SS.mmm format + Easy to revert to that code + My original format and one PeterE advocated - others disliked
I think this is the approach to go with as a starting point, since it
largely avoids both localization and units-naming concerns. If someone
feels the desire to build a customizable output format, that can be dealt
with as a separate patch on top of this one ... but I really question that
it'd ever be worth the trouble.
So for clarity's sake: first suitable format among these:
Time: 59.999 ms
Time: 121.999 ms (2:01.999)
Time: 10921.999 ms (3:02:01.999)
Time: 356521.999 ms (4 3:02:01.999)
In an NLS-enabled build, the translator would be able to fool with the
punctuation, though I dunno whether any translators would need to.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
I wrote:
So for clarity's sake: first suitable format among these:
Time: 59.999 ms
Time: 121.999 ms (2:01.999)
Time: 10921.999 ms (3:02:01.999)
Time: 356521.999 ms (4 3:02:01.999)
Sorry, that probably added no clarity at all, I was confusing
seconds with milliseconds in the example values :-(
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Sep 1, 2016 at 2:17 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
I wrote:
So for clarity's sake: first suitable format among these:
Time: 59.999 ms
Time: 121.999 ms (2:01.999)
Time: 10921.999 ms (3:02:01.999)
Time: 356521.999 ms (4 3:02:01.999)Sorry, that probably added no clarity at all, I was confusing
seconds with milliseconds in the example values :-(regards, tom lane
I didn't scan your examples for correctness, but the parentheticals matched
my own idea for what "left-trimmed" meant.
I'm going to hold off a bit to see if anybody else chimes in, and if not
I'm going to deliver a patch.
I wrote:
Sorry, that probably added no clarity at all, I was confusing
seconds with milliseconds in the example values :-(
After a bit of further fooling with sample values, I propose this
progression:
Time: 0.100 ms
Time: 1.200 ms
Time: 1001.200 ms (0:01.001)
Time: 12001.200 ms (0:12.001)
Time: 60001.200 ms (1:00.001)
Time: 720001.200 ms (12:00.001)
Time: 3660001.200 ms (1:01:00.001)
Time: 43920001.200 ms (12:12:00.001)
Time: 176460001.200 ms (2 01:01:00.001)
Time: 216720001.200 ms (2 12:12:00.001)
Time: 10000000000000000000.000 ms (115740740740 17:46:40.000)
Note that times from 1 second to 1 hour all get the nn:nn.nnn
treatment. I experimented with these variants for sub-minute times:
Time: 1001.200 ms (1.001)
Time: 12001.200 ms (12.001)
Time: 1001.200 ms (1.001 s)
Time: 12001.200 ms (12.001 s)
but it seems like the first variant is not terribly intelligible and
the second variant is inconsistent with what happens for longer times.
Adding a zero minutes field is a subtler way of cueing the reader that
it's mm:ss.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Corey Huinker <corey.huinker@gmail.com> writes:
I'm going to hold off a bit to see if anybody else chimes in, and if not
I'm going to deliver a patch.
I've already been updating yours, no need for another.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Sep 1, 2016 at 2:43 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
I wrote:
Sorry, that probably added no clarity at all, I was confusing
seconds with milliseconds in the example values :-(After a bit of further fooling with sample values, I propose this
progression:Time: 0.100 ms
Time: 1.200 ms
Time: 1001.200 ms (0:01.001)
Time: 12001.200 ms (0:12.001)
Time: 60001.200 ms (1:00.001)
Time: 720001.200 ms (12:00.001)
Time: 3660001.200 ms (1:01:00.001)
Time: 43920001.200 ms (12:12:00.001)
Time: 176460001.200 ms (2 01:01:00.001)
Time: 216720001.200 ms (2 12:12:00.001)
Time: 10000000000000000000.000 ms (115740740740 17:46:40.000)Note that times from 1 second to 1 hour all get the nn:nn.nnn
treatment. I experimented with these variants for sub-minute times:Time: 1001.200 ms (1.001)
Time: 12001.200 ms (12.001)
Time: 1001.200 ms (1.001 s)
Time: 12001.200 ms (12.001 s)but it seems like the first variant is not terribly intelligible and
the second variant is inconsistent with what happens for longer times.
Adding a zero minutes field is a subtler way of cueing the reader that
it's mm:ss.regards, tom lane
Well, if we're looking to be consistent, here's what interval does now:
# select '1 second 1 millisecond'::interval, '1 minute 2
milliseconds'::interval, '1 hour 30 milliseconds'::interval, '1 day 1 hour
999 milliseconds'::interval, '1 week 1 day 1 hour'::interval;
interval | interval | interval | interval |
interval
--------------+--------------+-------------+--------------------+-----------------
00:00:01.001 | 00:01:00.002 | 01:00:00.03 | 1 day 01:00:00.999 | 8 days
01:00:00
(1 row)
Should we just plug into whatever code that uses? It's slightly different:
# select interval '10000000000000000000.001 milliseconds'::interval;
ERROR: interval field value out of range: "10000000000000000000.001
milliseconds"
LINE 1: select interval '10000000000000000000.001 milliseconds'::int...
^
# select interval '216720001.200 milliseconds';
interval
---------------
60:12:00.0012
(1 row)
# select interval '176460001.200 ms';
interval
---------------
49:01:00.0012
(1 row)
Corey Huinker <corey.huinker@gmail.com> writes:
On Thu, Sep 1, 2016 at 2:43 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Note that times from 1 second to 1 hour all get the nn:nn.nnn
treatment. I experimented with these variants for sub-minute times:
...
but it seems like the first variant is not terribly intelligible and
the second variant is inconsistent with what happens for longer times.
Well, if we're looking to be consistent, here's what interval does now:
...
Should we just plug into whatever code that uses?
Well, that code's on the backend side so we're not going to just call it
in any case. And I think we don't want to be quite so verbose as to go up
to hh:mm:ss.fff as soon as we get past 1 second. However, comparing that
output to what I had suggests that maybe it's better to keep a leading
zero in two-digit fields, that is render times like "00:01.234",
"01:23.456", or "01:23:45.678" rather than suppressing the initial zero as
I had in my examples. It's an extra character but I think it reinforces
the meaning.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Sep 1, 2016 at 3:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Corey Huinker <corey.huinker@gmail.com> writes:
On Thu, Sep 1, 2016 at 2:43 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Note that times from 1 second to 1 hour all get the nn:nn.nnn
treatment. I experimented with these variants for sub-minute times:
...
but it seems like the first variant is not terribly intelligible and
the second variant is inconsistent with what happens for longer times.Well, if we're looking to be consistent, here's what interval does now:
...
Should we just plug into whatever code that uses?Well, that code's on the backend side so we're not going to just call it
in any case. And I think we don't want to be quite so verbose as to go up
to hh:mm:ss.fff as soon as we get past 1 second. However, comparing that
output to what I had suggests that maybe it's better to keep a leading
zero in two-digit fields, that is render times like "00:01.234",
"01:23.456", or "01:23:45.678" rather than suppressing the initial zero as
I had in my examples. It's an extra character but I think it reinforces
the meaning.regards, tom lane
+1
The larger jump in widths from no MM:SS to HH:MM:SS is a good visual cue.
Jumping from MM:SS to H:MM:SS to HH:MM:SS would be more subtle and possibly
confusing.
Corey Huinker <corey.huinker@gmail.com> writes:
On Thu, Sep 1, 2016 at 3:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Well, that code's on the backend side so we're not going to just call it
in any case. And I think we don't want to be quite so verbose as to go up
to hh:mm:ss.fff as soon as we get past 1 second. However, comparing that
output to what I had suggests that maybe it's better to keep a leading
zero in two-digit fields, that is render times like "00:01.234",
"01:23.456", or "01:23:45.678" rather than suppressing the initial zero as
I had in my examples. It's an extra character but I think it reinforces
the meaning.
+1
The larger jump in widths from no MM:SS to HH:MM:SS is a good visual cue.
Jumping from MM:SS to H:MM:SS to HH:MM:SS would be more subtle and possibly
confusing.
Attached is an updated patch that does it like that. Sample output
(generated by forcing specific arguments to PrintTiming):
Time: 0.100 ms
Time: 1.200 ms
Time: 1001.200 ms (00:01.001)
Time: 12001.200 ms (00:12.001)
Time: 60001.200 ms (01:00.001)
Time: 720001.200 ms (12:00.001)
Time: 3660001.200 ms (01:01:00.001)
Time: 43920001.200 ms (12:12:00.001)
Time: 176460001.200 ms (2 01:01:00.001)
Time: 216720001.200 ms (2 12:12:00.001)
Time: 8816460001.200 ms (102 01:01:00.001)
Time: 8856720001.200 ms (102 12:12:00.001)
Barring objections I'll commit this soon.
regards, tom lane
Attachments:
psql-timing-human-3.patchtext/x-diff; charset=us-ascii; name=psql-timing-human-3.patchDownload
diff --git a/doc/src/sgml/ref/psql-ref.sgml b/doc/src/sgml/ref/psql-ref.sgml
index 8a66ce7..88e2f66 100644
*** a/doc/src/sgml/ref/psql-ref.sgml
--- b/doc/src/sgml/ref/psql-ref.sgml
*************** testdb=> <userinput>\setenv LESS -imx
*** 2789,2796 ****
<term><literal>\timing [ <replaceable class="parameter">on</replaceable> | <replaceable class="parameter">off</replaceable> ]</literal></term>
<listitem>
<para>
! Without parameter, toggles a display of how long each SQL statement
! takes, in milliseconds. With parameter, sets same.
</para>
</listitem>
</varlistentry>
--- 2789,2798 ----
<term><literal>\timing [ <replaceable class="parameter">on</replaceable> | <replaceable class="parameter">off</replaceable> ]</literal></term>
<listitem>
<para>
! With a parameter, turns displaying of how long each SQL statement
! takes on or off. Without a parameter, toggles the display between
! on and off. The display is in milliseconds; intervals longer than
! 1 second are also shown in days/hours/minutes/seconds format.
</para>
</listitem>
</varlistentry>
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 7399950..a17f1de 100644
*** a/src/bin/psql/common.c
--- b/src/bin/psql/common.c
***************
*** 10,15 ****
--- 10,16 ----
#include <ctype.h>
#include <limits.h>
+ #include <math.h>
#include <signal.h>
#ifndef WIN32
#include <unistd.h> /* for write() */
*************** ClearOrSaveResult(PGresult *result)
*** 530,535 ****
--- 531,586 ----
}
}
+ /*
+ * Print microtiming output. Always print raw milliseconds; if the interval
+ * is >= 1 second, also break it down into days/hours/minutes/seconds.
+ */
+ static void
+ PrintTiming(double elapsed_msec)
+ {
+ double seconds;
+ double minutes;
+ double hours;
+ double days;
+
+ if (elapsed_msec < 1000.0)
+ {
+ /* This is the traditional (pre-v10) output format */
+ printf(_("Time: %.3f ms\n"), elapsed_msec);
+ return;
+ }
+
+ /*
+ * Note: we could print just seconds, in a format like %06.3f, when the
+ * total is less than 1min. But that's hard to interpret unless we tack
+ * on "s" or otherwise annotate it. Forcing the display to include
+ * minutes seems like a better solution.
+ */
+ seconds = elapsed_msec / 1000.0;
+ minutes = floor(seconds / 60.0);
+ seconds -= 60.0 * minutes;
+ if (minutes < 60.0)
+ {
+ printf(_("Time: %.3f ms (%02d:%06.3f)\n"),
+ elapsed_msec, (int) minutes, seconds);
+ return;
+ }
+
+ hours = floor(minutes / 60.0);
+ minutes -= 60.0 * hours;
+ if (hours < 24.0)
+ {
+ printf(_("Time: %.3f ms (%02d:%02d:%06.3f)\n"),
+ elapsed_msec, (int) hours, (int) minutes, seconds);
+ return;
+ }
+
+ days = floor(hours / 24.0);
+ hours -= 24.0 * days;
+ printf(_("Time: %.3f ms (%.0f %02d:%02d:%06.3f)\n"),
+ elapsed_msec, days, (int) hours, (int) minutes, seconds);
+ }
+
/*
* PSQLexec
*************** PSQLexecWatch(const char *query, const p
*** 679,685 ****
/* Possible microtiming output */
if (pset.timing)
! printf(_("Time: %.3f ms\n"), elapsed_msec);
return 1;
}
--- 730,736 ----
/* Possible microtiming output */
if (pset.timing)
! PrintTiming(elapsed_msec);
return 1;
}
*************** SendQuery(const char *query)
*** 1332,1338 ****
/* Possible microtiming output */
if (pset.timing)
! printf(_("Time: %.3f ms\n"), elapsed_msec);
/* check for events that may occur during query execution */
--- 1383,1389 ----
/* Possible microtiming output */
if (pset.timing)
! PrintTiming(elapsed_msec);
/* check for events that may occur during query execution */
On Thu, Sep 1, 2016 at 12:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Corey Huinker <corey.huinker@gmail.com> writes:
On Thu, Sep 1, 2016 at 3:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Well, that code's on the backend side so we're not going to just call it
in any case. And I think we don't want to be quite so verbose as to goup
to hh:mm:ss.fff as soon as we get past 1 second. However, comparing
that
output to what I had suggests that maybe it's better to keep a leading
zero in two-digit fields, that is render times like "00:01.234",
"01:23.456", or "01:23:45.678" rather than suppressing the initial zeroas
I had in my examples. It's an extra character but I think it reinforces
the meaning.+1
The larger jump in widths from no MM:SS to HH:MM:SS is a good visual cue.
Jumping from MM:SS to H:MM:SS to HH:MM:SS would be more subtle andpossibly
confusing.
Attached is an updated patch that does it like that. Sample output
(generated by forcing specific arguments to PrintTiming):Time: 0.100 ms
Time: 1.200 ms
Time: 1001.200 ms (00:01.001)
Time: 12001.200 ms (00:12.001)
Time: 60001.200 ms (01:00.001)
Time: 720001.200 ms (12:00.001)
Time: 3660001.200 ms (01:01:00.001)
Time: 43920001.200 ms (12:12:00.001)
Time: 176460001.200 ms (2 01:01:00.001)
Time: 216720001.200 ms (2 12:12:00.001)
Time: 8816460001.200 ms (102 01:01:00.001)
Time: 8856720001.200 ms (102 12:12:00.001)Barring objections I'll commit this soon.
regards, tom lane
Some kind of units on the parenthetical format would be helpful. Glancing
at several of these values it takes me a couple of seconds to decide what
I'm reading.
--
Peter van Hardenberg
San Francisco, California
"Everything was beautiful, and nothing hurt."—Kurt Vonnegut
Peter van Hardenberg <pvh@pvh.ca> writes:
Some kind of units on the parenthetical format would be helpful.
I was really hoping to not re-open that can of worms :-(
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
I wrote:
Attached is an updated patch that does it like that. Sample output
(generated by forcing specific arguments to PrintTiming):
Time: 0.100 ms
Time: 1.200 ms
Time: 1001.200 ms (00:01.001)
Time: 12001.200 ms (00:12.001)
Time: 60001.200 ms (01:00.001)
Time: 720001.200 ms (12:00.001)
Time: 3660001.200 ms (01:01:00.001)
Time: 43920001.200 ms (12:12:00.001)
Time: 176460001.200 ms (2 01:01:00.001)
Time: 216720001.200 ms (2 12:12:00.001)
Time: 8816460001.200 ms (102 01:01:00.001)
Time: 8856720001.200 ms (102 12:12:00.001)
After further thought I concluded that not providing any labeling of
days is a bad idea. The hours, minutes, and seconds fields seem
reasonably self-explanatory given the formatting, but days not so much.
(I'm not sure whether that is the whole of Peter van H's objection,
but surely it's part of it.) I pushed the patch using this:
Time: 176460001.200 ms (2 d 01:01:00.001)
and all else as before.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 9/3/16 2:35 PM, Tom Lane wrote:
I pushed the patch using this:
Time: 176460001.200 ms (2 d 01:01:00.001)
and all else as before.
I'd find this useful in the final output of EXPLAIN ANALYZE as well; any
objections to adding it?
--
Jim Nasby, Data Architect, Blue Treble Consulting, Austin TX
Experts in Analytics, Data Architecture and PostgreSQL
Data in Trouble? Get it in Treble! http://BlueTreble.com
855-TREBLE2 (855-873-2532) mobile: 512-569-9461
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Sun, Sep 4, 2016 at 7:05 PM, Jim Nasby <Jim.Nasby@bluetreble.com> wrote:
On 9/3/16 2:35 PM, Tom Lane wrote:
I pushed the patch using this:
Time: 176460001.200 ms (2 d 01:01:00.001)
and all else as before.
I'd find this useful in the final output of EXPLAIN ANALYZE as well; any
objections to adding it?
It's sorta out of my hands now, but what Tom said earlier is that because
this is client-side code, it wouldn't use existing interval code.
EXPLAIN *is* server-side, we couldn't use this code, but we could leverage
existing interval code there to achieve a similar concept.
I have another thing I'd like to add to EXPLAIN output : server version
number output. So maybe we can pick those up in another thread.
Corey Huinker <corey.huinker@gmail.com> writes:
On Sun, Sep 4, 2016 at 7:05 PM, Jim Nasby <Jim.Nasby@bluetreble.com> wrote:
I'd find this useful in the final output of EXPLAIN ANALYZE as well; any
objections to adding it?
It's sorta out of my hands now, but what Tom said earlier is that because
this is client-side code, it wouldn't use existing interval code.
EXPLAIN *is* server-side, we couldn't use this code, but we could leverage
existing interval code there to achieve a similar concept.
If we like this specific output format, I'd be inclined to just
copy-and-paste the code from psql. I seriously doubt that getting type
interval involved in the discussion would lead to a shorter or
better-performing solution.
I have another thing I'd like to add to EXPLAIN output : server version
number output. So maybe we can pick those up in another thread.
Ugh. There are multiple ways to get that already, and it's not like
space in EXPLAIN's output is not a precious resource.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 9/6/16 1:45 PM, Tom Lane wrote:
It's sorta out of my hands now, but what Tom said earlier is that because
this is client-side code, it wouldn't use existing interval code.
EXPLAIN *is* server-side, we couldn't use this code, but we could leverage
existing interval code there to achieve a similar concept.If we like this specific output format, I'd be inclined to just
copy-and-paste the code from psql. I seriously doubt that getting type
interval involved in the discussion would lead to a shorter or
better-performing solution.
If we could actually execute user functions as part of EXPLAIN
generating it's output then it might be a lot less invasive... but I
don't think that's an option.
I have another thing I'd like to add to EXPLAIN output : server version
number output. So maybe we can pick those up in another thread.Ugh. There are multiple ways to get that already, and it's not like
space in EXPLAIN's output is not a precious resource.
I don't think adding a line would be that bad, and it would probably
greatly reduce the amount of mailing list traffic asking for version if
nothing else. It might also be useful to tools like
https://explain.depesz.com/. If nothing else it's probably worth adding
to the non-text output formats.
--
Jim Nasby, Data Architect, Blue Treble Consulting, Austin TX
Experts in Analytics, Data Architecture and PostgreSQL
Data in Trouble? Get it in Treble! http://BlueTreble.com
855-TREBLE2 (855-873-2532) mobile: 512-569-9461
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
... and it would probably greatly reduce the amount of mailing list
traffic asking for version if nothing else.
That was the major reason for wanting it.
The second is that if an explain were posted to a forum like stackexchange,
the reader wouldn't have to wonder what version produced the plan.
On 4 Sep. 2016 3:36 am, "Tom Lane" <tgl@sss.pgh.pa.us> wrote:
After further thought I concluded that not providing any labeling of
days is a bad idea.
Yeah. I think labeling days is definitely good. I'm glad you changed that.
Personally I'd like to trim milliseconds when dealing with minute+ long
runs and seconds from hour+ runs too, since it's all there in the ms output
and the units output is for human readability. I see the value of retaining
full precision too, though, and don't feel strongly about it.
2016-09-08 13:10 GMT+02:00 Craig Ringer <craig.ringer@2ndquadrant.com>:
On 4 Sep. 2016 3:36 am, "Tom Lane" <tgl@sss.pgh.pa.us> wrote:
After further thought I concluded that not providing any labeling of
days is a bad idea.Yeah. I think labeling days is definitely good. I'm glad you changed that.
Personally I'd like to trim milliseconds when dealing with minute+ long
runs and seconds from hour+ runs too, since it's all there in the ms output
and the units output is for human readability. I see the value of retaining
full precision too, though, and don't feel strongly about it.
It should be hard to read without units. I know so now it is maybe late,
but the current output is not too readable for me. I miss units - 10s,
1m20.5s, 1h 30m 5s
Regards
Pavel