Обсуждение: vacuum verbose detail logs are unclear (show debug lines at *start*of each stage?)

This is a usability complaint.  If one knows enough about vacuum and/or
logging, I'm sure there's no issue.

Right now vacuum shows:

|  1  postgres=# VACUUM t; 
|  2  DEBUG:  vacuuming "public.t"
|  3  DEBUG:  scanned index "t_i_key" to remove 999 row versions
|  4  DETAIL:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
|  5  DEBUG:  "t": removed 999 row versions in 5 pages
|  6  DETAIL:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
|  7  DEBUG:  index "t_i_key" now contains 999 row versions in 11 pages
|  8  DETAIL:  999 index row versions were removed.
|  9  0 index pages have been deleted, 0 are currently reusable.
| 10  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
| 11  DEBUG:  "t": found 999 removable, 999 nonremovable row versions in 9 out of 9 pages
| 12  DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 130886944
| 13  There were 0 unused item identifiers.
| 14  Skipped 0 pages due to buffer pins, 0 frozen pages.
| 15  0 pages are entirely empty.
| 16  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
| 17  VACUUM

2: line showing action to be performed on table - good
3-4: line showing action which WAS performed on index, but only after it's done
5-6: line showing actions conditionally performed on table, but only after it's done
7-10: line showing status of on index, but only after it's done
11-16: line showing status of table; unconditional; good

I'm proposing to output a message before 3, 5, and 7, like in the attached.
The messages are just placeholders; if there's any agreement this is an
improvement, I'll accept suggestions for better content.

This is confusing, at least to me.  For example, the rusage output is shown
numerous times (depending on the number of indices and dead tuples).  I (at
least) tend to think think that a past-tense followed by an "elapsed" time
indicates that the process is neary done, and maybe just waiting on a fsync or
maybe some other synchronization.  If one sees multiple indexes output quickly,
you can infer that the process is looping over them.  When it's done with the
indexes, it starts another phase, but doesn't say that (or what).

#2 "vacuuming" line shows no rusage, and it's not very clear that the rusage
"DETAIL" in line#3 (in this example) applies to line#2 "scanning index", so
it's easy to think that the output is reporting that the whole command took
0.00s elapsed, which is irritating when the command hasn't yet finished.

Another example from CSV logs, to show log times (keep in mind that VACUUM
VERBOSE is less clear than the logfile, which has the adantage of a separate
column for DETAIL).

|  1   2019-12-16 09:59:22.568+10 | vacuuming "public.alarms"
               | 
 
|  2   2019-12-16 09:59:47.662+10 | scanned index "alarms_active_idx" to remove 211746 row versions
               | CPU: user: 0.22 s, system: 0.00 s, elapsed: 0.46 s
 
|  3   2019-12-16 09:59:48.036+10 | scanned index "alarms_displayable_idx" to remove 211746 row versions
               | CPU: user: 0.22 s, system: 0.00 s, elapsed: 0.37 s
 
|  4   2019-12-16 09:59:48.788+10 | scanned index "alarms_raw_current_idx" to remove 211746 row versions
               | CPU: user: 0.28 s, system: 0.00 s, elapsed: 0.75 s
 
|  5   2019-12-16 09:59:51.379+10 | scanned index "alarms_alarm_id_linkage_back_idx" to remove 211746 row versions
               | CPU: user: 1.04 s, system: 0.05 s, elapsed: 2.59 s
 
|  6   2019-12-16 09:59:53.75+10  | scanned index "alarms_alarm_id_linkage_idx" to remove 211746 row versions
               | CPU: user: 0.99 s, system: 0.08 s, elapsed: 2.37 s
 
|  7   2019-12-16 09:59:56.473+10 | scanned index "alarms_pkey" to remove 211746 row versions
               | CPU: user: 1.11 s, system: 0.08 s, elapsed: 2.72 s
 
|  8   2019-12-16 10:00:35.142+10 | scanned index "alarms_alarm_time_idx" to remove 211746 row versions
               | CPU: user: 0.94 s, system: 0.08 s, elapsed: 38.66 s
 
|  9   2019-12-16 10:00:37.002+10 | scanned index "alarms_alarm_clear_time_idx" to remove 211746 row versions
               | CPU: user: 0.72 s, system: 0.08 s, elapsed: 1.85 s
 
