public inbox for [email protected]
help / color / mirror / Atom feed[PATCH] Fix timeline-tracking failure while sending a historic timeline
3+ messages / 3 participants
[nested] [flat]
* [PATCH] Fix timeline-tracking failure while sending a historic timeline
@ 2021-01-05 04:34 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 3+ messages in thread
From: Kyotaro Horiguchi @ 2021-01-05 04:34 UTC (permalink / raw)
Walsender should track timeline switches while sending a historic
timeline. Regain that behavior, which was broken in PG13, by a thinko
of 709d003fbd. Backpatch to PG13.
---
src/backend/replication/walsender.c | 2 +-
src/test/perl/PostgresNode.pm | 33 ++++++++++++++++++
src/test/perl/TestLib.pm | 16 ++++++---
src/test/recovery/t/001_stream_rep.pl | 41 ++++++++++++++++++++++-
src/test/recovery/t/019_replslot_limit.pl | 37 ++++----------------
5 files changed, 92 insertions(+), 37 deletions(-)
diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 7f87eb7f19..04f6c3ebb4 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -2478,7 +2478,7 @@ WalSndSegmentOpen(XLogReaderState *state, XLogSegNo nextSegNo,
XLogSegNo endSegNo;
XLByteToSeg(sendTimeLineValidUpto, endSegNo, state->segcxt.ws_segsize);
- if (state->seg.ws_segno == endSegNo)
+ if (nextSegNo == endSegNo)
*tli_p = sendTimeLineNextTLI;
}
diff --git a/src/test/perl/PostgresNode.pm b/src/test/perl/PostgresNode.pm
index 980f1f1533..687aa3ac88 100644
--- a/src/test/perl/PostgresNode.pm
+++ b/src/test/perl/PostgresNode.pm
@@ -2138,6 +2138,39 @@ sub pg_recvlogical_upto
=pod
+=item $node->current_log_position()
+
+Return the current position of server log.
+
+=cut
+
+sub current_log_position
+{
+ my $self = shift;
+
+ return (stat $self->logfile)[7];
+}
+
+=pod
+
+=item $node->find_in_log($pattern, $startpos)
+
+Returns whether the $pattern occurs after $startpos in the server log.
+
+=cut
+
+sub find_in_log
+{
+ my ($self, $pattern, $startpos) = @_;
+
+ $startpos = 0 unless defined $startpos;
+ my $log = TestLib::slurp_file($self->logfile, $startpos);
+
+ return $log =~ m/$pattern/;
+}
+
+=pod
+
=back
=cut
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index a7490d2ce7..a0ce9521e2 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -402,30 +402,38 @@ sub slurp_dir
=pod
-=item slurp_file(filename)
+=item slurp_file(filename, pos)
-Return the full contents of the specified file.
+Return the contents after pos of the specified file.
+Reutrns the full contents if pos is omitted.
=cut
sub slurp_file
{
- my ($filename) = @_;
+ my ($filename, $from) = @_;
local $/;
my $contents;
+
+ $from = 0 unless defined $from;
+
if ($Config{osname} ne 'MSWin32')
{
open(my $in, '<', $filename)
or die "could not read \"$filename\": $!";
+ seek($in, $from, 0)
+ or die "could not seek \"$filename\" to $from: $!";
$contents = <$in>;
close $in;
}
else
{
my $fHandle = createFile($filename, "r", "rwd")
- or die "could not open \"$filename\": $^E";
+ or die "could not open \"$filename\": $^E\n";
OsFHandleOpen(my $fh = IO::Handle->new(), $fHandle, 'r')
or die "could not read \"$filename\": $^E\n";
+ seek($fh, $from, 0)
+ or die "could not seek \"$filename\" to $from: $^E\n";
$contents = <$fh>;
CloseHandle($fHandle)
or die "could not close \"$filename\": $^E\n";
diff --git a/src/test/recovery/t/001_stream_rep.pl b/src/test/recovery/t/001_stream_rep.pl
index 778f11b28b..8d2b24fe55 100644
--- a/src/test/recovery/t/001_stream_rep.pl
+++ b/src/test/recovery/t/001_stream_rep.pl
@@ -2,8 +2,9 @@
use strict;
use warnings;
use PostgresNode;
+use Time::HiRes qw(usleep);
use TestLib;
-use Test::More tests => 36;
+use Test::More tests => 37;
# Initialize master node
my $node_master = get_new_node('master');
@@ -409,3 +410,41 @@ ok( ($phys_restart_lsn_pre cmp $phys_restart_lsn_post) == 0,
my $master_data = $node_master->data_dir;
ok(!-f "$master_data/pg_wal/$segment_removed",
"WAL segment $segment_removed recycled after physical slot advancing");
+
+#
+# Check if timeline-increment works while reading a historic timeline.
+my $node_primary_2 = get_new_node('primary_2');
+# archiving is needed to create .paritial segment
+$node_primary_2->init(allows_streaming => 1, has_archiving => 1);
+$node_primary_2->start;
+$node_primary_2->backup($backup_name);
+my $node_standby_3 = get_new_node('standby_3');
+$node_standby_3->init_from_backup($node_primary_2, $backup_name,
+ has_streaming => 1);
+$node_primary_2->stop;
+$node_primary_2->set_standby_mode; # increment primary timeline
+$node_primary_2->start;
+$node_primary_2->promote;
+my $logstart = $node_standby_3->current_log_position();
+$node_standby_3->start;
+
+my $success = 0;
+for (my $i = 0 ; $i < 1000; $i++)
+{
+ if ($node_standby_3->find_in_log(
+ "requested WAL segment [0-9A-F]+ has already been removed",
+ $logstart))
+ {
+ last;
+ }
+ elsif ($node_standby_3->find_in_log(
+ "End of WAL reached on timeline",
+ $logstart))
+ {
+ $success = 1;
+ last;
+ }
+ usleep(100_000);
+}
+
+ok($success, 'Timeline increment while reading a historic timeline');
diff --git a/src/test/recovery/t/019_replslot_limit.pl b/src/test/recovery/t/019_replslot_limit.pl
index a7231dcd47..8b3c5de057 100644
--- a/src/test/recovery/t/019_replslot_limit.pl
+++ b/src/test/recovery/t/019_replslot_limit.pl
@@ -165,19 +165,17 @@ $node_master->wait_for_catchup($node_standby, 'replay', $start_lsn);
$node_standby->stop;
-ok( !find_in_log(
- $node_standby,
- "requested WAL segment [0-9A-F]+ has already been removed"),
+ok( !$node_standby->find_in_log(
+ "requested WAL segment [0-9A-F]+ has already been removed"),
'check that required WAL segments are still available');
# Advance WAL again, the slot loses the oldest segment.
-my $logstart = get_log_size($node_master);
+my $logstart = $node_master->current_log_position();
advance_wal($node_master, 7);
$node_master->safe_psql('postgres', "CHECKPOINT;");
# WARNING should be issued
-ok( find_in_log(
- $node_master,
+ok( $node_master->find_in_log(
"invalidating slot \"rep1\" because its restart_lsn [0-9A-F/]+ exceeds max_slot_wal_keep_size",
$logstart),
'check that the warning is logged');
@@ -190,14 +188,13 @@ is($result, "rep1|f|t|lost|",
'check that the slot became inactive and the state "lost" persists');
# The standby no longer can connect to the master
-$logstart = get_log_size($node_standby);
+$logstart = $node_standby->current_log_position();
$node_standby->start;
my $failed = 0;
for (my $i = 0; $i < 10000; $i++)
{
- if (find_in_log(
- $node_standby,
+ if ($node_standby->find_in_log(
"requested WAL segment [0-9A-F]+ has already been removed",
$logstart))
{
@@ -264,25 +261,3 @@ sub advance_wal
}
return;
}
-
-# return the size of logfile of $node in bytes
-sub get_log_size
-{
- my ($node) = @_;
-
- return (stat $node->logfile)[7];
-}
-
-# find $pat in logfile of $node after $off-th byte
-sub find_in_log
-{
- my ($node, $pat, $off) = @_;
-
- $off = 0 unless defined $off;
- my $log = TestLib::slurp_file($node->logfile);
- return 0 if (length($log) <= $off);
-
- $log = substr($log, $off);
-
- return $log =~ m/$pat/;
-}
--
2.27.0
----Next_Part(Wed_Jan__6_10_48_04_2021_104)----
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: pg_stat_io_histogram
@ 2026-01-28 11:12 Jakub Wartak <[email protected]>
2026-01-29 16:27 ` Re: pg_stat_io_histogram Andres Freund <[email protected]>
0 siblings, 1 reply; 3+ messages in thread
From: Jakub Wartak @ 2026-01-28 11:12 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: PostgreSQL Hackers <[email protected]>
On Tue, Jan 27, 2026 at 1:06 PM Jakub Wartak <[email protected]>
wrote:
> [..]
> > > Of course most of the I/O calls today are hitting page cache, so one
> would
> > > expect they'll be < 128us most of the time
> >
> > Have you measured whether overhead is measurable when hitting the page
> cache?
> > I'd hope that it doesn't, due to io combing amortizing the cost
> somewhat. But
> > it seems worth measuring.
>
> Not yet, I first wanted to hear if I'm not sailing into some plain stupid
> direction somewhere with this idea or implementation (e.g.
> that INSTR_TIME_GET_MICROSEC() was a really stupid omission from my side).
>
> I'll try to perform this test overhead measurement hopefully with v3 once
> we settle on how to do that bit shifting/clz().
>
[..]
Here's the answer: on properly isolated perf test run (my
old&legacy&predictiable
4s32c64t NUMA box, s_b=8GB, DB size 16GB, hugepages, no turboboost, proper
warmup,
no THP, cpupower D0, no physical I/O, ~22k pread64() calls/sec combined to
VFS
cache)
and started on just using single NUMA: numactl --membind=0
--cpunodebind=0
measured using: pgbench -M prepared -c 4 -j 4 postgres -T 20 -P 1 -S
master+track_io_timings=on, 60s warmup and then 3x runs
tps = 44615.603668
tps = 44556.191492
tps = 44813.793981
avg = 44662
master+track_io_timings=on+patch, , 60s warmup and then 3x runs
tps = 44441.879384
tps = 44403.101737
tps = 45036.747418
avg = 44627
so that's like 99.921% (so literally no overhead) and yields picture like:
postgres=# select bucket_latency_us, bucket_count
from pg_stat_io_histogram
where
bucket_count > 0 and
backend_type = 'client backend' and
io_type = 'read' and
context = 'normal'
order by bucket_latency_us;
bucket_latency_us | bucket_count
-------------------+--------------
[0,9) | 273455
[8,17) | 3820379
[16,33) | 29359
[32,65) | 585
[64,129) | 467
[128,257) | 419
[256,513) | 15828
[512,1025) | 89
So one can also see 0.25..0.5ms bucket being larger there (initial reading
of the data from physical device) and that's hardware RAID-1 with 2x
Intel D3-S4510. And if I do pg_buffercache_evict_all()+vm drop_cache+
pg_stat_reset_shared(), I get this picture (note for bulkreads):
postgres=# select bucket_latency_us, bucket_count
from pg_stat_io_histogram
where
bucket_count > 0 and
backend_type = 'client backend' and context='bulkread';
bucket_latency_us | bucket_count
-------------------+--------------
[0,9) | 102555
[8,17) | 70
[16,33) | 3938
[32,65) | 6763
[64,129) | 5206
[128,257) | 9392
[256,513) | 10959
[512,1025) | 21372
[1024,2049) | 502
[2048,4097) | 34
[4096,8193) | 2
[8192,16385) | 2
[16384,32769) | 7
So clearly there's a distinction between reading the VFS cache and hitting
physical I/O.
Now we'll just probably settle on the proper get_bucket_index() impl.
-J.
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: pg_stat_io_histogram
2026-01-28 11:12 Re: pg_stat_io_histogram Jakub Wartak <[email protected]>
@ 2026-01-29 16:27 ` Andres Freund <[email protected]>
0 siblings, 0 replies; 3+ messages in thread
From: Andres Freund @ 2026-01-29 16:27 UTC (permalink / raw)
To: Jakub Wartak <[email protected]>; +Cc: PostgreSQL Hackers <[email protected]>
Hi,
On 2026-01-28 12:12:10 +0100, Jakub Wartak wrote:
> On Tue, Jan 27, 2026 at 1:06 PM Jakub Wartak <[email protected]>
> > Not yet, I first wanted to hear if I'm not sailing into some plain stupid
> > direction somewhere with this idea or implementation (e.g.
> > that INSTR_TIME_GET_MICROSEC() was a really stupid omission from my side).
> >
> > I'll try to perform this test overhead measurement hopefully with v3 once
> > we settle on how to do that bit shifting/clz().
> >
>
> [..]
> Here's the answer: on properly isolated perf test run (my
> old&legacy&predictiable
> 4s32c64t NUMA box, s_b=8GB, DB size 16GB, hugepages, no turboboost, proper
> warmup,
> no THP, cpupower D0, no physical I/O, ~22k pread64() calls/sec combined to
> VFS
> cache)
> and started on just using single NUMA: numactl --membind=0
> --cpunodebind=0
> measured using: pgbench -M prepared -c 4 -j 4 postgres -T 20 -P 1 -S
>
> master+track_io_timings=on, 60s warmup and then 3x runs
> tps = 44615.603668
> tps = 44556.191492
> tps = 44813.793981
> avg = 44662
>
> master+track_io_timings=on+patch, , 60s warmup and then 3x runs
> tps = 44441.879384
> tps = 44403.101737
> tps = 45036.747418
> avg = 44627
>
> so that's like 99.921% (so literally no overhead) and yields picture like:
I don't think that's a particularly useful assurance, unfortunately:
1) Using pgbench with an in-memory readonly workload is typically limited by
context switch overhead and per-statement overhead. After a short while you
have at most one IO per statement (the heap page), which obviously isn't
going to be affected by a small per-IO overhead.
2) The per-core memory bandwidth on that old machine, if it's the quite old
EDB machine I think it is, is so low, that you'd be bottlenecked by memory
bandwidth well before you're going to be bottlenecked by actual CPU stuff
(which the bucket computation is).
I think you'd have to test something like pg_prewarm(), with
io_combine_limit=1, on a modern *client* CPU (client CPUs typically have much
higher per-core memory bandwidth than the more scalable server CPUs).
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2026-01-29 16:27 UTC | newest]
Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-01-05 04:34 [PATCH] Fix timeline-tracking failure while sending a historic timeline Kyotaro Horiguchi <[email protected]>
2026-01-28 11:12 Re: pg_stat_io_histogram Jakub Wartak <[email protected]>
2026-01-29 16:27 ` Re: pg_stat_io_histogram Andres Freund <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox