Обсуждение: Slow queries on simple index

Logs on our PostgreSQL cluster show frequent slow reads on a simple query by unique index. 

This issue has been present for some years, and survived multiple server moves as well as PostgreSQL version upgrades.
Vacuuming or reindexing the table does not seem to help.

Jan 17 13:38:13 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[172632]: pluralkit-db-dataLOG:
duration:2322.842 ms  execute <unnamed>: SELECT * FROM "members" WHERE "hid" = $1
 
Jan 17 13:38:15 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[157893]: pluralkit-db-dataLOG:
duration:2155.033 ms  execute _auto8: SELECT * FROM "members" WHERE "hid" = $1
 
Jan 17 13:38:16 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[157826]: pluralkit-db-dataLOG:
duration:2164.851 ms  execute _auto10: SELECT * FROM "members" WHERE "hid" = $1
 
Jan 17 13:38:19 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[171076]: pluralkit-db-dataLOG:
duration:2039.040 ms  execute _auto3: SELECT * FROM "members" WHERE "hid" = $1
 
Jan 17 13:38:20 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[162682]: pluralkit-db-dataLOG:
duration:2189.700 ms  execute _auto8: SELECT * FROM "members" WHERE "hid" = $1
 
Jan 17 13:38:22 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[159824]: pluralkit-db-dataLOG:
duration:2137.666 ms  execute _auto10: SELECT * FROM "members" WHERE "hid" = $1
 

Parameter detail has been redacted for privacy.

This is not reproducible on manual queries, whether using the same values or other random ones.

pluralkit=# explain (analyze, buffers, settings) select * from members where hid = 'exampl';
                                                          QUERY PLAN

------------------------------------------------------------------------------------------------------------------------------
 Index Scan using members_hid_key on members  (cost=0.43..8.45 rows=1 width=838) (actual time=0.098..0.098 rows=0.00
loops=1)
   Index Cond: (hid = 'exampl'::bpchar)
   Index Searches: 1
   Buffers: shared hit=3
 Settings: effective_cache_size = '40GB'
 Planning Time: 0.161 ms
 Execution Time: 0.124 ms
(7 rows)

Table info:

pluralkit=# \d+ members
                                                                            Table "public.members"
         Column         |            Type             | Collation | Nullable |                 Default
|Storage  | Compression | Stats target | Description
 

------------------------+-----------------------------+-----------+----------+------------------------------------------+----------+-------------+--------------+-------------
 id                     | integer                     |           | not null | nextval('members_id_seq'::regclass)
|plain    |             |              |
 
 hid                    | character(6)                |           | not null |
|extended |             |              |
 
 system                 | integer                     |           | not null | nextval('members_system_seq'::regclass)
|plain    |             |              |
 
 color                  | character(6)                |           |          |
|extended |             |              |
 
 avatar_url             | text                        |           |          |
|extended |             |              |
 
 name                   | text                        |           | not null |
|extended |             |              |
 
 birthday               | date                        |           |          |
|plain    |             |              |
 
 pronouns               | text                        |           |          |
|extended |             |              |
 
 description            | text                        |           |          |
|extended |             |              |
 
 created                | timestamp without time zone |           | not null | timezone('utc'::text, CURRENT_TIMESTAMP)
|plain    |             |              |
 
 display_name           | text                        |           |          |
|extended |             |              |
 
 proxy_tags             | proxy_tag[]                 |           | not null | ARRAY[]::proxy_tag[]
|extended |             |              |
 
 keep_proxy             | boolean                     |           | not null | false
|plain    |             |              |
 
 member_visibility      | integer                     |           | not null | 1
|plain    |             |              |
 
 message_count          | integer                     |           | not null | 0
|plain    |             |              |
 
 description_privacy    | integer                     |           | not null | 1
|plain    |             |              |
 
 name_privacy           | integer                     |           | not null | 1
|plain    |             |              |
 
 avatar_privacy         | integer                     |           | not null | 1
|plain    |             |              |
 
 birthday_privacy       | integer                     |           | not null | 1
|plain    |             |              |
 
 pronoun_privacy        | integer                     |           | not null | 1
|plain    |             |              |
 
 metadata_privacy       | integer                     |           | not null | 1
|plain    |             |              |
 
 allow_autoproxy        | boolean                     |           | not null | true
|plain    |             |              |
 
 banner_image           | text                        |           |          |
|extended |             |              |
 
 uuid                   | uuid                        |           |          | public.gen_random_uuid()