| 10   2019-12-16 10:03:57.42+10  | "alarms": removed 211746 row versions in 83923 pages
               | CPU: user: 10.24 s, system: 2.28 s, elapsed: 200.41 s
 
| 11   2019-12-16 10:03:57.425+10 | index "alarms_active_idx" now contains 32 row versions in 1077 pages
               | 57251 index row versions were removed.                 +
 
| 13   2019-12-16 10:03:57.426+10 | index "alarms_raw_current_idx" now contains 1495 row versions in 1753 pages
               | 96957 index row versions were removed.                 +
 
| 15   2019-12-16 10:03:57.426+10 | index "alarms_displayable_idx" now contains 32 row versions in 1129 pages
               | 55220 index row versions were removed.                 +
 
| 16   2019-12-16 10:03:57.427+10 | index "alarms_pkey" now contains 2269786 row versions in 9909 pages
               | 197172 index row versions were removed.                +
 
| 17   2019-12-16 10:03:57.427+10 | index "alarms_alarm_time_idx" now contains 2269791 row versions in 10306 pages
               | 211745 index row versions were removed.                +
 
| 17   2019-12-16 10:03:57.427+10 | index "alarms_alarm_id_linkage_idx" now contains 2269786 row versions in 11141
pages               | 211746 index row versions were removed.                +
 
| 19   2019-12-16 10:03:57.427+10 | index "alarms_alarm_id_linkage_back_idx" now contains 2269786 row versions in 11352
pages          | 211746 index row versions were removed.                +
 
| 20   2019-12-16 10:03:57.428+10 | index "alarms_alarm_clear_time_idx" now contains 2269791 row versions in 9875 pages
               | 166886 index row versions were removed.                +
 
| 21   2019-12-16 10:03:57.43+10  | "alarms": found 9534 removable, 1093069 nonremovable row versions in 211956 out of
430749pages     | 1 dead row versions cannot be removed yet, oldest xmin: 133809389+
 
|                                 |
               | There were 562588 unused item identifiers.                       +
 
|                                 |
               | Skipped 0 pages due to buffer pins, 7066 frozen pages.           +
 
|                                 |
               | 0 pages are entirely empty.                                      +
 
|                                 |
               | CPU: user: 17.85 s, system: 5.40 s, elapsed: 274.86 s.
 
| 22   2019-12-16 10:03:58.795+10 | "pg_toast_17781": removed 28 row versions in 7 pages
               | CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
 
| 23   2019-12-16 10:03:58.795+10 | scanned index "pg_toast_17781_index" to remove 28 row versions
               | CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.07 s
 
| 24   2019-12-16 10:03:58.816+10 | index "pg_toast_17781_index" now contains 1503 row versions in 7 pages
               | 23 index row versions were removed.                    +
 
| 25   2019-12-16 10:03:58.816+10 | "pg_toast_17781": found 23 removable, 1503 nonremovable row versions in 375 out of
375pages        | 0 dead row versions cannot be removed yet, oldest xmin:
 
       
#9 shows result of action performed on index, followed by 3.5 minutes of
silence...  This isn't very amusing when the last output says "elapsed: 1.85s",
and when you don't know how many "elapsed" lines to expect (as bad as any
progress bar with multiple phases).

Another approach would be to somehow make it more clear (for vacuum or in
general) that the "detail" line is associated with the preceding output.

Justin

On Sun, Dec 29, 2019 at 01:15:24PM -0500, Jeff Janes wrote:
> On Fri, Dec 20, 2019 at 12:11 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
> 
> > This is a usability complaint.  If one knows enough about vacuum and/or
> > logging, I'm sure there's no issue.
> 
> > | 11  DEBUG:  "t": found 999 removable, 999 nonremovable row versions in 9 out of 9 pages
> 
> I agree the mixture of pre-action and after-action reporting is rather
> confusing sometimes.  I'm more concerned about what the user sees in their
> terminal, though, rather than the server's log file.

Sorry, I ran vacuum (not verbose) with client_min_messages=debug, which was confusing.

> Also, the above quoted line is confusing.  It makes it sound like it found
> removable items, but didn't actually remove them.  I think that that is
> taking grammatical parallelism too far.  How about something like:
> 
> DEBUG:  "t": removed 999 row versions, found 999 nonremovable row versions in 9 out of 9 pages

Since da4ed8bf, lazy_vacuum_heap() actually says: "removed %d [row versions] in
%d pages".  Strangely, the "found .. removable, .. nonremovable" in
lazy_scan_heap() is also from da4ed8bf.  Should we change them to match ?

> Also, I'd appreciate a report on how many hint-bits were set
> and how many pages were marked all-visible and/or frozen.

Possibly should fork this part to a different thread, but..
hint bits are being set by heap_prune_chain():

|#0  HeapTupleSatisfiesVacuum (htup=htup@entry=0x7fffabfcccc0, OldestXmin=OldestXmin@entry=536,
buffer=buffer@entry=167)at heapam_visibility.c:1245
 
|#1  0x00007fb6eb3eb848 in heap_prune_chain (prstate=0x7fffabfccf30, OldestXmin=536, rootoffnum=1, buffer=167,
relation=0x7fb6eb1e6858)at pruneheap.c:488
 
|#2  heap_page_prune (relation=relation@entry=0x7fb6eb1e6858, buffer=buffer@entry=167, OldestXmin=536,
report_stats=report_stats@entry=false,latestRemovedXid=latestRemovedXid@entry=0x7fb6ed84a13c) at pruneheap.c:223
 
|#3  0x00007fb6eb3f02a2 in lazy_scan_heap (aggressive=false, nindexes=0, Irel=0x0, vacrelstats=0x7fb6ed84a0c0,
params=0x7fffabfcdfd0,onerel=0x7fb6eb1e6858) at vacuumlazy.c:970
 
|#4  heap_vacuum_rel (onerel=0x7fb6eb1e6858, params=0x7fffabfcdfd0, bstrategy=<optimized out>) at vacuumlazy.c:302

In the attached, I moved heap_page_prune to avoid a second loop over items.
Then, initdb crashed until I avoided calling heap_prepare_freeze_tuple() for
HEAPTUPLE_DEAD.  I'm not sure that's ok or maybe if it's exposing an issue.
I'm also not sure if t_infomask!=oldt_infomask is the right test.

One of my usability complaints was that the DETAIL includes newlines, which
makes it not apparent that it's detail, or that it's associated with the
preceding INFO.  Should those all be separate DETAIL messages (currently, only
the first errdetail is used, but maybe they should be catted together
usefully).  Should errdetail do something with newlines, like change them to
\n\t for output to the client (but not logfile).  Should vacuum itself do
something (but probably no change to logfiles).

I remembered that log_statement_stats looks like this:

2020-01-01 11:28:33.758 CST [3916] LOG:  EXECUTOR STATISTICS
2020-01-01 11:28:33.758 CST [3916] DETAIL:  ! system usage stats:
        !       0.050185 s user, 0.000217 s system, 0.050555 s elapsed
        !       [2.292346 s user, 0.215656 s system total]
        [...]


It calls errdetail_internal("%s", str.data), same as vaccum, but the multi-line
detail messages are written like this:
|appendStringInfo(&str, "!\t...")
|...
|ereport(LOG,
|    (errmsg_internal("%s", title),
|    errdetail_internal("%s", str.data)));

Since they can run multiple times, including rusage, and there's not currently
any message shown before their action, I propose that lazy_vacuum_index/heap
should write VACUUM VERBOSE logs at DEBUG level.  Or otherwise show a log
before starting each action, at least those for which it logs completion.

I'm not sure why this one doesn't use get ngettext() ?  Missed at a8d585c0 ?
|appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),

Or why this one uses _/gettext() ?  (580ddcec suggests that I'm missing
something?).
|appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));

Anyway, now it looks like this:
postgres=# VACUUM VERBOSE t;
INFO:  vacuuming "pg_temp_3.t"
INFO:  "t": removed 1998 row versions in 5 pages
INFO:  "t": removed 1998, found 999 nonremovable row versions in 9 out of 9 pages
DETAIL:  ! 0 dead row versions cannot be removed yet, oldest xmin: 4505
!       There were 0 unused item identifiers.
!       Skipped 0 pages due to buffer pins, 0 frozen pages.
!       0 pages are entirely empty.
!       Marked 9 pages all visible, 4 pages frozen.
!       Wrote 1998 hint bits.
!       CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
VACUUM

Thanks for your input.

Justin

Rebased against 40d964ec997f64227bc0ff5e058dc4a5770a70a9
I added to March CF https://commitfest.postgresql.org/27/2425/

