Re: Replication slot stats misgivings - Mailing list pgsql-hackers

On Thu, Apr 29, 2021 at 3:06 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Wed, Apr 28, 2021 at 5:01 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > On Wed, Apr 28, 2021 at 4:51 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> > >
> > > On Wed, Apr 28, 2021 at 6:39 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > @@ -1369,7 +1369,7 @@ ReorderBufferIterTXNNext(ReorderBuffer *rb,
> > ReorderBufferIterTXNState *state)
> >   * Update the total bytes processed before releasing the current set
> >   * of changes and restoring the new set of changes.
> >   */
> > - rb->totalBytes += rb->size;
> > + rb->totalBytes += entry->txn->total_size;
> >   if (ReorderBufferRestoreChanges(rb, entry->txn, &entry->file,
> >   &state->entries[off].segno))
> >
> > I have not tested this but won't in the above change you need to check
> > txn->toptxn for subtxns?
> >
>
> Now, I am able to reproduce this issue:
> Create table t1(c1 int);
> select pg_create_logical_replication_slot('s', 'test_decoding');
> Begin;
> insert into t1 values(1);
> savepoint s1;
> insert into t1 select generate_series(1, 100000);
> commit;
>
> postgres=# select count(*) from pg_logical_slot_peek_changes('s1', NULL, NULL);
>  count
> --------
>  100005
> (1 row)
>
> postgres=# select * from pg_stat_replication_slots;
>  slot_name | spill_txns | spill_count | spill_bytes | stream_txns |
> stream_count | stream_bytes | total_txns | total_bytes |
> stats_reset
> -----------+------------+-------------+-------------+-------------+--------------+--------------+------------+-------------+----------------------------------
>  s1        |          0 |           0 |           0 |           0 |
>         0 |            0 |          2 |    13200672 | 2021-04-29
> 14:33:55.156566+05:30
> (1 row)
>
> select * from pg_stat_reset_replication_slot('s1');
>
> Now reduce the logical decoding work mem to allow spilling.
> postgres=# set logical_decoding_work_mem='64kB';
> SET
> postgres=# select count(*) from pg_logical_slot_peek_changes('s1', NULL, NULL);
>  count
> --------
>  100005
> (1 row)
>
> postgres=# select * from pg_stat_replication_slots;
>  slot_name | spill_txns | spill_count | spill_bytes | stream_txns |
> stream_count | stream_bytes | total_txns | total_bytes |
> stats_reset
> -----------+------------+-------------+-------------+-------------+--------------+--------------+------------+-------------+----------------------------------
>  s1        |          1 |         202 |    13200000 |           0 |
>         0 |            0 |          2 |         672 | 2021-04-29
> 14:35:21.836613+05:30
> (1 row)
>
> You can notice that after we have allowed spilling the 'total_bytes'
> stats is showing a different value. The attached patch fixes the issue
> for me. Let me know what do you think about this?

I found one issue with the following scenario when testing with logical_decoding_work_mem as 64kB:

BEGIN;
INSERT INTO t1 values(generate_series(1,10000));
SAVEPOINT s1;
INSERT INTO t1 values(generate_series(1,10000));
COMMIT;
SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot1', NULL,
        NULL, 'include-xids', '0', 'skip-empty-xacts', '1');
select * from pg_stat_replication_slots;
    slot_name     | spill_txns | spill_count | spill_bytes | stream_txns | stream_count | stream_bytes | total_txns | total_bytes |           stats_reset            
------------------+------------+-------------+-------------+-------------+--------------+--------------+------------+-------------+----------------------------------
 regression_slot1 |          6 |         154 |     9130176 |           0 |            0 |            0 |          1 |     4262016 | 2021-04-29 17:50:00.080663+05:30
(1 row)

Same thing works fine with logical_decoding_work_mem as 64MB:
select * from pg_stat_replication_slots;
   slot_name     | spill_txns | spill_count | spill_bytes | stream_txns | stream_count | stream_bytes | total_txns | total_bytes |           stats_reset            
------------------+------------+-------------+-------------+-------------+--------------+--------------+------------+-------------+----------------------------------
 regression_slot1 |          6 |         154 |     9130176 |           0 |            0 |            0 |          1 |     2640000 | 2021-04-29 17:50:00.080663+05:30
(1 row)