|plain    |             |              |
 
 last_message_timestamp | timestamp without time zone |           |          |
|plain    |             |              |
 
 webhook_avatar_url     | text                        |           |          |
|extended |             |              |
 
 proxy_privacy          | integer                     |           | not null | 1
|plain    |             |              |
 
 tts                    | boolean                     |           | not null | false
|plain    |             |              |
 
 banner_privacy         | integer                     |           | not null | 1
|plain    |             |              |
 
Indexes:
    "members_pkey" PRIMARY KEY, btree (id)
    "members_by_system" btree (system)
    "members_hid_key" UNIQUE CONSTRAINT, btree (hid)
    "members_uuid_idx" btree (uuid)
Check constraints:
    "members_avatar_privacy_check" CHECK (avatar_privacy = ANY (ARRAY[1, 2]))
    "members_banner_privacy_check" CHECK (banner_privacy = ANY (ARRAY[1, 2]))
    "members_birthday_privacy_check" CHECK (birthday_privacy = ANY (ARRAY[1, 2]))
    "members_description_privacy_check" CHECK (description_privacy = ANY (ARRAY[1, 2]))
    "members_member_privacy_check" CHECK (member_visibility = ANY (ARRAY[1, 2]))
    "members_metadata_privacy_check" CHECK (metadata_privacy = ANY (ARRAY[1, 2]))
    "members_name_privacy_check" CHECK (name_privacy = ANY (ARRAY[1, 2]))
    "members_pronoun_privacy_check" CHECK (pronoun_privacy = ANY (ARRAY[1, 2]))
    "members_proxy_privacy_check" CHECK (proxy_privacy = ANY (ARRAY[1, 2]))
Foreign-key constraints:
    "members_system_fkey" FOREIGN KEY (system) REFERENCES systems(id) ON DELETE CASCADE
Referenced by:
    TABLE "autoproxy" CONSTRAINT "autoproxy_autoproxy_member_fkey" FOREIGN KEY (autoproxy_member) REFERENCES
members(id)ON DELETE SET NULL
 
    TABLE "group_members" CONSTRAINT "group_members_member_id_fkey" FOREIGN KEY (member_id) REFERENCES members(id) ON
DELETECASCADE
 
    TABLE "member_guild" CONSTRAINT "member_guild_member_fkey" FOREIGN KEY (member) REFERENCES members(id) ON DELETE
CASCADE
    TABLE "switch_members" CONSTRAINT "switch_members_member_fkey" FOREIGN KEY (member) REFERENCES members(id) ON
DELETECASCADE
 
Access method: heap

pluralkit=# SELECT relname, relpages, reltuples, relallvisible, relkind, relnatts, relhassubclass, reloptions,
pg_table_size(oid)FROM pg_class WHERE relname='members';
 
-[ RECORD 1 ]--+--------------
relname        | members
relpages       | 816042
reltuples      | 1.3412575e+07
relallvisible  | 297904
relkind        | r
relnatts       | 29
relhassubclass | f
reloptions     |
pg_table_size  | 6687031296

postgresql.conf:

archive_command = '/nix/store/dz9vwg5grhvpz4v7rscdl95n7s5z8c3x-pluralkit-scripts-1/bin/pk-walg data 5432 pluralkit
wal-push%p'
 
archive_mode = 'yes'
archive_timeout = 60
effective_cache_size = '40GB'
hba_file = '/nix/store/0pihm0qzk2pdn1d344p8kihpa58hd7s6-pg_hba.conf'
listen_addresses = 'localhost, 100.123.150.13, fdaa:9:e856:a7b:910f:0:a:102'
log_destination = 'stderr'
log_line_prefix = 'pluralkit-db-data'
log_min_duration_statement = 1000
max_connections = 2000
max_wal_size = '1GB'
min_wal_size = '80MB'
port = 5432
shared_buffers = '50GB'

Environment:

PostgreSQL 18.1 on x86_64-pc-linux-gnu, compiled by clang version 20.1.8, 64-bit
installed from nixpkgs
NixOS 25.11 on Linux 6.12.61 on AMD EPYC 7351P
2x Intel SSDPELKX020T7 in RAID1 (md-raid), with LUKS, ext4 filesystem

