On Wed, Jan 22, 2020 at 02:34:57PM +0900, Michael Paquier wrote:
> From patch 0003:
> /*
> + * Indent multi-line DETAIL if being sent to client (verbose)
> + * We don't know if it's sent to the client (client_min_messages);
> + * Also, that affects output to the logfile, too; assume that it's
> more
> + * important to format messages requested by the client than to make
> + * verbose logs pretty when also sent to the logfile.
> + */
> + msgprefix = elevel==INFO ? "!\t" : "";
> Such stuff gets a -1 from me. This is not project-like, and you make
> the translation of those messages much harder than they should be.
I don't see why its harder to translate ? Do you mean because it changes the
strings by adding %s ?
- appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
- "%u
pages are entirely empty.\n",
+ appendStringInfo(&sbuf, ngettext("%s%u page is entirely empty.\n",
+ "%s%u
pages are entirely empty.\n",
...
I did raise two questions regarding translation:
I'm not sure why this one doesn't use get ngettext() ? Seems to have been
missed at a8d585c0.
|appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
Or why this one does use _/gettext() ? (580ddcec suggests that I'm missing
something, but I just experimented, and it really seems to do nothing, since
"%s" shouldn't be translated).
|appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
Also, I realized it's possible to write different strings to the log vs the
client (with and without a prefix) by calling errdetail_internal() and
errdetail_log().
Here's a version rebased on top of f942dfb9, and making use of errdetail_log.
I'm not sure if it address your concern about translation, but it doesn't
change strings.
I think it's not needed or desirable to change what's written to the logfile,
since CSV logs have a separate "detail" field, and text logs are indented. The
server log is unchanged:
> 2020-01-25 23:08:40.451 CST [13971] INFO: "t": removed 0, found 160
> nonremovable row versions in 1 out of 888 pages
> 2020-01-25 23:08:40.451 CST [13971] DETAIL: 0 dead row versions cannot be
> removed yet, oldest xmin: 781
> There were 0 unused item identifiers.
> Skipped 0 pages due to buffer pins, 444 frozen pages.
> 0 pages are entirely empty.
> CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s.
If VERBOSE, then the client log has ! prefixes, with the style borrowed from
ShowUsage:
> INFO: "t": removed 0, found 160 nonremovable row versions in 1 out of 888
> pages
> DETAIL: ! 0 dead row versions cannot be removed yet, oldest xmin: 781
> ! There were 0 unused item identifiers.
> ! Skipped 0 pages due to buffer pins, 444 frozen pages.
> ! 0 pages are entirely empty.
> ! CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s.
I mentioned before that maybe the client's messages with newlines should be
indented similarly to how the they're done in the text logfile. I looked,
that's append_with_tabs() in elog.c. So that's a different possible
implementation, which would apply to any message with newlines (or possibly
just DETAIL).
I'll also fork the allvisible/frozen/hintbits patches to a separate thread.
Thanks,
Justin
>From a3d0b41435655615ab13f808ec7c30e53e596e50 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryz...@telsasoft.com>
Date: Sat, 25 Jan 2020 21:25:37 -0600
Subject: [PATCH v3 1/4] Remove gettext erronously readded at 580ddce
---
src/backend/access/heap/vacuumlazy.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 8ce5011..8e8ea9d 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1690,7 +1690,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
"%u pages are entirely empty.\n",
empty_pages),
empty_pages);
- appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
+ appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
ereport(elevel,
(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
--
2.7.4
>From 2db7c4e3482120b2a83cda74603f2454da7eaa03 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryz...@telsasoft.com>
Date: Sat, 25 Jan 2020 22:50:46 -0600
Subject: [PATCH v3 2/4] vacuum verbose: use ngettext() everywhere possible
---
src/backend/access/heap/vacuumlazy.c | 9 ++++++---
1 file changed, 6 insertions(+), 3 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 8e8ea9d..eb903d5 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1673,10 +1673,13 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
* individual parts of the message when not applicable.
*/
initStringInfo(&buf);
- appendStringInfo(&buf,
- _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
+ appendStringInfo(&buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
+ "%.0f dead row versions cannot be removed yet, oldest xmin: %u\n",
+ nkeep),
nkeep, OldestXmin);
- appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
+ appendStringInfo(&buf, ngettext("There was %.0f unused item identifier.\n",
+ "There were %.0f unused item identifiers.\n",
+ nunused),
nunused);
appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
"Skipped %u pages due to buffer pins, ",
--
2.7.4
>From 3467bf485972065f73c25a8f1e66c7c4f0bd5d23 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryz...@telsasoft.com>
Date: Sat, 25 Jan 2020 21:47:05 -0600
Subject: [PATCH v3 3/4] vacuum verbose: prefix write multi-line output to
client..
..but do not change output to logfile, which isn't unclear.
I borrowed the format from ShowUsage.
TODO: lazy_cleanup_index
---
src/backend/access/heap/vacuumlazy.c | 58 ++++++++++++++++++++++++++----------
1 file changed, 43 insertions(+), 15 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index eb903d5..6f85af7 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -307,6 +307,7 @@ static BufferAccessStrategy vac_strategy;
static void lazy_scan_heap(Relation onerel, VacuumParams *params,
LVRelStats *vacrelstats, Relation *Irel, int nindexes,
bool aggressive);
+static void vacuum_msg(StringInfoData *buf, const char *prefix, LVRelStats *vacrelstats, double nkeep, double nunused, BlockNumber empty_pages, PGRUsage *ru0);
static void lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats);
static bool lazy_check_needs_freeze(Buffer buf, bool *hastup);
static void lazy_vacuum_all_indexes(Relation onerel, Relation *Irel,
@@ -717,7 +718,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
BlockNumber next_unskippable_block;
bool skipping_blocks;
xl_heap_freeze_tuple *frozen;
- StringInfoData buf;
+ StringInfoData logdetail,
+ clientdetail;
const int initprog_index[] = {
PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -1668,40 +1670,66 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
RelationGetRelationName(onerel),
tups_vacuumed, vacuumed_pages)));
+ /* Write separate log messages to client (with prefix) and logfile (without prefix) */
+ vacuum_msg(&logdetail, "", vacrelstats, nkeep, nunused, empty_pages, &ru0);
+ vacuum_msg(&clientdetail, "! ", vacrelstats, nkeep, nunused, empty_pages, &ru0);
+
+ ereport(elevel,
+ (errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
+ RelationGetRelationName(onerel),
+ tups_vacuumed, num_tuples,
+ vacrelstats->scanned_pages, nblocks),
+ errdetail_log("%s", logdetail.data),
+ errdetail_internal("%s", clientdetail.data)));
+
+ pfree(logdetail.data);
+ pfree(clientdetail.data);
+}
+
+/* Populate buf with string to be freed by caller */
+static void
+vacuum_msg(StringInfoData *buf, const char *prefix, LVRelStats *vacrelstats, double nkeep, double nunused, BlockNumber empty_pages, PGRUsage *ru0)
+{
/*
* This is pretty messy, but we split it up so that we can skip emitting
* individual parts of the message when not applicable.
*/
- initStringInfo(&buf);
- appendStringInfo(&buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
+ initStringInfo(buf);
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
"%.0f dead row versions cannot be removed yet, oldest xmin: %u\n",
nkeep),
nkeep, OldestXmin);
- appendStringInfo(&buf, ngettext("There was %.0f unused item identifier.\n",
+
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, ngettext("There was %.0f unused item identifier.\n",
"There were %.0f unused item identifiers.\n",
nunused),
nunused);
- appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
+
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, ngettext("Skipped %u page due to buffer pins, ",
"Skipped %u pages due to buffer pins, ",
vacrelstats->pinskipped_pages),
vacrelstats->pinskipped_pages);
- appendStringInfo(&buf, ngettext("%u frozen page.\n",
+ appendStringInfo(buf, ngettext("%u frozen page.\n",
"%u frozen pages.\n",
vacrelstats->frozenskipped_pages),
vacrelstats->frozenskipped_pages);
- appendStringInfo(&buf, ngettext("%u page is entirely empty.\n",
+
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, ngettext("%u page is entirely empty.\n",
"%u pages are entirely empty.\n",
empty_pages),
empty_pages);
- appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
- ereport(elevel,
- (errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
- RelationGetRelationName(onerel),
- tups_vacuumed, num_tuples,
- vacrelstats->scanned_pages, nblocks),
- errdetail_internal("%s", buf.data)));
- pfree(buf.data);
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, "%s.", pg_rusage_show(ru0));
}
/*
--
2.7.4
>From 55fea31f5d3d99a94eba206ec5a75f94e1f43097 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryz...@telsasoft.com>
Date: Sun, 15 Dec 2019 17:00:29 -0600
Subject: [PATCH v3 4/4] reduce to DEBUG status logged from vacuum_heap/index..
..since they can run multiple times, which is both excessively noisy, and
confusing, due to showing multiple, multi-line messages with rusage.
Also output (at DEBUG) a message indicating the action to be taken, before
starting it. To avoid outputting a message about completion of one step, and
taking a long time before outputting anything about the next/current step.
I'm taking as a guiding principle to elog whenever calling
pgstat_progress_update_param.
---
src/backend/access/heap/vacuumlazy.c | 24 +++++++++++++++++-------
1 file changed, 17 insertions(+), 7 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 6f85af7..95d999f 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -501,6 +501,7 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
lazy_truncate_heap(onerel, vacrelstats);
/* Report that we are now doing final cleanup */
+ elog(DEBUG1, "cleaning up");
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_FINAL_CLEANUP);
@@ -1773,9 +1774,12 @@ lazy_vacuum_all_indexes(Relation onerel, Relation *Irel,
{
int idx;
- for (idx = 0; idx < nindexes; idx++)
+ for (idx = 0; idx < nindexes; idx++) {
+ ereport(DEBUG1, (errmsg("\"%s\": vacuuming index",
+ RelationGetRelationName(Irel[idx]))));
lazy_vacuum_index(Irel[idx], &stats[idx], vacrelstats->dead_tuples,
vacrelstats->old_live_tuples);
+ }
}
/* Increase and report the number of index scans */
@@ -1805,6 +1809,8 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
Buffer vmbuffer = InvalidBuffer;
/* Report that we are now vacuuming the heap */
+ ereport(DEBUG1, (errmsg("\"%s\": vacuuming heap",
+ RelationGetRelationName(onerel))));
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_VACUUM_HEAP);
@@ -1848,7 +1854,7 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
vmbuffer = InvalidBuffer;
}
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg("\"%s\": removed %d row versions in %d pages",
RelationGetRelationName(onerel),
tupindex, npages),
@@ -2093,13 +2099,13 @@ lazy_parallel_vacuum_indexes(Relation *Irel, IndexBulkDeleteResult **stats,
}
if (lps->lvshared->for_cleanup)
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(ngettext("launched %d parallel vacuum worker for index cleanup (planned: %d)",
"launched %d parallel vacuum workers for index cleanup (planned: %d)",
lps->pcxt->nworkers_launched),
lps->pcxt->nworkers_launched, nworkers)));
else
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(ngettext("launched %d parallel vacuum worker for index vacuuming (planned: %d)",
"launched %d parallel vacuum workers for index vacuuming (planned: %d)",
lps->pcxt->nworkers_launched),
@@ -2326,10 +2332,13 @@ lazy_cleanup_all_indexes(Relation *Irel, IndexBulkDeleteResult **stats,
}
else
{
- for (idx = 0; idx < nindexes; idx++)
+ for (idx = 0; idx < nindexes; idx++) {
+ ereport(DEBUG1, (errmsg("cleaning up index \"%s\"",
+ RelationGetRelationName(Irel[idx]))));
lazy_cleanup_index(Irel[idx], &stats[idx],
vacrelstats->new_rel_tuples,
vacrelstats->tupcount_pages < vacrelstats->rel_pages);
+ }
}
}
@@ -2369,7 +2378,7 @@ lazy_vacuum_index(Relation indrel, IndexBulkDeleteResult **stats,
else
msg = gettext_noop("scanned index \"%s\" to remove %d row versions");
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(msg,
RelationGetRelationName(indrel),
dead_tuples->num_tuples),
@@ -2412,7 +2421,7 @@ lazy_cleanup_index(Relation indrel,
else
msg = gettext_noop("index \"%s\" now contains %.0f row versions in %u pages");
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(msg,
RelationGetRelationName(indrel),
(*stats)->num_index_tuples,
@@ -2476,6 +2485,7 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
pg_rusage_init(&ru0);
/* Report that we are now truncating */
+ elog(DEBUG1, "truncating heap");
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_TRUNCATE);
--
2.7.4
