Horton

Thread

Commits

  1. Add WAL usage reporting to ANALYZE VERBOSE output.

  2. Add resource statistics reporting to ANALYZE VERBOSE.

  3. Use pgBufferUsage for buffer usage tracking in analyze.

  4. Fix parallel vacuum buffer usage reporting.

  1. Use pgBufferUsage for block reporting in analyze

    Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com> — 2024-05-10T08:54:07Z

    Hi,

Analyze logs within autovacuum uses specific variables
VacuumPage{Hit,Miss,Dirty} to track the buffer usage count. However,
pgBufferUsage already provides block usage tracking and handles more cases
(temporary tables, parallel workers...).

Those variables were only used in two places, block usage reporting in
verbose vacuum and analyze. 5cd72cc0c5017a9d4de8b5d465a75946da5abd1d
removed their usage in the vacuum command as part of a bugfix.

This patch replaces those Vacuum specific variables by pgBufferUsage
in analyze. This makes VacuumPage{Hit,Miss,Dirty} unused and removable.
This commit removes both their calls in bufmgr and their declarations.

Regards,
Anthonin

  2. Re: Use pgBufferUsage for block reporting in analyze

    Michael Paquier <michael@paquier.xyz> — 2024-05-10T10:40:35Z

    On Fri, May 10, 2024 at 10:54:07AM +0200, Anthonin Bonnefoy wrote:
> This patch replaces those Vacuum specific variables by pgBufferUsage
> in analyze. This makes VacuumPage{Hit,Miss,Dirty} unused and removable.
> This commit removes both their calls in bufmgr and their declarations.

Hmm, yeah, it looks like you're right.  I can track all the blocks
read, hit and dirtied for VACUUM and ANALYZE in all the code path
where these removed variables were incremented.  This needs some
runtime check to make sure that the calculations are consistent before
and after the fact (cannot do that now).

             appendStringInfo(&buf, _("buffer usage: %lld hits, %lld misses, %lld dirtied\n"),
-                             (long long) AnalyzePageHit,
-                             (long long) AnalyzePageMiss,
-                             (long long) AnalyzePageDirty);
+                             (long long) (bufferusage.shared_blks_hit + bufferusage.local_blks_hit),
+                             (long long) (bufferusage.shared_blks_read + bufferusage.local_blks_read),
+                             (long long) (bufferusage.shared_blks_dirtied + bufferusage.local_blks_dirtied));

Perhaps this should say "read" rather than "miss" in the logs as the
two read variables for the shared and local blocks are used?  For
consistency, at least.

That's not material for v17, only for v18.
--
Michael

  3. Re: Use pgBufferUsage for block reporting in analyze

    Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com> — 2024-05-28T09:00:51Z

    Thanks for having a look.

On Fri, May 10, 2024 at 12:40 PM Michael Paquier <michael@paquier.xyz>
wrote:

> This needs some runtime check to make sure that the calculations
> are consistent before and after the fact (cannot do that now).
>
Yeah, testing this is also a bit painful as buffer usage of analyze is only
displayed in the logs during autoanalyze. While looking at this, I've
thought of additional changes that could make testing easier and improve
consistency with VACUUM VERBOSE:
- Have ANALYZE VERBOSE outputs the buffer usage stats
- Add Wal usage to ANALYZE VERBOSE

analyze verbose output would look like:
postgres=# analyze (verbose) pgbench_accounts ;
INFO:  analyzing "public.pgbench_accounts"
INFO:  "pgbench_accounts": scanned 1640 of 1640 pages, containing 100000
live rows and 0 dead rows; 30000 rows in sample, 100000 estimated total rows
INFO:  analyze of table "postgres.public.pgbench_accounts"
avg read rate: 124.120 MB/s, avg write rate: 0.110 MB/s
buffer usage: 533 hits, 1128 reads, 1 dirtied
WAL usage: 12 records, 1 full page images, 5729 bytes
system usage: CPU: user: 0.06 s, system: 0.00 s, elapsed: 0.07 s

Perhaps this should say "read" rather than "miss" in the logs as the
> two read variables for the shared and local blocks are used?  For
> consistency, at least.
>
Sounds good.

That's not material for v17, only for v18.
>
 Definitely

I've split the patch in two parts
1: Removal of the vacuum specific variables, this is the same as the
initial patch.
2: Add buffer and wal usage to analyze verbose output + rename miss to
reads

Regards,
Anthonin

  4. Re: Use pgBufferUsage for block reporting in analyze

    Karina Litskevich <litskevichkarina@gmail.com> — 2024-07-05T14:24:41Z

    Hi Anthonin,

