Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1ivacD-0006EE-Ol for pgsql-hackers@arkaria.postgresql.org; Sun, 26 Jan 2020 05:37:46 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1ivabC-0007Zo-LO for pgsql-hackers@arkaria.postgresql.org; Sun, 26 Jan 2020 05:36:42 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1ivabB-0007Ue-VA for pgsql-hackers@lists.postgresql.org; Sun, 26 Jan 2020 05:36:42 +0000 Received: from mail-yw1-xc43.google.com ([2607:f8b0:4864:20::c43]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1ivab4-0007kN-32 for pgsql-hackers@postgresql.org; Sun, 26 Jan 2020 05:36:40 +0000 Received: by mail-yw1-xc43.google.com with SMTP id i190so3171119ywc.2 for ; Sat, 25 Jan 2020 21:36:33 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=telsasoft-com.20150623.gappssmtp.com; s=20150623; h=date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to:user-agent; bh=f4cF5jEB98EM+r2QcorCXzfF4IeB3LokIZwrXhNypnU=; b=oG1e4Z60OOxCsN5WvKoznwJl7rSsyPoQsmT92f/zhVSKN38CZ1V1+dcinaNv1v9IM3 t4d4fnw+1Ot8Px03ES87rKDyCY3hsz1pGc1M1q4x7WC8BUfbcRP/laClmHM7/Hr4Ao5A KAUgkiO3iHwivYc93EFFoCuzk824bVnRUgsxxGkwXY6wanx28XqqXvX8ZEzABriWp3Sj pvH6JZJhtfbvOBXn65iA1OJDx2Zt7ewgDcx3vimiUzOczF7fS6z7Lqeye9W35FFq3Upu iDRAvje20tyamha6H3cn5pnEIBTqETkjDjcs5/cJypDgAj4vn0NjZnZDW39ydNGZuH/a dh0A== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to:user-agent; bh=f4cF5jEB98EM+r2QcorCXzfF4IeB3LokIZwrXhNypnU=; b=tFCNpN7jCoG7PjjAWH6nhXE5TTY+FRY5nnA183NlswpG/bVxUuIeE8Td636wf6z9Ry 18xpzf2cR9xxvFlqVVKmQeC9d5tSjUPo3S/tyDRftpsMk5MWs1DTCM2+4srluCxujCzD 8V6j9YDGgGuF+K+esJQ+x7oTscCMif6gF36eVqOiQy4yjo9ulem9VZtN1jUh0bUJpsh5 nXMlhHk1lRwoyEXS/yX5/L/F0iXmxAIYHGRqWVG4vUf1VQmGXnYMLrFXJDbz9zBHw5X/ zgCbe9avf7DycuzOePTopobbp5PdEsCHSDvDHU4SnBg/Cx7iJRmhfDh5O/t4PSIqO4FO uJtQ== X-Gm-Message-State: APjAAAXTh5+MsR5S6TfLNwUQJexRQpCPQnRCjL6AivdnK+0nxrbhC4B1 7xWLUlzcTbdntWMScX8ZYrsPog== X-Google-Smtp-Source: APXvYqxSmctqlO3138Xhmxpi0y9GXgoiSh0kHIUaO8upME1A8PNrMxQdJkx8kBHWV8bUoyQxkzjisw== X-Received: by 2002:a0d:cec3:: with SMTP id q186mr7988230ywd.394.1580016992543; Sat, 25 Jan 2020 21:36:32 -0800 (PST) Received: from pryzbyj (charmander.telsasoft.com. [50.244.222.1]) by smtp.gmail.com with ESMTPSA id t142sm4918621ywf.53.2020.01.25.21.36.31 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Sat, 25 Jan 2020 21:36:31 -0800 (PST) Received: by pryzbyj (Postfix, from userid 1000) id CC1D5800831; Sat, 25 Jan 2020 23:36:29 -0600 (CST) Date: Sat, 25 Jan 2020 23:36:29 -0600 From: Justin Pryzby To: Michael Paquier Cc: Jeff Janes , pgsql-hackers Subject: Re: vacuum verbose detail logs are unclear; log at *start* of each stage Message-ID: <20200126053629.GO13621@telsasoft.com> References: <20191220171132.GB30414@telsasoft.com> <20200113004542.GA26045@telsasoft.com> <20200121134934.GY26045@telsasoft.com> <20200122053457.GG174860@paquier.xyz> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="54u2kuW9sGWg/X+X" Content-Disposition: inline In-Reply-To: <20200122053457.GG174860@paquier.xyz> User-Agent: Mutt/1.5.24 (2015-08-30) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --54u2kuW9sGWg/X+X Content-Type: text/plain; charset=us-ascii Content-Disposition: inline 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 --54u2kuW9sGWg/X+X Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="v3-0001-Remove-gettext-erronously-readded-at-580ddce.patch" From a3d0b41435655615ab13f808ec7c30e53e596e50 Mon Sep 17 00:00:00 2001 From: Justin Pryzby 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 --54u2kuW9sGWg/X+X Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="v3-0002-vacuum-verbose-use-ngettext-everywhere-possible.patch" From 2db7c4e3482120b2a83cda74603f2454da7eaa03 Mon Sep 17 00:00:00 2001 From: Justin Pryzby 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 --54u2kuW9sGWg/X+X Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="v3-0003-vacuum-verbose-prefix-write-multi-line-output-to-.patch" From 3467bf485972065f73c25a8f1e66c7c4f0bd5d23 Mon Sep 17 00:00:00 2001 From: Justin Pryzby 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 --54u2kuW9sGWg/X+X Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="v3-0004-reduce-to-DEBUG-status-logged-from-vacuum_heap-in.patch" From 55fea31f5d3d99a94eba206ec5a75f94e1f43097 Mon Sep 17 00:00:00 2001 From: Justin Pryzby 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 --54u2kuW9sGWg/X+X--