public inbox for [email protected]
help / color / mirror / Atom feedTest timings are increasing too fast for cfbot
9+ messages / 5 participants
[nested] [flat]
* Test timings are increasing too fast for cfbot
@ 2026-03-24 21:30 Andres Freund <[email protected]>
0 siblings, 1 reply; 9+ messages in thread
From: Andres Freund @ 2026-03-24 21:30 UTC (permalink / raw)
To: pgsql-hackers; +Cc: Dilip Kumar <[email protected]>; Jelte Fennema-Nio <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>
Hi,
I was working on giving at least committers, and perhaps a few more folks,
access to our custom compute setup for running CI, as I had gotten a few
reports about folks running out of CI cycles during busy periods like right
now.
I was thinking that we had enough compute credits to make that possible. Which
I luckily, prodded by a question from Melanie, did check.
Unfortunately it seems that our usage has increased substantially enough to
make that a problem, even with just cfbot.
Most of the test are quite cheap to run, however windows costs a fair bit in
licensing cost (we spend 2x on windows than we do for compute, ram and storage
for all the tests together). There's a few other things we can improve
(e.g. we spend a fair bit on cross region data transfers, which should largely
be fixable). But we do need to get the increases in windows runtime under
control.
Here's a look at the test timings. Unfortunately the trends are decidedly not
good, particularly on windows. Looking at a few random cross-branch commits
and looking only at the test times (since build times are affected by caching
etc).
CI msvc CI mingw CI linux andres-local
17 11:21 10:38 3:32 1:22
18 16:03 14:22 5:39 1:38
master 18:13 15:00 6:69 1:49
I checked this across a few commits and got similar numbers
everywhere. There's a lot of noise, but the trendline is pretty darn clear.
Due to the number of times we run the main regression tests, they have a
particularly large effect on test resources.
time cycles syscalls
17 37.13 239.2T 1.573M
18 44.27 295.7T 1.715M
master 48.19 323.5T 1.854M
Another interesting aspect is the time spent doing initdb has gone up
noticeably:
assert optimize
17 1.934 819.1
18 2.190 827.9
master 2.274 814.5
Which, given the number of times initdb is executed in the tests (even with
the template mechanism in place), probably is a factor in all this. It's
certainly interesting that somehow assertions play a major role, given that
the non-assert time hasn't regressed.
Some increase in test cycles and time is inevitable, but to me the current
rate of increase is not sustainable / faster than the rate at which hardware
speed increases.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: Test timings are increasing too fast for cfbot
@ 2026-03-25 03:15 Andres Freund <[email protected]>
parent: Andres Freund <[email protected]>
0 siblings, 4 replies; 9+ messages in thread
From: Andres Freund @ 2026-03-25 03:15 UTC (permalink / raw)
To: pgsql-hackers; +Cc: Dilip Kumar <[email protected]>; Jelte Fennema-Nio <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>
Hi,
On 2026-03-24 17:30:46 -0400, Andres Freund wrote:
> Due to the number of times we run the main regression tests, they have a
> particularly large effect on test resources.
>
> time cycles syscalls
> 17 37.13 239.2T 1.573M
> 18 44.27 295.7T 1.715M
> master 48.19 323.5T 1.854M
A surprisingly large source of this is psql internal queries. I first ran the
regression tests with pg_stat_statements activated [1] and noticed that a lot
of the queries, by exec and or plan time, are psql queries.
I patched psql to add "-- psql internal\n" to every internal query and then
used log_min_duration_statement=0 to see how much of the time is spent in psql
- ~13% of the reported duration of all queries.
A lot of that is because describeTbleDetails() ends up with a sequential scan:
regression[1020428][1]=# EXPLAIN ANALYZE SELECT c.oid,
n.nspname,
c.relname
FROM pg_catalog.pg_class c
LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace
WHERE c.relname OPERATOR(pg_catalog.~) '^(pg_class)$' COLLATE pg_catalog.default
AND pg_catalog.pg_table_is_visible(c.oid)
ORDER BY 2, 3;
┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
├──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Sort (cost=324.79..324.80 rows=1 width=132) (actual time=7.192..7.194 rows=1.00 loops=1) │
│ Sort Key: n.nspname, c.relname │
│ Sort Method: quicksort Memory: 25kB │
│ Buffers: shared hit=234 │
│ -> Nested Loop Left Join (cost=0.00..324.78 rows=1 width=132) (actual time=2.489..7.121 rows=1.00 loops=1) │
│ Join Filter: (n.oid = c.relnamespace) │
│ Buffers: shared hit=231 │
│ -> Seq Scan on pg_class c (cost=0.00..313.79 rows=1 width=72) (actual time=2.473..7.105 rows=1.00 loops=1) │
│ Filter: ((relname ~ '^(pg_class)$'::text) AND pg_table_is_visible(oid)) │
│ Rows Removed by Filter: 2260 │
│ Buffers: shared hit=229 │
│ -> Seq Scan on pg_namespace n (cost=0.00..8.22 rows=222 width=68) (actual time=0.011..0.011 rows=1.00 loops=1) │
│ Buffers: shared hit=2 │
│ Planning: │
│ Buffers: shared hit=6 │
│ Planning Time: 0.520 ms │
│ Execution Time: 7.265 ms │
└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(17 rows)
It seems decidedly not optimal that "\d tablename", without any patterns, ends
up doing a seqscan. That's bad enough in the regression database, but there
are many PG instances with many many entries in pg_class.
I don't think this was always the case?
If I remove the COLLATE pg_catalog.default, a sane plan is chosen. That's
obviously not the right fix, but seemed interesting enough to mention.
That alone seems makes a surprising 4.5% improvement in an unoptimized -O0
build.
Another psql query that stands out is \d's query for publications. Not because
of runtime, but because of the planning cost. Nuking that (obviously not
correct), is worth another 3% of test time (and some test failues).
I've not analyzed the psql queries any further, but I'd bet that the rest also
do add up.
The most expensive query in the entire regression tests is:
DO $$
BEGIN
FOR r IN 1..1350 LOOP
DELETE FROM dedup_unique_test_table;
INSERT INTO dedup_unique_test_table SELECT 1;
END LOOP;
END$$;
which makes sense, as that's pretty clearly O(N^2).
There are a surprisingly large number of temporary file creations in the
regression tests. A lot of them due to shared file sets in the context of
parallelism. I wonder whether that is a partial cause for the slowness on
windows, which has very slow metadata operations and slower data caching.
The slowest test is stats_ext.sql - Not surprising, it does sequential scans
of tables with ~1000-10000 rows over and over again. I don't see why it has
to do that with as many rows as it does.
Another thing we spend a decent amount of time, distributed over many places,
is FROM generate_series(x, y), which ends up slow due to nodeFunctionscan.c
always using a tuplestore.
Code wise, the most immediately noticeable things are
1) MEMORY_CONTEXT_CHECKING
2) AssertCheckRanges() (only in the brin test, but there a very large portion
of the runtime)
3) verify_compact_attribute(), pretty spread around
Greetings,
Andres Freund
[1] which annoyingly generates a bunch of test failures due to "Query
Identifier" getting added to tests
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: Test timings are increasing too fast for cfbot
@ 2026-03-25 04:36 Julien Rouhaud <[email protected]>
parent: Andres Freund <[email protected]>
3 siblings, 1 reply; 9+ messages in thread
From: Julien Rouhaud @ 2026-03-25 04:36 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: pgsql-hackers; Dilip Kumar <[email protected]>; Jelte Fennema-Nio <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>
Hi,
On Tue, Mar 24, 2026 at 11:15:32PM -0400, Andres Freund wrote:
>
> A surprisingly large source of this is psql internal queries. I first ran the
> regression tests with pg_stat_statements activated [1] and noticed that a lot
> of the queries, by exec and or plan time, are psql queries.
>
> [1] which annoyingly generates a bunch of test failures due to "Query
> Identifier" getting added to tests
FWIW `compute_query_id = regress` is supposed to avoid that problem.
^ permalink raw reply [nested|flat] 9+ messages in thread
* Make \d tablename fast again, regression introduced by 85b7efa1cdd
@ 2026-03-25 08:54 Jelte Fennema-Nio <[email protected]>
parent: Andres Freund <[email protected]>
3 siblings, 0 replies; 9+ messages in thread
From: Jelte Fennema-Nio @ 2026-03-25 08:54 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: pgsql-hackers; Dilip Kumar <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>; Peter Eisentraut <[email protected]>
(forked from: Test timings are increasing too fast for cfbot)
On Wed, 25 Mar 2026 at 04:15, Andres Freund <[email protected]> wrote:
> It seems decidedly not optimal that "\d tablename", without any patterns, ends
> up doing a seqscan. That's bad enough in the regression database, but there
> are many PG instances with many many entries in pg_class.
>
> I don't think this was always the case?
>
> If I remove the COLLATE pg_catalog.default, a sane plan is chosen. That's
> obviously not the right fix, but seemed interesting enough to mention.
Due to a very similar problem I faced in the past[1], I thought I had a
good sense of where roughly the problem was. And I indeed quickly found
it.
Attached is a patch that addresses this issue and starts using index
scans again for \d tablename.
This should be backpatched to PG18 where the regression was introduced
by 85b7efa1cdd
[1]: https://www.postgresql.org/message-id/flat/CAGECzQRqysy0eJMKR5he3gwtLrT87f9u5CQQua6B_XNwMnUtFA%40mai...
Attachments:
[text/x-patch] v1-0001-Fix-LIKE-optimization-for-prefix-scan-with-determ.patch (4.2K, 2-v1-0001-Fix-LIKE-optimization-for-prefix-scan-with-determ.patch)
download | inline diff:
From 0ab6bef30ab0b19e4704328624cb926d09a07876 Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <[email protected]>
Date: Wed, 25 Mar 2026 09:29:05 +0100
Subject: [PATCH v1] Fix LIKE optimization for prefix scan with deterministic
collations
In 85b7efa1cdd support was introduced for LIKE on non-deterministic
collations. By moving some conditionals around, that accidentally broke
the LIKE optimization for deterministic collations when the index
collation did not match the filter collation. This re-introduces the
optimization.
Important benefactors of this optimization are the "\d tablename" and
"\d tablename*" commands in psql. Without this optimization they do a
sequence scan instead of an index lookup/prefix scan.
Discussion: https://postgr.es/m/mtkrkkcn2tlhytumitpch5ubxiprv2jzvprf5r5m3mjeczvq4q@p6wkzbfxuyv2
Backpatch-through: 18
---
src/backend/utils/adt/like_support.c | 3 ++-
src/test/regress/expected/collate.out | 18 ++++++++++++++++++
src/test/regress/sql/collate.sql | 11 +++++++++++
3 files changed, 31 insertions(+), 1 deletion(-)
diff --git a/src/backend/utils/adt/like_support.c b/src/backend/utils/adt/like_support.c
index 01cd6b10730..dd6524fcec4 100644
--- a/src/backend/utils/adt/like_support.c
+++ b/src/backend/utils/adt/like_support.c
@@ -386,7 +386,8 @@ match_pattern_prefix(Node *leftop,
{
if (!op_in_opfamily(eqopr, opfamily))
return NIL;
- if (indexcollation != expr_coll)
+ if (indexcollation != expr_coll &&
+ expr_coll && !get_collation_isdeterministic(expr_coll))
return NIL;
expr = make_opclause(eqopr, BOOLOID, false,
(Expr *) leftop, (Expr *) prefix,
diff --git a/src/test/regress/expected/collate.out b/src/test/regress/expected/collate.out
index 25818f09ad2..c4cf7cfc644 100644
--- a/src/test/regress/expected/collate.out
+++ b/src/test/regress/expected/collate.out
@@ -768,6 +768,24 @@ DETAIL: LOCALE cannot be specified together with LC_COLLATE or LC_CTYPE.
CREATE COLLATION coll_dup_chk (FROM = "C", VERSION = "1");
ERROR: conflicting or redundant options
DETAIL: FROM cannot be specified together with any other options.
+-- Regex exact-match optimization should use index even when the expression
+-- has COLLATE "default" and the index has a different (but deterministic)
+-- collation OID, because equality is collation-insensitive for deterministic
+-- collations.
+CREATE TABLE collate_tests.regex_idx_test (x text);
+CREATE INDEX ON collate_tests.regex_idx_test (x COLLATE "C");
+SET enable_seqscan = off;
+EXPLAIN (costs off) SELECT * FROM collate_tests.regex_idx_test WHERE x ~ '^(abc)$' COLLATE "default";
+ QUERY PLAN
+-------------------------------------------------
+ Bitmap Heap Scan on regex_idx_test
+ Filter: (x ~ '^(abc)$'::text)
+ -> Bitmap Index Scan on regex_idx_test_x_idx
+ Index Cond: (x = 'abc'::text)
+(4 rows)
+
+RESET enable_seqscan;
+DROP TABLE collate_tests.regex_idx_test;
--
-- Clean up. Many of these table names will be re-used if the user is
-- trying to run any platform-specific collation tests later, so we
diff --git a/src/test/regress/sql/collate.sql b/src/test/regress/sql/collate.sql
index 4b0e4472c3f..4f4f607c70e 100644
--- a/src/test/regress/sql/collate.sql
+++ b/src/test/regress/sql/collate.sql
@@ -302,6 +302,17 @@ CREATE COLLATION coll_dup_chk (LC_CTYPE = "POSIX", LOCALE = '');
-- FROM conflicts with any other option
CREATE COLLATION coll_dup_chk (FROM = "C", VERSION = "1");
+-- Regex exact-match optimization should use index even when the expression
+-- has COLLATE "default" and the index has a different (but deterministic)
+-- collation OID, because equality is collation-insensitive for deterministic
+-- collations.
+CREATE TABLE collate_tests.regex_idx_test (x text);
+CREATE INDEX ON collate_tests.regex_idx_test (x COLLATE "C");
+SET enable_seqscan = off;
+EXPLAIN (costs off) SELECT * FROM collate_tests.regex_idx_test WHERE x ~ '^(abc)$' COLLATE "default";
+RESET enable_seqscan;
+DROP TABLE collate_tests.regex_idx_test;
+
--
-- Clean up. Many of these table names will be re-used if the user is
-- trying to run any platform-specific collation tests later, so we
base-commit: c79e4141273caa1b4fb88c479bb90dc40f2fbbf2
--
2.53.0
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: Test timings are increasing too fast for cfbot
@ 2026-03-25 14:38 Tomas Vondra <[email protected]>
parent: Andres Freund <[email protected]>
3 siblings, 1 reply; 9+ messages in thread
From: Tomas Vondra @ 2026-03-25 14:38 UTC (permalink / raw)
To: Andres Freund <[email protected]>; pgsql-hackers; +Cc: Dilip Kumar <[email protected]>; Jelte Fennema-Nio <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>
On 3/25/26 04:15, Andres Freund wrote:
> ...
>
> The slowest test is stats_ext.sql - Not surprising, it does sequential scans
> of tables with ~1000-10000 rows over and over again. I don't see why it has
> to do that with as many rows as it does.
>
IIRC we needed to use non-trivial amounts of data to ensure building the
right right type of statistics (e.g. no MCV). But I understand it can be
annoyingly expensive, so I'll try to make it cheaper.
> ...
> 2) AssertCheckRanges() (only in the brin test, but there a very large portion
> of the runtime)
True. It is a very comprehensive validation of the ranges, and it was
very useful - particularly during development. But I'll try to make it
more targeted at the stuff actually changed / called less often.
Both changes will require time (so that we don't lose test coverage),
but I assume it's OK if that happens sometime after the feature freeze.
regards
--
Tomas Vondra
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: Test timings are increasing too fast for cfbot
@ 2026-03-25 16:13 Andres Freund <[email protected]>
parent: Tomas Vondra <[email protected]>
0 siblings, 0 replies; 9+ messages in thread
From: Andres Freund @ 2026-03-25 16:13 UTC (permalink / raw)
To: Tomas Vondra <[email protected]>; +Cc: pgsql-hackers; Dilip Kumar <[email protected]>; Jelte Fennema-Nio <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>
Hi,
On 2026-03-25 15:38:01 +0100, Tomas Vondra wrote:
> On 3/25/26 04:15, Andres Freund wrote:
> > ...
> >
> > The slowest test is stats_ext.sql - Not surprising, it does sequential scans
> > of tables with ~1000-10000 rows over and over again. I don't see why it has
> > to do that with as many rows as it does.
> >
>
> IIRC we needed to use non-trivial amounts of data to ensure building the
> right right type of statistics (e.g. no MCV). But I understand it can be
> annoyingly expensive, so I'll try to make it cheaper.
Great. It might also be worth checking if any of the query conditions can be
made cheaper without actually changing what they do test.
> > ...
> > 2) AssertCheckRanges() (only in the brin test, but there a very large portion
> > of the runtime)
>
> True. It is a very comprehensive validation of the ranges, and it was
> very useful - particularly during development. But I'll try to make it
> more targeted at the stuff actually changed / called less often.
Makes sense. There might also be some changs that make it faster without
loosing any coverage. E.g. not using FunctionCall2Coll() - which initializes
stuff on every call - but doing InitFunctionCallInfoData() once and then
update arguments + FunctionCallInvoke() for each call.
> Both changes will require time (so that we don't lose test coverage),
> but I assume it's OK if that happens sometime after the feature freeze.
Yea. We're not running out of credits tomorrow or something like that.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: Test timings are increasing too fast for cfbot
@ 2026-03-25 22:09 David Rowley <[email protected]>
parent: Andres Freund <[email protected]>
3 siblings, 1 reply; 9+ messages in thread
From: David Rowley @ 2026-03-25 22:09 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: pgsql-hackers; Dilip Kumar <[email protected]>; Jelte Fennema-Nio <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>
On Wed, 25 Mar 2026 at 16:15, Andres Freund <[email protected]> wrote:
> Code wise, the most immediately noticeable things are
> 3) verify_compact_attribute(), pretty spread around
We do now have TupleDescFinalize(), where those could be checked just
once rather than on each call to TupleDescCompactAttr(). That's not
quite as watertight a guarantee as someone could change the
FormData_pg_attribute after TupleDescFinalize(). Just doing it in
TupleDescFinalize() would at least still catch the places where people
forget to call populate_compact_attribute() before
TupleDescFinalize().
I would have expected this to be a little less overhead now since
d8a859d22 removed the calls to TupleDescCompactAttr() in the main
deforming routine. Maybe I should just make that change in the other
deformers...? Do you have an idea of which callers of
verify_compact_attribute() are causing the most overhead?
David
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: Test timings are increasing too fast for cfbot
@ 2026-03-26 14:02 Andres Freund <[email protected]>
parent: David Rowley <[email protected]>
0 siblings, 0 replies; 9+ messages in thread
From: Andres Freund @ 2026-03-26 14:02 UTC (permalink / raw)
To: David Rowley <[email protected]>; +Cc: pgsql-hackers; Dilip Kumar <[email protected]>; Jelte Fennema-Nio <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>
On 2026-03-26 11:09:36 +1300, David Rowley wrote:
> On Wed, 25 Mar 2026 at 16:15, Andres Freund <[email protected]> wrote:
> > Code wise, the most immediately noticeable things are
>
> > 3) verify_compact_attribute(), pretty spread around
>
> We do now have TupleDescFinalize(), where those could be checked just
> once rather than on each call to TupleDescCompactAttr(). That's not
> quite as watertight a guarantee as someone could change the
> FormData_pg_attribute after TupleDescFinalize(). Just doing it in
> TupleDescFinalize() would at least still catch the places where people
> forget to call populate_compact_attribute() before
> TupleDescFinalize().
Maybe verify_compact_attribute() could just do an assert comparison between
the underlying non-compact attribute and the compact one? Or even just an
assert checking if the compact attribute is initialized, with the full
checking happening in TupleDescFinalize(), as you suggest?
> I would have expected this to be a little less overhead now since
> d8a859d22 removed the calls to TupleDescCompactAttr() in the main
> deforming routine. Maybe I should just make that change in the other
> deformers...?
Might be worth it.
> Do you have an idea of which callers of verify_compact_attribute() are
> causing the most overhead?
I'm not sure how much to believe the profile when the costs are as distributed
as they are here. But according to the profile it's
- heap_form_tuple
- heap_form_minimal_tuple
- index_getattr
- nocachegetattr
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: Test timings are increasing too fast for cfbot
@ 2026-03-26 14:11 Andres Freund <[email protected]>
parent: Julien Rouhaud <[email protected]>
0 siblings, 0 replies; 9+ messages in thread
From: Andres Freund @ 2026-03-26 14:11 UTC (permalink / raw)
To: Julien Rouhaud <[email protected]>; +Cc: pgsql-hackers; Dilip Kumar <[email protected]>; Jelte Fennema-Nio <[email protected]>; Thomas Munro <[email protected]>; Noah Misch <[email protected]>
Hi,
On 2026-03-25 12:36:12 +0800, Julien Rouhaud wrote:
> On Tue, Mar 24, 2026 at 11:15:32PM -0400, Andres Freund wrote:
> >
> > A surprisingly large source of this is psql internal queries. I first ran the
> > regression tests with pg_stat_statements activated [1] and noticed that a lot
> > of the queries, by exec and or plan time, are psql queries.
> >
> > [1] which annoyingly generates a bunch of test failures due to "Query
> > Identifier" getting added to tests
>
> FWIW `compute_query_id = regress` is supposed to avoid that problem.
Hm. I guess that should work. Thanks!
It's pretty annoying that one has to manually specify it to keep the tests
passing. I wonder if we should make pg_regress specify it to avoid that.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 9+ messages in thread
end of thread, other threads:[~2026-03-26 14:11 UTC | newest]
Thread overview: 9+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2026-03-24 21:30 Test timings are increasing too fast for cfbot Andres Freund <[email protected]>
2026-03-25 03:15 ` Andres Freund <[email protected]>
2026-03-25 04:36 ` Julien Rouhaud <[email protected]>
2026-03-26 14:11 ` Andres Freund <[email protected]>
2026-03-25 08:54 ` Make \d tablename fast again, regression introduced by 85b7efa1cdd Jelte Fennema-Nio <[email protected]>
2026-03-25 14:38 ` Tomas Vondra <[email protected]>
2026-03-25 16:13 ` Andres Freund <[email protected]>
2026-03-25 22:09 ` David Rowley <[email protected]>
2026-03-26 14:02 ` 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