I suggest assigning values
bufferusage.shared_blks_read + bufferusage.local_blks_read
and
bufferusage.shared_blks_dirtied + bufferusage.local_blks_dirtied
to new variables and using them. This would keep the changed lines within
the 80 symbols limit, and make the code more readable overall.

I also believe that changing "misses" to "reads" should belong to 0001
patch since we only change it because we replace AnalyzePageMiss with
bufferusage.shared_blks_read + bufferusage.local_blks_read in 0001.

Best regards,
Karina Litskevich
Postgres Professional: http://postgrespro.com/

>

  5. Re: Use pgBufferUsage for block reporting in analyze

    Karina Litskevich <litskevichkarina@gmail.com> — 2024-07-05T14:32:30Z

    I wrote:

>
> I suggest assigning values
> bufferusage.shared_blks_read + bufferusage.local_blks_read
> and
> bufferusage.shared_blks_dirtied + bufferusage.local_blks_dirtied
> to new variables and using them. This would keep the changed lines within
> the 80 symbols limit, and make the code more readable overall.
>

The same applies to
bufferusage.shared_blks_hit + bufferusage.local_blks_hit

  6. Re: Use pgBufferUsage for block reporting in analyze

    Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com> — 2024-07-08T09:35:19Z

    Hi,

Thanks for the review, I've updated the patches with the suggestions:
- moved renaming of misses to reads to the first patch
- added intermediate variables for total blks usage

I've also done some additional tests using the provided
vacuum_analyze_buffer_usage.sql script. It relies on
pg_stat_statements to check the results (only pgss gives information
on dirtied buffers). It gives the following output:

 psql:vacuum_analyze_buffer_usage.sql:21: INFO:  vacuuming