On Tue, Jan 21, 2020 at 07:49:34AM -0600, Justin Pryzby wrote:
> Rebased against 40d964ec997f64227bc0ff5e058dc4a5770a70a9
> I added to March CF https://commitfest.postgresql.org/27/2425/

Please be careful with the sets of patches sent to a thread, just to
say that what you are sending is organized in a messy way, and that
this is not the only thread (I can see sometimes the same patches sent
to multiple threads for no actual reason).  First, patches 0001 and
0002 have nothing to do with this thread.  Patches 0003 and 0005 could
just be merged together, visibly with 0004 as well as they treat of
the same concepts, actually related to this thread.  My point is that
it is harder to understand what you are trying to do, and that this is
inconsistent with the threads created.

From patch 0002:
-    * If the all-visible page is turned out to be all-frozen but not
+    * If the all-visible page turned out to be all-frozen but not
     * marked, we should so mark it.  Note that all_frozen is only valid
     * if all_visible is true, so we must check both.
Shouldn't the last part of the sentence be "we should mark it so"
instead of "we should so mark it"?  I would rephrase the whole as
follows:
"If the all-visible page is all-frozen but not marked as such yet,
mark it as all-frozen."

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.
--
Michael

On Wed, Jan 22, 2020 at 02:34:57PM +0900, Michael Paquier wrote:
> Shouldn't the last part of the sentence be "we should mark it so"
> instead of "we should so mark it"?  I would rephrase the whole as
> follows:
> "If the all-visible page is all-frozen but not marked as such yet,
> mark it as all-frozen."

Applied this one to HEAD after chewing on it a bit.
--
Michael

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

On 2020-01-26 06:36, Justin Pryzby wrote:
>  From a3d0b41435655615ab13f808ec7c30e53e596e50 Mon Sep 17 00:00:00 2001
> From: Justin Pryzby<pryzbyj@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

Why do you think it was erroneously added?

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Thu, Feb 27, 2020 at 10:10:57AM +0100, Peter Eisentraut wrote:
> On 2020-01-26 06:36, Justin Pryzby wrote:
> >Subject: [PATCH v3 1/4] Remove gettext erronously readded at 580ddce
> >
> >-    appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
> >+    appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
> 
> Why do you think it was erroneously added?

I was wrong.

It seemed useless to me to translate "%s.", but I see now that at least JA.PO
uses a different terminator than ".".

$ git grep -C3 'msgid "%s."$' '*.po' |grep msgstr
src/backend/po/de.po-msgstr "%s."
src/backend/po/es.po-msgstr "%s."
src/backend/po/fr.po-msgstr "%s."
src/backend/po/id.po-msgstr "%s."
src/backend/po/it.po-msgstr "%s."
src/backend/po/ja.po-msgstr "%s。"

BTW I only *happened* to see your message on the www interface.  I didn't get
the original message.  And the "Resend email" button didn't get it to me,
either..

-- 
Justin

Justin Pryzby <pryzby@telsasoft.com> writes:
> 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 ?

The really fundamental problem with this is that you are trying to make
the server do what is properly the client's job, namely format messages
nicely.  Please read the message style guidelines [1], particularly
the bit about "Formatting", which basically says "don't":

    Formatting

    Don't put any specific assumptions about formatting into the message
    texts. Expect clients and the server log to wrap lines to fit their
    own needs. In long messages, newline characters (\n) can be used to
    indicate suggested paragraph breaks. Don't end a message with a
    newline. Don't use tabs or other formatting characters. (In error
    context displays, newlines are automatically added to separate levels
    of context such as function calls.)

    Rationale: Messages are not necessarily displayed on terminal-type
    displays. In GUI displays or browsers these formatting instructions
    are at best ignored.


            regards, tom lane

[1] https://www.postgresql.org/docs/devel/error-style-guide.html

> On 24 Mar 2020, at 22:58, Tom Lane <tgl@sss.pgh.pa.us> wrote:

> The really fundamental problem with this is that you are trying to make
> the server do what is properly the client's job, namely format messages
> nicely.  Please read the message style guidelines [1], particularly
> the bit about "Formatting", which basically says "don't":

This thread has stalled since the last CF with Tom's raised issue unanswered,
and the patch no longer applies.  I'm closing this as Returned with Feedback,
if there is an updated patchset then please re-open the entry.

cheers ./daniel