On Sun, Apr 18, 2021 at 9:02 AM vignesh C <vignes...@gmail.com> wrote:
>
> On Sun, Apr 18, 2021 at 8:43 AM Amit Kapila <amit.kapil...@gmail.com> wrote:
> >
> > On Sun, Apr 18, 2021 at 7:36 AM vignesh C <vignes...@gmail.com> wrote:
> > >
> > > On Sun, Apr 18, 2021 at 3:51 AM Tom Lane <t...@sss.pgh.pa.us> wrote:
> > > >
> > > > I wrote:
> > > > > The buildfarm suggests that this isn't entirely stable:
> > > > > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=anole&dt=2021-04-17%2011%3A14%3A49
> > > > > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=bichir&dt=2021-04-17%2016%3A30%3A15
> > > >
> > > > Oh, I missed that hyrax is showing the identical symptom:
> > > >
> > > > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hyrax&dt=2021-04-16%2007%3A05%3A44
> > > >
> > > > So you might try CLOBBER_CACHE_ALWAYS to see if you can reproduce it
> > > > that way.
> > > >
> > >
> > > I will try to check and identify why it is failing.
> > >
> >
> > I think the failure is due to the reason that in the new tests after
> > reset, we are not waiting for the stats message to be delivered as we
> > were doing in other cases. Also, for the new test (non-spilled case),
> > we need to decode changes as we are doing for other tests, otherwise,
> > it will show the old stats.
>
> I also felt that is the reason for the failure, I will fix and post a
> patch for this.
Attached a patch which includes the changes for the fix. I have moved
the non-spilled transaction test to reduce the steps which reduces
calling pg_logical_slot_get_changes before this test.
Regards,
Vignesh
diff --git a/contrib/test_decoding/expected/stats.out b/contrib/test_decoding/expected/stats.out
index bc8e601eab..c537e38bfe 100644
--- a/contrib/test_decoding/expected/stats.out
+++ b/contrib/test_decoding/expected/stats.out
@@ -51,20 +51,15 @@ BEGIN
extract(epoch from clock_timestamp() - start_time);
END
$$ LANGUAGE plpgsql;
--- spilling the xact
-BEGIN;
-INSERT INTO stats_test SELECT 'serialize-topbig--1:'||g.i FROM generate_series(1, 5000) g(i);
-COMMIT;
-SELECT count(*) FROM pg_logical_slot_peek_changes('regression_slot', NULL, NULL, 'skip-empty-xacts', '1');
+-- non-spilled xact
+INSERT INTO stats_test values(1);
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'skip-empty-xacts', '1');
count
-------
- 5002
+ 3
(1 row)
--- Check stats, wait for the stats collector to update. We can't test the
--- exact stats count as that can vary if any background transaction (say by
--- autovacuum) happens in parallel to the main transaction.
-SELECT wait_for_decode_stats(false, true);
+SELECT wait_for_decode_stats(false, false);
wait_for_decode_stats
-----------------------
@@ -73,17 +68,17 @@ SELECT wait_for_decode_stats(false, true);
SELECT slot_name, spill_txns > 0 AS spill_txns, spill_count > 0 AS spill_count, total_txns > 0 AS total_txns, total_bytes > 0 AS total_bytes FROM pg_stat_replication_slots;
slot_name | spill_txns | spill_count | total_txns | total_bytes
-----------------+------------+-------------+------------+-------------
- regression_slot | t | t | t | t
+ regression_slot | f | f | t | t
(1 row)
--- reset the slot stats, and wait for stats collector to reset
+-- reset the slot stats, and wait for stats collector's total txn to reset
SELECT pg_stat_reset_replication_slot('regression_slot');
pg_stat_reset_replication_slot
--------------------------------
(1 row)
-SELECT wait_for_decode_stats(true, true);
+SELECT wait_for_decode_stats(true, false);
wait_for_decode_stats
-----------------------
@@ -95,13 +90,19 @@ SELECT slot_name, spill_txns, spill_count, total_txns, total_bytes FROM pg_stat_
regression_slot | 0 | 0 | 0 | 0
(1 row)
--- decode and check stats again.
+-- spilling the xact
+BEGIN;
+INSERT INTO stats_test SELECT 'serialize-topbig--1:'||g.i FROM generate_series(1, 5000) g(i);
+COMMIT;
SELECT count(*) FROM pg_logical_slot_peek_changes('regression_slot', NULL, NULL, 'skip-empty-xacts', '1');
count
-------
5002
(1 row)
+-- Check stats, wait for the stats collector to update. We can't test the
+-- exact stats count as that can vary if any background transaction (say by
+-- autovacuum) happens in parallel to the main transaction.
SELECT wait_for_decode_stats(false, true);
wait_for_decode_stats
-----------------------
@@ -114,24 +115,42 @@ SELECT slot_name, spill_txns > 0 AS spill_txns, spill_count > 0 AS spill_count,
regression_slot | t | t | t | t
(1 row)
+-- reset the slot stats, and wait for stats collector to reset
SELECT pg_stat_reset_replication_slot('regression_slot');
pg_stat_reset_replication_slot
--------------------------------
(1 row)
--- non-spilled xact
-INSERT INTO stats_test values(generate_series(1, 10));
-SELECT wait_for_decode_stats(false, false);
+SELECT wait_for_decode_stats(true, true);
wait_for_decode_stats
-----------------------
(1 row)
-SELECT slot_name, spill_txns = 0 AS spill_txns, spill_count = 0 AS spill_count, total_txns > 0 AS total_txns, total_bytes > 0 AS total_bytes FROM pg_stat_replication_slots;
+SELECT slot_name, spill_txns, spill_count, total_txns, total_bytes FROM pg_stat_replication_slots;
slot_name | spill_txns | spill_count | total_txns | total_bytes
-----------------+------------+-------------+------------+-------------
- regression_slot | f | f | t | t
+ regression_slot | 0 | 0 | 0 | 0
+(1 row)
+
+-- decode and check stats again.
+SELECT count(*) FROM pg_logical_slot_peek_changes('regression_slot', NULL, NULL, 'skip-empty-xacts', '1');
+ count
+-------
+ 5002
+(1 row)
+
+SELECT wait_for_decode_stats(false, true);
+ wait_for_decode_stats
+-----------------------
+
+(1 row)
+
+SELECT slot_name, spill_txns > 0 AS spill_txns, spill_count > 0 AS spill_count, total_txns > 0 AS total_txns, total_bytes > 0 AS total_bytes FROM pg_stat_replication_slots;
+ slot_name | spill_txns | spill_count | total_txns | total_bytes
+-----------------+------------+-------------+------------+-------------
+ regression_slot | t | t | t | t
(1 row)
-- Ensure stats can be repeatedly accessed using the same stats snapshot. See
diff --git a/contrib/test_decoding/sql/stats.sql b/contrib/test_decoding/sql/stats.sql
index 8c34aeced1..8a0451dffe 100644
--- a/contrib/test_decoding/sql/stats.sql
+++ b/contrib/test_decoding/sql/stats.sql
@@ -50,6 +50,17 @@ BEGIN
END
$$ LANGUAGE plpgsql;
+-- non-spilled xact
+INSERT INTO stats_test values(1);
+SELECT count(*) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'skip-empty-xacts', '1');
+SELECT wait_for_decode_stats(false, false);
+SELECT slot_name, spill_txns > 0 AS spill_txns, spill_count > 0 AS spill_count, total_txns > 0 AS total_txns, total_bytes > 0 AS total_bytes FROM pg_stat_replication_slots;
+
+-- reset the slot stats, and wait for stats collector's total txn to reset
+SELECT pg_stat_reset_replication_slot('regression_slot');
+SELECT wait_for_decode_stats(true, false);
+SELECT slot_name, spill_txns, spill_count, total_txns, total_bytes FROM pg_stat_replication_slots;
+
-- spilling the xact
BEGIN;
INSERT INTO stats_test SELECT 'serialize-topbig--1:'||g.i FROM generate_series(1, 5000) g(i);
@@ -72,13 +83,6 @@ SELECT count(*) FROM pg_logical_slot_peek_changes('regression_slot', NULL, NULL,
SELECT wait_for_decode_stats(false, true);
SELECT slot_name, spill_txns > 0 AS spill_txns, spill_count > 0 AS spill_count, total_txns > 0 AS total_txns, total_bytes > 0 AS total_bytes FROM pg_stat_replication_slots;
-SELECT pg_stat_reset_replication_slot('regression_slot');
-
--- non-spilled xact
-INSERT INTO stats_test values(generate_series(1, 10));
-SELECT wait_for_decode_stats(false, false);
-SELECT slot_name, spill_txns = 0 AS spill_txns, spill_count = 0 AS spill_count, total_txns > 0 AS total_txns, total_bytes > 0 AS total_bytes FROM pg_stat_replication_slots;
-
-- Ensure stats can be repeatedly accessed using the same stats snapshot. See
-- https://postgr.es/m/20210317230447.c7uc4g3vbs4wi32i%40alap3.anarazel.de
BEGIN;