"postgres.pg_temp_7.vacuum_blks_stat_test"
 ...
 buffer usage: 105 hits, 3 reads, 6 dirtied
 ...
              query  | sum_hit | sum_read | sum_dirtied
 --------------------+---------+----------+-------------
  VACUUM (VERBOSE... |     105 |        3 |           6

For vacuum, we have the same results with SKIP_DATABASE_STATS. Without
this setting, we would have block usage generated by
vac_update_datfrozenxid outside of vacuum_rel and therefore not
tracked by the verbose output. For the second test, the second patch
is needed to have ANALYZE (VERBOSE) output the block usage. It will
output the following:

 psql:vacuum_analyze_buffer_usage.sql:29: INFO:  analyzing
"pg_temp_7.vacuum_blks_stat_test"
 ...
 buffer usage: 84 hits, 33 reads, 2 dirtied
 ...
     query            | sum_hit | sum_read | sum_dirtied
 ---------------------+---------+----------+-------------
  ANALYZE (VERBOSE... |      91 |       38 |           2

There's additional buffer hits/reads reported by pgss, those are from
analyze_rel opening the relations in try_relation_open and are not
tracked by the ANALYZE VERBOSE.

  7. Re: Use pgBufferUsage for block reporting in analyze

    Masahiko Sawada <sawada.mshk@gmail.com> — 2024-07-22T20:59:10Z

    On Mon, Jul 8, 2024 at 2:35 AM Anthonin Bonnefoy
<anthonin.bonnefoy@datadoghq.com> wrote:
>
> Hi,
>
> Thanks for the review, I've updated the patches with the suggestions:
> - moved renaming of misses to reads to the first patch
> - added intermediate variables for total blks usage
>

Thank you for working on this. 0001 patch looks good to me.

I like the 0002 patch idea. But with this patch, ANALYZE VERBOSE
writes something like this:

INFO:  analyzing "public.test"
INFO:  "test": scanned 443 of 443 pages, containing 100000 live rows
and 0 dead rows; 30000 rows in sample, 100000 estimated total rows
INFO:  analyze of table "postgres.public.test"
avg read rate: 38.446 MB/s, avg write rate: 0.000 MB/s
buffer usage: 265 hits, 187 reads, 0 dirtied
WAL usage: 4 records, 0 full page images, 637 bytes
system usage: CPU: user: 0.03 s, system: 0.00 s, elapsed: 0.03 s

Which seems not to be consistent with what we do in VACUUM VERBOSE in
some points. For example, in VACUUM VERBOSE outputs, we write
statistics of pages, tuples, buffer usage, and WAL usage in one INFO
message:

INFO:  vacuuming "postgres.public.test"
INFO:  finished vacuuming "postgres.public.test": index scans: 0
pages: 0 removed, 443 remain, 1 scanned (0.23% of total)
tuples: 0 removed, 100000 remain, 0 are dead but not yet removable
removable cutoff: 754, which was 0 XIDs old when operation ended
frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
index scan not needed: 0 pages from table (0.00% of total) had 0 dead
item identifiers removed
avg read rate: 23.438 MB/s, avg write rate: 0.000 MB/s
buffer usage: 5 hits, 3 reads, 0 dirtied
WAL usage: 0 records, 0 full page images, 0 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s

I'd suggest writing analyze verbose messages as something like:

INFO: finished analyzing "postgres.public.test"
pages: 443 of 443 scanned
tuples: 100000 live tuples, 0 are dead; 30000 tuples in sample, 100000
estimated total tuples
avg read rate: 38.446 MB/s, avg write rate: 0.000 MB/s
buffer usage: 265 hits, 187 reads, 0 dirtied
WAL usage: 4 records, 0 full page images, 637 bytes
system usage: CPU: user: 0.03 s, system: 0.00 s, elapsed: 0.03 s

The first line would vary depending on whether an autovacuum worker or
not. And the above suggestion includes a change of term "row" to
"tuple" for better consistency with VACUUM VERBOSE outputs. I think it
would be great if autoanalyze also writes logs in the same format.
IIUC with the patch, autoanalyze logs don't include the page and tuple
statistics.

Regards,

-- 
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com

  8. Re: Use pgBufferUsage for block reporting in analyze

    Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com> — 2024-07-24T08:57:57Z

    On Mon, Jul 22, 2024 at 10:59 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> The first line would vary depending on whether an autovacuum worker or
> not. And the above suggestion includes a change of term "row" to
> "tuple" for better consistency with VACUUM VERBOSE outputs. I think it
> would be great if autoanalyze also writes logs in the same format.
> IIUC with the patch, autoanalyze logs don't include the page and tuple
> statistics.

One issue is that the number of scanned pages, live tuples and dead
tuples is only available in acquire_sample_rows which is where the log
containing those stats is emitted. I've tried to implement the
following in 0003:
- Sampling functions now accept an AcquireSampleStats struct to store
pages and tuples stats
- Log is removed from sampling functions
- do_analyze_rel now outputs scanned and tuples statistics when
relevant. sampling from fdw doesn't provide those statistics so they
are not displayed in those cases.

This ensures that analyze logs are only emitted in do_analyze_rel,
allowing to display the same output for both autoanalyze and ANALYZE
VERBOSE. With those changes, we have the following output for analyze
verbose of a table:

analyze (verbose) pgbench_accounts ;
INFO:  analyzing "public.pgbench_accounts"
INFO:  analyze of table "postgres.public.pgbench_accounts"
pages: 1640 of 1640 scanned
tuples: 100000 live tuples, 0 are dead; 30000 tuples in samples,
100000 estimated total tuples
avg read rate: 174.395 MB/s, avg write rate: 0.000 MB/s
buffer usage: 285 hits, 1384 reads, 0 dirtied
WAL usage: 14 records, 0 full page images, 1343 bytes
system usage: CPU: user: 0.05 s, system: 0.00 s, elapsed: 0.06 s

For a file_fdw, the output will look like:

analyze (verbose) pglog;
INFO:  analyzing "public.pglog"
INFO:  analyze of table "postgres.public.pglog"
tuples: 30000 tuples in samples, 60042 estimated total tuples
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
buffer usage: 182 hits, 0 reads, 0 dirtied
WAL usage: 118 records, 0 full page images, 13086 bytes
system usage: CPU: user: 0.40 s, system: 0.00 s, elapsed: 0.41 s

I've also slightly modified 0002 to display "automatic analyze" when
we're inside an autovacuum worker, similar to what's done with vacuum
output.

Regards,
Anthonin

  9. Re: Use pgBufferUsage for block reporting in analyze

    Masahiko Sawada <sawada.mshk@gmail.com> — 2024-07-26T22:34:46Z

    On Wed, Jul 24, 2024 at 1:58 AM Anthonin Bonnefoy
<anthonin.bonnefoy@datadoghq.com> wrote:
>
> On Mon, Jul 22, 2024 at 10:59 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> > The first line would vary depending on whether an autovacuum worker or
> > not. And the above suggestion includes a change of term "row" to
> > "tuple" for better consistency with VACUUM VERBOSE outputs. I think it
> > would be great if autoanalyze also writes logs in the same format.
> > IIUC with the patch, autoanalyze logs don't include the page and tuple
> > statistics.
>
> One issue is that the number of scanned pages, live tuples and dead
> tuples is only available in acquire_sample_rows which is where the log
> containing those stats is emitted. I've tried to implement the
> following in 0003:
> - Sampling functions now accept an AcquireSampleStats struct to store
> pages and tuples stats
> - Log is removed from sampling functions
> - do_analyze_rel now outputs scanned and tuples statistics when
> relevant. sampling from fdw doesn't provide those statistics so they
> are not displayed in those cases.

Studying how we write verbose log messages, it seems that currently
ANALYZE (autoanalyze) lets tables and FDWs write logs in its own
format. Which makes sense to me as some instruments for heap such as
dead tuple might not be necessary for FDWs and FDW might want to write
other information such as executed queries. An alternative idea would
be to pass StringInfo to AcquireSampleRowsFunc() so that callback can
write its messages there. This is somewhat similar to what we do in
the EXPLAIN command (cf, ExplainPropertyText() etc). It could be too
much but I think it could be better than writing logs in the single
format.

>
> I've also slightly modified 0002 to display "automatic analyze" when
> we're inside an autovacuum worker, similar to what's done with vacuum
> output.

+1

Regards,

--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com

  10. Re: Use pgBufferUsage for block reporting in analyze

    Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com> — 2024-07-29T07:11:52Z

    On Sat, Jul 27, 2024 at 12:35 AM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> An alternative idea would
> be to pass StringInfo to AcquireSampleRowsFunc() so that callback can
> write its messages there. This is somewhat similar to what we do in
> the EXPLAIN command (cf, ExplainPropertyText() etc). It could be too
> much but I think it could be better than writing logs in the single
> format.

I've tested this approach, it definitely looks better. I've added a
logbuf StringInfo to AcquireSampleRowsFunc which will receive the
logs. elevel was removed as it is not used anymore. Since everything
is in the same log line, I've removed the relation name in the acquire
sample functions.

For partitioned tables, I've also added the processed partition table
being sampled. The output will look like:

INFO:  analyze of table "postgres.public.test_partition"
Sampling rows from child "public.test_partition_1"
pages: 5 of 5 scanned
tuples: 999 live tuples, 0 are dead; 999 tuples in sample, 999
estimated total tuples
Sampling rows from child "public.test_partition_2"
pages: 5 of 5 scanned
tuples: 1000 live tuples, 0 are dead; 1000 tuples in sample, 1000
estimated total tuples
avg read rate: 2.604 MB/s, avg write rate: 0.000 MB/s
...

For a file_fdw, the output will be:

INFO:  analyze of table "postgres.public.pglog"
tuples: 60043 tuples; 30000 tuples in sample
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
...

Regards,
Anthonin

  11. Re: Use pgBufferUsage for block reporting in analyze

    Masahiko Sawada <sawada.mshk@gmail.com> — 2024-07-29T23:13:11Z

    Hi,

On Mon, Jul 29, 2024 at 12:12 AM Anthonin Bonnefoy
<anthonin.bonnefoy@datadoghq.com> wrote:
>
> On Sat, Jul 27, 2024 at 12:35 AM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> > An alternative idea would
> > be to pass StringInfo to AcquireSampleRowsFunc() so that callback can
> > write its messages there. This is somewhat similar to what we do in
> > the EXPLAIN command (cf, ExplainPropertyText() etc). It could be too
> > much but I think it could be better than writing logs in the single
> > format.
>

I have one comment on 0001 patch:

                         /*
                          * Calculate the difference in the Page
Hit/Miss/Dirty that
                          * happened as part of the analyze by
subtracting out the
                          * pre-analyze values which we saved above.
                          */
-                        AnalyzePageHit = VacuumPageHit - AnalyzePageHit;
-                        AnalyzePageMiss = VacuumPageMiss - AnalyzePageMiss;
-                        AnalyzePageDirty = VacuumPageDirty - AnalyzePageDirty;
+                        memset(&bufferusage, 0, sizeof(BufferUsage));
+                        BufferUsageAccumDiff(&bufferusage,
&pgBufferUsage, &startbufferusage);
+
+                        total_blks_hit = bufferusage.shared_blks_hit +
+                                bufferusage.local_blks_hit;
+                        total_blks_read = bufferusage.shared_blks_read +
+                                bufferusage.local_blks_read;
+                        total_blks_dirtied = bufferusage.shared_blks_dirtied +
+                                bufferusage.local_blks_dirtied;

The comment should also be updated or removed.

And here are some comments on 0002 patch:

-           TimestampDifference(starttime, endtime, &secs_dur, &usecs_dur);
+           delay_in_ms = TimestampDifferenceMilliseconds(starttime, endtime);

I think that this change is to make vacuum code consistent with
analyze code, particularly the following part:

            /*
             * We do not expect an analyze to take > 25 days and it simplifies
             * things a bit to use TimestampDifferenceMilliseconds.
             */
            delay_in_ms = TimestampDifferenceMilliseconds(starttime, endtime);

However, as the above comment says, delay_in_ms can have a duration up
to 25 days. I guess it would not be a problem for analyze cases but
could be in vacuum cases as vacuum could sometimes be running for a
very long time. I've seen vacuums running even for almost 1 month. So
I think we should keep this part.

---
         /* measure elapsed time iff autovacuum logging requires it */
-        if (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+        if (instrument)

The comment should also be updated.

---
Could you split the 0002 patch into two patches? One is to have
ANALYZE command (with VERBOSE option) write the buffer usage, and
second one is to add WAL usage to both ANALYZE command and
autoanalyze. I think adding WAL usage to ANALYZE could be
controversial as it should not be WAL-intensive operation, so I'd like
to keep them separate.


> I've tested this approach, it definitely looks better. I've added a
> logbuf StringInfo to AcquireSampleRowsFunc which will receive the
> logs. elevel was removed as it is not used anymore. Since everything
> is in the same log line, I've removed the relation name in the acquire
> sample functions.
>
> For partitioned tables, I've also added the processed partition table
> being sampled. The output will look like:
>
> INFO:  analyze of table "postgres.public.test_partition"
> Sampling rows from child "public.test_partition_1"
> pages: 5 of 5 scanned
> tuples: 999 live tuples, 0 are dead; 999 tuples in sample, 999
> estimated total tuples
> Sampling rows from child "public.test_partition_2"
> pages: 5 of 5 scanned
> tuples: 1000 live tuples, 0 are dead; 1000 tuples in sample, 1000
> estimated total tuples
> avg read rate: 2.604 MB/s, avg write rate: 0.000 MB/s
> ...
>
> For a file_fdw, the output will be:
>
> INFO:  analyze of table "postgres.public.pglog"
> tuples: 60043 tuples; 30000 tuples in sample
> avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
> ...

Thank you for updating the patch. With your patch, I got the following
logs for when executing ANALYZE VERBOSE on a partitioned table:

postgres(1:3971560)=# analyze (verbose) p;
INFO:  analyzing "public.p" inheritance tree
INFO:  analyze of table "postgres.public.p"
Sampling rows from child "public.c1"
pages: 10000 of 14750 scanned
tuples: 2259833 live tuples, 0 are dead; 10000 tuples in sample,
3333254 estimated total tuples
Sampling rows from child "public.c2"
pages: 10000 of 14750 scanned
tuples: 2260000 live tuples, 0 are dead; 10000 tuples in sample,
3333500 estimated total tuples
Sampling rows from child "public.c3"
pages: 10000 of 14750 scanned
tuples: 2259833 live tuples, 0 are dead; 10000 tuples in sample,
3333254 estimated total tuples
avg read rate: 335.184 MB/s, avg write rate: 0.031 MB/s
buffer usage: 8249 hits, 21795 reads, 2 dirtied
WAL usage: 6 records, 1 full page images, 8825 bytes
system usage: CPU: user: 0.46 s, system: 0.03 s, elapsed: 0.50 s
:

Whereas the current log messages are like follow:

INFO:  analyzing "public.p" inheritance tree
INFO:  "c1": scanned 10000 of 14750 pages, containing 2259833 live
rows and 0 dead rows; 10000 rows in sample, 3333254 estimated total
rows
INFO:  "c2": scanned 10000 of 14750 pages, containing 2259834 live
rows and 0 dead rows; 10000 rows in sample, 3333255 estimated total
rows
INFO:  "c3": scanned 10000 of 14750 pages, containing 2259833 live
rows and 0 dead rows; 10000 rows in sample, 3333254 estimated total
rows
:

It seems to me that the current style is more concise and readable (3
rows per table vs. 1 row per table). We might need to consider a
better output format for partitioned tables as the number of
partitions could be high. I don't have a good idea now, though.

Regards,

-- 
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com

  12. Re: Use pgBufferUsage for block reporting in analyze

    Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com> — 2024-07-30T07:21:25Z

    Hi,

On Tue, Jul 30, 2024 at 1:13 AM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> I have one comment on 0001 patch:
> The comment should also be updated or removed.

Ok, I've removed the comment.

> However, as the above comment says, delay_in_ms can have a duration up
> to 25 days. I guess it would not be a problem for analyze cases but
> could be in vacuum cases as vacuum could sometimes be running for a
> very long time. I've seen vacuums running even for almost 1 month. So
> I think we should keep this part.

Good point, I've reverted to using TimestampDifference for vacuum.

>          /* measure elapsed time iff autovacuum logging requires it */
> -        if (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
> +        if (instrument)
>
> The comment should also be updated.

Updated.

> Could you split the 0002 patch into two patches? One is to have
> ANALYZE command (with VERBOSE option) write the buffer usage, and
> second one is to add WAL usage to both ANALYZE command and
> autoanalyze. I think adding WAL usage to ANALYZE could be
> controversial as it should not be WAL-intensive operation, so I'd like
> to keep them separate.

I've split the patch, 0002 makes verbose outputs the same as
autoanalyze logs with buffer/io/system while 0003 adds WAL usage
output.

> It seems to me that the current style is more concise and readable (3
> rows per table vs. 1 row per table). We might need to consider a
> better output format for partitioned tables as the number of
> partitions could be high. I don't have a good idea now, though.

A possible change would be to pass an inh flag when an acquirefunc is
called from acquire_inherited_sample_rows. The acquirefunc could then
use an alternative log format to append to logbuf. This way, we could
have a more compact format for partitioned tables.

Regards,
Anthonin

  13. Re: Use pgBufferUsage for block reporting in analyze

    Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com> — 2024-07-31T07:03:24Z

    On Tue, Jul 30, 2024 at 9:21 AM Anthonin Bonnefoy
<anthonin.bonnefoy@datadoghq.com> wrote:
> A possible change would be to pass an inh flag when an acquirefunc is
> called from acquire_inherited_sample_rows. The acquirefunc could then
> use an alternative log format to append to logbuf. This way, we could
> have a more compact format for partitioned tables.

I've just tested this, the result isn't great as it creates an
inconsistent output

INFO:  analyze of table "postgres.public.test_partition"
"test_partition_1": scanned 5 of 5 pages, containing 999 live tuples
and 0 dead tuples; 999 rows in sample, 999 estimated total rows
"test_partition_2": scanned 5 of 5 pages, containing 1000 live tuples
and 0 dead tuples; 1000 rows in sample, 1000 estimated total rows
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
...
INFO:  analyze of table "postgres.public.test_partition_1"
pages: 5 of 5 scanned
tuples: 999 live tuples, 0 are dead; 999 tuples in sample, 999
estimated total tuples
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s

Maybe the best approach is to always use the compact form?

INFO:  analyze of table "postgres.public.test_partition"
"test_partition_1": scanned 5 of 5 pages, containing 999 live tuples
and 0 dead tuples; 999 tuples in sample, 999 estimated total tuples
"test_partition_2": scanned 5 of 5 pages, containing 1000 live tuples
and 0 dead tuples; 1000 tuples in sample, 1000 estimated total tuples
avg read rate: 1.953 MB/s, avg write rate: 0.000 MB/s
...
INFO:  analyze of table "postgres.public.test_partition_1"
"test_partition_1": scanned 5 of 5 pages, containing 999 live tuples
and 0 dead tuples; 999 tuples in sample, 999 estimated total tuples
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s

I've updated the patchset with those changes. 0004 introduces the
StringInfo logbuf so we can output logs as a single log and during
ANALYZE VERBOSE while using the compact form.

Regards,
Anthonin

  14. Re: Use pgBufferUsage for block reporting in analyze

    Masahiko Sawada <sawada.mshk@gmail.com> — 2024-07-31T19:36:13Z

    On Wed, Jul 31, 2024 at 12:03 AM Anthonin Bonnefoy
<anthonin.bonnefoy@datadoghq.com> wrote:
>
> On Tue, Jul 30, 2024 at 9:21 AM Anthonin Bonnefoy
> <anthonin.bonnefoy@datadoghq.com> wrote:
> > A possible change would be to pass an inh flag when an acquirefunc is
> > called from acquire_inherited_sample_rows. The acquirefunc could then
> > use an alternative log format to append to logbuf. This way, we could
> > have a more compact format for partitioned tables.
>
> I've just tested this, the result isn't great as it creates an
> inconsistent output
>
> INFO:  analyze of table "postgres.public.test_partition"
> "test_partition_1": scanned 5 of 5 pages, containing 999 live tuples
> and 0 dead tuples; 999 rows in sample, 999 estimated total rows
> "test_partition_2": scanned 5 of 5 pages, containing 1000 live tuples
> and 0 dead tuples; 1000 rows in sample, 1000 estimated total rows
> avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
> ...
> INFO:  analyze of table "postgres.public.test_partition_1"
> pages: 5 of 5 scanned
> tuples: 999 live tuples, 0 are dead; 999 tuples in sample, 999
> estimated total tuples
> avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
>
> Maybe the best approach is to always use the compact form?
>
> INFO:  analyze of table "postgres.public.test_partition"
> "test_partition_1": scanned 5 of 5 pages, containing 999 live tuples
> and 0 dead tuples; 999 tuples in sample, 999 estimated total tuples
> "test_partition_2": scanned 5 of 5 pages, containing 1000 live tuples
> and 0 dead tuples; 1000 tuples in sample, 1000 estimated total tuples
> avg read rate: 1.953 MB/s, avg write rate: 0.000 MB/s
> ...
> INFO:  analyze of table "postgres.public.test_partition_1"
> "test_partition_1": scanned 5 of 5 pages, containing 999 live tuples
> and 0 dead tuples; 999 tuples in sample, 999 estimated total tuples
> avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
>
> I've updated the patchset with those changes. 0004 introduces the
> StringInfo logbuf so we can output logs as a single log and during
> ANALYZE VERBOSE while using the compact form.
>

Fair point. I'll consider a better output format.

Meanwhile, I think we can push 0001 and 0002 patches since they are in
good shape. I've updated commit messages to them and slightly changed
0002 patch to write "finished analyzing of table \"%s.%s.%s\" instead
of  "analyze of table \"%s.%s.%s\".

Also, regarding 0003 patch, what is the main reason why we want to add
WAL usage to analyze reports? I think that analyze normally does not
write WAL records much so I'm not sure it's going to provide a good
insight for users.

Regards,

--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com

  15. Re: Use pgBufferUsage for block reporting in analyze

    Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com> — 2024-08-01T06:27:29Z

    On Wed, Jul 31, 2024 at 9:36 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> Meanwhile, I think we can push 0001 and 0002 patches since they are in
> good shape. I've updated commit messages to them and slightly changed
> 0002 patch to write "finished analyzing of table \"%s.%s.%s\" instead
> of  "analyze of table \"%s.%s.%s\".

Wouldn't it make sense to do the same for autoanalyze and write
"finished automatic analyze of table \"%s.%s.%s\"\n" instead of
"automatic analyze of table \"%s.%s.%s\"\n"?

> Also, regarding 0003 patch, what is the main reason why we want to add
> WAL usage to analyze reports? I think that analyze normally does not
> write WAL records much so I'm not sure it's going to provide a good
> insight for users.

There was no strong reason except for consistency with VACUUM VERBOSE
output. But as you said, it's not really providing valuable
information so it's probably better to keep the noise down and drop
it.

Regards,
Anthonin Bonnefoy

  16. Re: Use pgBufferUsage for block reporting in analyze

    Masahiko Sawada <sawada.mshk@gmail.com> — 2024-08-01T23:11:29Z

    On Wed, Jul 31, 2024 at 11:27 PM Anthonin Bonnefoy
<anthonin.bonnefoy@datadoghq.com> wrote:
>
> On Wed, Jul 31, 2024 at 9:36 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> > Meanwhile, I think we can push 0001 and 0002 patches since they are in
> > good shape. I've updated commit messages to them and slightly changed
> > 0002 patch to write "finished analyzing of table \"%s.%s.%s\" instead
> > of  "analyze of table \"%s.%s.%s\".
>
> Wouldn't it make sense to do the same for autoanalyze and write
> "finished automatic analyze of table \"%s.%s.%s\"\n" instead of
> "automatic analyze of table \"%s.%s.%s\"\n"?

I think that the current style is consistent with autovacuum logs:

2024-08-01 16:04:48.088 PDT [12302] LOG:  automatic vacuum of table
"postgres.public.test": index scans: 0
        pages: 0 removed, 443 remain, 443 scanned (100.00% of total)
        tuples: 0 removed, 100000 remain, 0 are dead but not yet removable
        removable cutoff: 751, which was 0 XIDs old when operation ended
        new relfrozenxid: 739, which is 1 XIDs ahead of previous value
        frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
        index scan not needed: 0 pages from table (0.00% of total) had
0 dead item identifiers removed
        avg read rate: 0.000 MB/s, avg write rate: 1.466 MB/s
        buffer usage: 905 hits, 0 reads, 4 dirtied
        system usage: CPU: user: 0.01 s, system: 0.00 s, elapsed: 0.02 s
2024-08-01 16:04:48.125 PDT [12302] LOG:  automatic analyze of table
"postgres.public.test"
        avg read rate: 5.551 MB/s, avg write rate: 0.617 MB/s
        buffer usage: 512 hits, 27 reads, 3 dirtied
        system usage: CPU: user: 0.02 s, system: 0.00 s, elapsed: 0.03 s

Since ANALYZE command writes the start log, I think it makes sense to
write "finished" at the end of the operation:

=# analyze verbose test;
INFO:  analyzing "public.test"
INFO:  "test": scanned 443 of 443 pages, containing 100000 live rows
and 0 dead rows; 30000 rows in sample, 100000 estimated total rows
INFO:  finished analyzing table "postgres.public.test"
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
buffer usage: 549 hits, 0 reads, 0 dirtied
system usage: CPU: user: 0.02 s, system: 0.00 s, elapsed: 0.03 s
ANALYZE

>
> > Also, regarding 0003 patch, what is the main reason why we want to add
> > WAL usage to analyze reports? I think that analyze normally does not
> > write WAL records much so I'm not sure it's going to provide a good
> > insight for users.
>
> There was no strong reason except for consistency with VACUUM VERBOSE
> output. But as you said, it's not really providing valuable
> information so it's probably better to keep the noise down and drop
> it.

Okay. I think writing WAL usage would not be very noisy and probably
could help some cases where (auto)analyze unexpectedly writes many WAL
records (e.g., writing full page images much), and is consistent with
(auto)vacuum logs as you mentioned. So let's go with this direction
unless others think differently.

Regards,

-- 
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com

  17. Re: Use pgBufferUsage for block reporting in analyze

    Masahiko Sawada <sawada.mshk@gmail.com> — 2024-08-14T05:36:57Z

    On Fri, Aug 2, 2024 at 8:11 AM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
>
> On Wed, Jul 31, 2024 at 11:27 PM Anthonin Bonnefoy
> <anthonin.bonnefoy@datadoghq.com> wrote:
> >
> > On Wed, Jul 31, 2024 at 9:36 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> > > Meanwhile, I think we can push 0001 and 0002 patches since they are in
> > > good shape. I've updated commit messages to them and slightly changed
> > > 0002 patch to write "finished analyzing of table \"%s.%s.%s\" instead
> > > of  "analyze of table \"%s.%s.%s\".
> >
> > Wouldn't it make sense to do the same for autoanalyze and write
> > "finished automatic analyze of table \"%s.%s.%s\"\n" instead of
> > "automatic analyze of table \"%s.%s.%s\"\n"?
>
> I think that the current style is consistent with autovacuum logs:
>
> 2024-08-01 16:04:48.088 PDT [12302] LOG:  automatic vacuum of table
> "postgres.public.test": index scans: 0
>         pages: 0 removed, 443 remain, 443 scanned (100.00% of total)
>         tuples: 0 removed, 100000 remain, 0 are dead but not yet removable
>         removable cutoff: 751, which was 0 XIDs old when operation ended
>         new relfrozenxid: 739, which is 1 XIDs ahead of previous value
>         frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
>         index scan not needed: 0 pages from table (0.00% of total) had
> 0 dead item identifiers removed
>         avg read rate: 0.000 MB/s, avg write rate: 1.466 MB/s
>         buffer usage: 905 hits, 0 reads, 4 dirtied
>         system usage: CPU: user: 0.01 s, system: 0.00 s, elapsed: 0.02 s
> 2024-08-01 16:04:48.125 PDT [12302] LOG:  automatic analyze of table
> "postgres.public.test"
>         avg read rate: 5.551 MB/s, avg write rate: 0.617 MB/s
>         buffer usage: 512 hits, 27 reads, 3 dirtied
>         system usage: CPU: user: 0.02 s, system: 0.00 s, elapsed: 0.03 s
>
> Since ANALYZE command writes the start log, I think it makes sense to
> write "finished" at the end of the operation:
>
> =# analyze verbose test;
> INFO:  analyzing "public.test"
> INFO:  "test": scanned 443 of 443 pages, containing 100000 live rows
> and 0 dead rows; 30000 rows in sample, 100000 estimated total rows
> INFO:  finished analyzing table "postgres.public.test"
> avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
> buffer usage: 549 hits, 0 reads, 0 dirtied
> system usage: CPU: user: 0.02 s, system: 0.00 s, elapsed: 0.03 s
> ANALYZE
>

Committed 0001 and 0002 patches.

> >
> > > Also, regarding 0003 patch, what is the main reason why we want to add
> > > WAL usage to analyze reports? I think that analyze normally does not
> > > write WAL records much so I'm not sure it's going to provide a good
> > > insight for users.
> >
> > There was no strong reason except for consistency with VACUUM VERBOSE
> > output. But as you said, it's not really providing valuable
> > information so it's probably better to keep the noise down and drop
> > it.
>
> Okay. I think writing WAL usage would not be very noisy and probably
> could help some cases where (auto)analyze unexpectedly writes many WAL
> records (e.g., writing full page images much), and is consistent with
> (auto)vacuum logs as you mentioned. So let's go with this direction
> unless others think differently.

I've updated the patch to add WAL usage to analyze. I'm going to push
it this week, barring any objections.

Regards,

-- 
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com