Make getrusage() output a little more readable
The getrusage() output that is shown by VACUUM VERBOSE and other places
has always been a little too terse and confusing for me. I propose to
improve that a bit:
-CPU 0.01s/0.08u sec elapsed 0.18 sec.
+CPU: user: 0.08s, system: 0.01s, elapsed: 0.18s.
Patch attached.
I have also updated the ShowUsage() output used by log_parser_stats etc.
to match this change, but I don't claim that that output is particularly
readable either way.
While updating the VACUUM man page I noticed that the example output
doesn't match exactly anymore, but I didn't do anything about that in
this patch, just changed the lines that are affected by this patch.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Attachments:
0001-Make-getrusage-output-a-little-more-readable.patchtext/x-patch; name=0001-Make-getrusage-output-a-little-more-readable.patchDownload
From 56bc77e09cd653d768722b8561b78b532d71860e Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <peter_e@gmx.net>
Date: Fri, 14 Oct 2016 12:00:00 -0400
Subject: [PATCH] Make getrusage() output a little more readable
---
doc/src/sgml/ref/vacuum.sgml | 12 ++++++------
src/backend/tcop/postgres.c | 10 +++++-----
src/backend/utils/misc/pg_rusage.c | 6 +++---
3 files changed, 14 insertions(+), 14 deletions(-)
diff --git a/doc/src/sgml/ref/vacuum.sgml b/doc/src/sgml/ref/vacuum.sgml
index dee1c5b..275b5e0 100644
--- a/doc/src/sgml/ref/vacuum.sgml
+++ b/doc/src/sgml/ref/vacuum.sgml
@@ -253,27 +253,27 @@ <title>Examples</title>
INFO: index "onek_unique1" now contains 1000 tuples in 14 pages
DETAIL: 3000 index tuples were removed.
0 index pages have been deleted, 0 are currently reusable.
-CPU 0.01s/0.08u sec elapsed 0.18 sec.
+CPU: user: 0.08s, system: 0.01s, elapsed: 0.18s.
INFO: index "onek_unique2" now contains 1000 tuples in 16 pages
DETAIL: 3000 index tuples were removed.
0 index pages have been deleted, 0 are currently reusable.
-CPU 0.00s/0.07u sec elapsed 0.23 sec.
+CPU: user: 0.07s, system: 0.00s, elapsed: 0.23s.
INFO: index "onek_hundred" now contains 1000 tuples in 13 pages
DETAIL: 3000 index tuples were removed.
0 index pages have been deleted, 0 are currently reusable.
-CPU 0.01s/0.08u sec elapsed 0.17 sec.
+CPU: user: 0.08s, system: 0.01s, elapsed: 0.17s.
INFO: index "onek_stringu1" now contains 1000 tuples in 48 pages
DETAIL: 3000 index tuples were removed.
0 index pages have been deleted, 0 are currently reusable.
-CPU 0.01s/0.09u sec elapsed 0.59 sec.
+CPU: user: 0.09s, system: 0.01s, elapsed: 0.59s.
INFO: "onek": removed 3000 tuples in 108 pages
-DETAIL: CPU 0.01s/0.06u sec elapsed 0.07 sec.
+DETAIL: CPU: user: 0.06s, system: 0.01s, elapsed: 0.07s.
INFO: "onek": found 3000 removable, 1000 nonremovable tuples in 143 pages
DETAIL: 0 dead tuples cannot be removed yet.
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins.
0 pages are entirely empty.
-CPU 0.07s/0.39u sec elapsed 1.56 sec.
+CPU: user: 0.39s, system: 0.07s, elapsed: 1.56s.
INFO: analyzing "public.onek"
INFO: "onek": 36 pages, 1000 rows sampled, 1000 estimated total rows
VACUUM
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 2347f1b..5853caf 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4422,15 +4422,15 @@ ShowUsage(const char *title)
appendStringInfoString(&str, "! system usage stats:\n");
appendStringInfo(&str,
- "!\t%ld.%06ld elapsed %ld.%06ld user %ld.%06ld system sec\n",
- (long) (elapse_t.tv_sec - Save_t.tv_sec),
- (long) (elapse_t.tv_usec - Save_t.tv_usec),
+ "!\t%ld.%06lds user, %ld.%06lds system, %ld.%06lds elapsed\n",
(long) (r.ru_utime.tv_sec - Save_r.ru_utime.tv_sec),
(long) (r.ru_utime.tv_usec - Save_r.ru_utime.tv_usec),
(long) (r.ru_stime.tv_sec - Save_r.ru_stime.tv_sec),
- (long) (r.ru_stime.tv_usec - Save_r.ru_stime.tv_usec));
+ (long) (r.ru_stime.tv_usec - Save_r.ru_stime.tv_usec),
+ (long) (elapse_t.tv_sec - Save_t.tv_sec),
+ (long) (elapse_t.tv_usec - Save_t.tv_usec));
appendStringInfo(&str,
- "!\t[%ld.%06ld user %ld.%06ld sys total]\n",
+ "!\t[%ld.%06lds user, %ld.%06lds system total]\n",
(long) user.tv_sec,
(long) user.tv_usec,
(long) sys.tv_sec,
diff --git a/src/backend/utils/misc/pg_rusage.c b/src/backend/utils/misc/pg_rusage.c
index 8781a38..cbaced7 100644
--- a/src/backend/utils/misc/pg_rusage.c
+++ b/src/backend/utils/misc/pg_rusage.c
@@ -61,11 +61,11 @@ pg_rusage_show(const PGRUsage *ru0)
}
snprintf(result, sizeof(result),
- "CPU %d.%02ds/%d.%02du sec elapsed %d.%02d sec",
- (int) (ru1.ru.ru_stime.tv_sec - ru0->ru.ru_stime.tv_sec),
- (int) (ru1.ru.ru_stime.tv_usec - ru0->ru.ru_stime.tv_usec) / 10000,
+ "CPU: user: %d.%02ds, system: %d.%02ds, elapsed: %d.%02ds",
(int) (ru1.ru.ru_utime.tv_sec - ru0->ru.ru_utime.tv_sec),
(int) (ru1.ru.ru_utime.tv_usec - ru0->ru.ru_utime.tv_usec) / 10000,
+ (int) (ru1.ru.ru_stime.tv_sec - ru0->ru.ru_stime.tv_sec),
+ (int) (ru1.ru.ru_stime.tv_usec - ru0->ru.ru_stime.tv_usec) / 10000,
(int) (ru1.tv.tv_sec - ru0->tv.tv_sec),
(int) (ru1.tv.tv_usec - ru0->tv.tv_usec) / 10000);
--
2.10.1
On Fri, Oct 14, 2016 at 10:06 AM, Peter Eisentraut
<peter.eisentraut@2ndquadrant.com> wrote:
The getrusage() output that is shown by VACUUM VERBOSE and other places
has always been a little too terse and confusing for me. I propose to
improve that a bit:-CPU 0.01s/0.08u sec elapsed 0.18 sec. +CPU: user: 0.08s, system: 0.01s, elapsed: 0.18s.Patch attached.
I have also updated the ShowUsage() output used by log_parser_stats etc.
to match this change, but I don't claim that that output is particularly
readable either way.While updating the VACUUM man page I noticed that the example output
doesn't match exactly anymore, but I didn't do anything about that in
this patch, just changed the lines that are affected by this patch.
+1 for this change.
I have reviewed the patch and it seems fine.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Fri, Oct 14, 2016 at 7:06 AM, Peter Eisentraut
<peter.eisentraut@2ndquadrant.com> wrote:
The getrusage() output that is shown by VACUUM VERBOSE and other places
has always been a little too terse and confusing for me. I propose to
improve that a bit:-CPU 0.01s/0.08u sec elapsed 0.18 sec. +CPU: user: 0.08s, system: 0.01s, elapsed: 0.18s.
I look at trace_sort output a lot, and do agree that this is confusing. +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