Same issue previously appeared on
PostgreSQL 14, both self-compiled and from nixpkgs
NixOS 24.10 on AMD Ryzen 7950X
ext4 filesystem directly on single Kioxia enterprise SSD (sorry I don't remember the model)

Kindly,
Lillian

On Sat, Jan 17, 2026 at 02:58:01PM +0100, Lillian Berry wrote:
> Logs on our PostgreSQL cluster show frequent slow reads on a simple query by unique index. 
> 
> This issue has been present for some years, and survived multiple server moves as well as PostgreSQL version
upgrades.
> Vacuuming or reindexing the table does not seem to help.
> 
> Jan 17 13:38:13 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[172632]: pluralkit-db-dataLOG:
duration:2322.842 ms  execute <unnamed>: SELECT * FROM "members" WHERE "hid" = $1
 
> Jan 17 13:38:15 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[157893]: pluralkit-db-dataLOG:
duration:2155.033 ms  execute _auto8: SELECT * FROM "members" WHERE "hid" = $1
 
> Jan 17 13:38:16 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[157826]: pluralkit-db-dataLOG:
duration:2164.851 ms  execute _auto10: SELECT * FROM "members" WHERE "hid" = $1
 
> Jan 17 13:38:19 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[171076]: pluralkit-db-dataLOG:
duration:2039.040 ms  execute _auto3: SELECT * FROM "members" WHERE "hid" = $1
 
> Jan 17 13:38:20 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[162682]: pluralkit-db-dataLOG:
duration:2189.700 ms  execute _auto8: SELECT * FROM "members" WHERE "hid" = $1
 
> Jan 17 13:38:22 database-node1-bd9aa148 pzqzs8zyvqrq1rq25z4drws8dhnbxa59-run-postgres[159824]: pluralkit-db-dataLOG:
duration:2137.666 ms  execute _auto10: SELECT * FROM "members" WHERE "hid" = $1
 
> 
> Parameter detail has been redacted for privacy.
> 
> This is not reproducible on manual queries, whether using the same values or other random ones.
> 

Hi,

You may want to try auto_explain to try and catch the explain for one of
these queries. You should also consider things like a checkpoint or
other query that needs a lot of I/O or needs a lock on the affected
table that would delay your query. I have had a system where the
statistics changed the query to a sequential scan instead of an index
lookup. Then when they stats were updated the query went back to the
index. This just looks like normal multi-body problem fluctuations which
can be identified by using much more instrumentation and logging at all
layers: network, disk, db logs,... Good luck.

Regards,
Ken

"Lillian Berry" <lillian@star-ark.net> writes:
> Logs on our PostgreSQL cluster show frequent slow reads on a simple query by unique index.
> This issue has been present for some years, and survived multiple server moves as well as PostgreSQL version
upgrades.
> Vacuuming or reindexing the table does not seem to help.

What else is going on in that database?  The fact that you show
several different sessions suffering similar delays at almost the
same time seems suspicious to me.  I'm wondering if something is
taking an exclusive lock on that table and then sitting on it
for a second or two.

            regards, tom lane

Hi,

> You may want to try auto_explain to try and catch the explain for one of
> these queries.

I enabled auto_explain and it was very informative.

LOG:  duration: 2202.924 ms  execute <unnamed>: SELECT * FROM "members" WHERE "hid" = $1
LOG:  duration: 2202.918 ms  plan:
        Query Text: SELECT * FROM "members" WHERE "hid" = $1
        Query Parameters: $1 = '<redacted>'
        Gather  (cost=1000.00..907603.54 rows=67083 width=832) (actual time=1222.570..2202.893 rows=1.00 loops=1)
          Workers Planned: 2
          Workers Launched: 2
          Buffers: shared hit=816042
          ->  Parallel Seq Scan on members  (cost=0.00..899895.24 rows=27951 width=832) (actual time=1719.931..1972.703
rows=0.33loops=3)
 
                Filter: ((hid)::text = '<redacted>'::text)
                Rows Removed by Filter: 4463227
                Buffers: shared hit=816042

It's not using the indexes at all.

Since the query is clearly the same as I attempted earlier, why would it not be using the index?

This table gets reasonably frequent inserts, but the insert timestamps don't really match up with the slow queries (for
instance,there can be a 30-second gap where no rows are inserted, but there is still a slow query every few seconds).
Thetable gets infrequent deletes.
 

Most if not all activity on this table is only updating single rows, or deleting based on the "system" foreign key
column.
There is a job that calculates the count of rows (select count(*) from members), but it only runs once a minute and
takes1-2 seconds.
 

Kindly,
Lillian

On 17/1/26 14:58, Lillian Berry wrote:
> Logs on our PostgreSQL cluster show frequent slow reads on a simple query by unique index.
> 
> This issue has been present for some years, and survived multiple server moves as well as PostgreSQL version
upgrades.
> Vacuuming or reindexing the table does not seem to help.
Hmm, where is the evidence that your query uses theindex? Maybe the 
generic plan accidentally forces SeqScan?

-- 
regards, Andrei Lepikhov,
pgEdge

> Hmm, where is the evidence that your query uses theindex? Maybe the 
> generic plan accidentally forces SeqScan?

You may be correct - I just noticed that I am able to reproduce slow queries through my app. However, running the exact
samequeries in psql does use the index.
 

What might be different about my app's connections than psql? It uses Npgsql 9.0.2 on .NET 8, with these settings:

// src is "Host=[fdaa:9:e856:a7b:910f:0:a:102];Port=5432;Username=pluralkit;Database=pluralkit;Maximum Pool
Size=150;MinimumPool Size = 50;Max Auto Prepare=50"
 
var builder = new NpgsqlConnectionStringBuilder(src)
{
    Pooling = true,
    Enlist = false,
    NoResetOnClose = true,
    Timeout = 2
};

My understanding is slow query logs calculate the query time on the backend, and any client or network latency is not
counted.Is this correct?
 

Kindly,
Lillian

Andrei Lepikhov <lepihov@gmail.com> writes:
> Hmm, where is the evidence that your query uses theindex? Maybe the
> generic plan accidentally forces SeqScan?

Oh ... you're on to something.  I think we all assumed that this was
an intermittent problem, but if it happens every time, I bet it's a
datatype mismatch issue.  Observe:

postgres=# create table members(hid char(6) unique not null);
CREATE TABLE
postgres=# prepare p as select * from members where hid = '42';
PREPARE
postgres=# explain execute p;
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Only Scan using members_hid_key on members  (cost=0.15..8.17 rows=1 width=10)
   Index Cond: (hid = '42'::bpchar)
(2 rows)
postgres=# prepare p2(char) as select * from members where hid = $1;
PREPARE
postgres=# explain execute p2('42');
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Only Scan using members_hid_key on members  (cost=0.15..8.17 rows=1 width=10)
   Index Cond: (hid = '42'::bpchar)
(2 rows)
postgres=# prepare p3(text) as select * from members where hid = $1;
PREPARE
postgres=# explain execute p3('42');
                        QUERY PLAN
----------------------------------------------------------
 Seq Scan on members  (cost=0.00..42.10 rows=11 width=10)
   Filter: ((hid)::text = '42'::text)
(2 rows)

If the $1 parameter is declared to be type "text" then it wins the
tug-of-war over which equals operator is used, and text-equals-text
does not match the bpchar index.

If it's not convenient to alter whatever aspect of the client logic is
causing that parameter to be marked as text, you could force the issue
by putting a cast into the text of the statement:

postgres=# prepare p4(text) as select * from members where hid = $1::char(6);
PREPARE
postgres=# explain execute p4('42');
                                     QUERY PLAN
-------------------------------------------------------------------------------------
 Index Only Scan using members_hid_key on members  (cost=0.15..8.17 rows=1 width=10)
   Index Cond: (hid = '42    '::character(6))
(2 rows)

Or better yet, avoid using char(n).  It's a legacy type with no
real reason to exist, and it has semantic gotchas beyond this one.
varchar(n) is a much better idea.

            regards, tom lane

> I bet it's a datatype mismatch issue.

It was indeed!

I changed the query to `select * from members where hid = ($1)::char(6)` and this completely got rid of the slow
queries.

Thanks all!

Kindly,
Lillian

On 17/1/26 22:10, Tom Lane wrote:
> Andrei Lepikhov <lepihov@gmail.com> writes:
>> Hmm, where is the evidence that your query uses theindex? Maybe the
>> generic plan accidentally forces SeqScan?
> 
> Oh ... you're on to something.  I think we all assumed that this was
> an intermittent problem, but if it happens every time, I bet it's a
> datatype mismatch issue.
Yes, index mismatches due to type differences are frequently a pain for 
me in the world of auto-generated queries. Why not spend a few 
additional cycles to check whether a potential cast is possible?
I didn't track what happened in this example, but it would be beneficial 
to let an extension implement such functionality. The prosupport 
machinery attached to an index looks like a promising approach.

-- 
regards, Andrei Lepikhov,
pgEdge