tds_fdw binary column

[Aleš Zelený]

Hello,

I've an issue with foreign table using tds_fdw from PostgreSQL 10 to Sybase
ASE 15.7.

The issue is, that primary key, which I have to use for my predicate is in
Sybase data type binary.

Foreign table maps ID column from Sybase binary to PostgreSQL BYTEA.

Simple select is smooth:
[local]:5432 postgres@postgres:7650
=# select branch_id from ase.tds_tbl limit 1;
NOTICE:  tds_fdw: Query executed correctly
NOTICE:  tds_fdw: Getting results
┌┐
│ branch_id  │
├┤
│ \x000246000944242d │
└┘
(1 row)

Whereas select using the ID fails:

[local]:5432 postgres@postgres:7650
=# select * from ase. tds_tbl where branch_id =
E'\\x000246000944242d'::bytea;
ERROR:  DB-Library error: DB #: 102, DB Msg: General SQL Server error:
Check messages from the SQL Server, OS #: -1, OS Msg: , Level: 15
Time: 0.213 ms

Thanks for any hints.
Kind regards Ales Zeleny

Re: tds_fdw binary column

[Aleš Zelený]

Hello,

my fault, I've forgot to mention that I have only DSN and database
user/password credentials with no access to the box with Sybase. trying to
reach service vendor support,  but it might take some time and I hoped I've
done some mistake on my side...

Kind Regards
Ales Zeleny

st 10. 10. 2018 v 0:08 odesílatel Adrian Klaver 
napsal:

> On 10/9/18 12:07 PM, Aleš Zelený wrote:
> > Hello,
> >
> > I've an issue with foreign table using tds_fdw from PostgreSQL 10 to
> > Sybase ASE 15.7.
> >
> > The issue is, that primary key, which I have to use for my predicate is
> > in Sybase data type binary.
> >
> > Foreign table maps ID column from Sybase binary to PostgreSQL BYTEA.
> >
> > Simple select is smooth:
> > [local]:5432 postgres@postgres:7650
> > =# select branch_id from ase.tds_tbl limit 1;
> > NOTICE:  tds_fdw: Query executed correctly
> > NOTICE:  tds_fdw: Getting results
> > ┌┐
> > │ branch_id  │
> > ├┤
> > │ \x000246000944242d │
> > └┘
> > (1 row)
> >
> > Whereas select using the ID fails:
> >
> > [local]:5432 postgres@postgres:7650
> > =# select * from ase. tds_tbl where branch_id =
> > E'\\x000246000944242d'::bytea;
> > ERROR:  DB-Library error: DB #: 102, DB Msg: General SQL Server error:
> > Check messages from the SQL Server, OS #: -1, OS Msg: , Level: 15
>^^
> Have you done the above, look at the error log for the server?
>
> > Time: 0.213 ms
> >
> > Thanks for any hints.
>
>
> > Kind regards Ales Zeleny
>
>
> --
> Adrian Klaver
> adrian.kla...@aklaver.com
>

Re: tds_fdw binary column

[Aleš Zelený]

r 'E'.
Might be some issue with cast handling???

test_bytea_predicate_to_bytea)
[local]:5432 postgres@postgres:13550
=# select branch_id from ase.tds_tbl where branch_id = (select branch_id
from ase.tds_tbl where branch_id::text = '\x00038500875c3d60');
NOTICE:  DB-Library notice: Msg #: 5701, Msg state: 2, Msg: Changed
database context to 'customer'.
, Server: FMI0MA1, Process: , Line: 0, Level: 0
NOTICE:  DB-Library notice: Msg #: 5701, Msg state: 1, Msg: Changed
database context to 'vendor'.
, Server: FMI0MA1, Process: , Line: 1, Level: 0
NOTICE:  tds_fdw: Query executed correctly
NOTICE:  tds_fdw: Getting results
NOTICE:  DB-Library notice: Msg #: 5701, Msg state: 2, Msg: Changed
database context to 'customer'.
, Server: FMI0MA1, Process: , Line: 0, Level: 0
NOTICE:  DB-Library notice: Msg #: 5701, Msg state: 1, Msg: Changed
database context to 'vendor'.
, Server: FMI0MA1, Process: , Line: 1, Level: 0
NOTICE:  DB-Library notice: Msg #: 2715, Msg state: 1, Msg: Can't find type
'bytea'.
, Server: FMI0MA1, Process: , Line: 1, Level: 16
ERROR:  DB-Library error: DB #: 2715, DB Msg: General SQL Server error:
Check messages from the SQL Server, OS #: -1, OS Msg: , Level: 16
Time: 0.249 ms

The error is different, it looks tds_fdw is trying use bytea dat type fro
ASE query (guess).

That is what I was able to test.

Kind regards
Ales Zeleny

st 10. 10. 2018 v 15:30 odesílatel Adrian Klaver 
napsal:

> On 10/10/18 1:31 AM, Aleš Zelený wrote:
> > Hello,
> >
> > my fault, I've forgot to mention that I have only DSN and database
> > user/password credentials with no access to the box with Sybase. trying
> > to reach service vendor support,  but it might take some time and I
> > hoped I've done some mistake on my side...
>
> Hmm, some digging found this:
>
> https://github.com/tds-fdw/tds_fdw/issues/88
>
> If your credentials allow it you might try the suggestion in the above
> to see if you can get a more detailed error message.
>
> >
> > Kind Regards
> > Ales Zeleny
> >
>
> --
> Adrian Klaver
> adrian.kla...@aklaver.com
>

Wall shiping replica failed to recover database with error: invalid contrecord length 1956 at FED/38FFE208

[Aleš Zelený]

Hello,

we run out of disk space on our production primary database on file system
dedicated for WALs (one of our logical replica died and thus WALs were
accumulated).
As expeced, primary instance shuts down:


Primary instance:
PostgreSQL 11.3 (Ubuntu 11.3-1.pgdg18.04+1) on x86_64-pc-linux-gnu,
compiled by gcc (Ubuntu 7.4.0-1ubuntu1~18.04) 7.4.0, 64-bit

2019-09-29 19:24:28 UTC 2241 5d36488f.8c1 10[53100]:PANIC:  could
not write to file "pg_wal/xlogtemp.2241": No space left on device
2019-09-29 19:24:30 UTC 1706 5d364871.6aa 33870[0]:LOG:  WAL
writer process (PID 2241) was terminated by signal 6: Aborted
2019-09-29 19:24:30 UTC 1706 5d364871.6aa 33880[0]:LOG:
 terminating any other active server processes

2019-09-29 19:24:30 UTC 1706 5d364871.6aa 33900[0]:LOG:  all
server processes terminated; reinitializing
2019-09-29 19:24:30 UTC 21499 5d9104ee.53fb 10[0]:LOG:
 database system was interrupted; last known up at 2019-09-29 19:23:47 UTC

2019-09-29 19:24:33 UTC 21499 5d9104ee.53fb 20[0]:LOG:
 recovered replication state of node 1 to CF3/442D0758
2019-09-29 19:24:33 UTC 21499 5d9104ee.53fb 30[0]:LOG:
 database system was not properly shut down; automatic recovery in progress
2019-09-29 19:24:33 UTC 21499 5d9104ee.53fb 40[0]:LOG:  redo
starts at FE9/A49830D8

2019-09-29 19:25:55 UTC 21499 5d9104ee.53fb 50[0]:LOG:  redo
done at FED/38FFC540
2019-09-29 19:25:55 UTC 21499 5d9104ee.53fb 60[0]:LOG:  last
completed transaction was at log time 2019-09-29 19:22:06.597333+00
2019-09-29 19:25:55 UTC 21499 5d9104ee.53fb 70[0]:LOG:
 checkpoint starting: end-of-recovery immediate

2019-09-29 19:26:59 UTC 21499 5d9104ee.53fb 80[0]:LOG:
 checkpoint complete: wrote 1046940 buffers (99.8%); 0 WAL file(s) added, 0
removed, 0 recycled; write=64.166 s, sync=0.008 s, total=64.212 s; sync
files=184, longest=0.001 s, average=0.000 s; distance=15014380 kB,
estimate=15014380 kB
2019-09-29 19:26:59 UTC 21499 5d9104ee.53fb 90[53100]:FATAL:  could
not write to file "pg_wal/xlogtemp.21499": No space left on device
2019-09-29 19:26:59 UTC 1706 5d364871.6aa 33910[0]:LOG:
 startup process (PID 21499) exited with exit code 1
2019-09-29 19:26:59 UTC 1706 5d364871.6aa 33920[0]:LOG:
 aborting startup due to startup process failure
2019-09-29 19:26:59 UTC 1706 5d364871.6aa 33930[0]:LOG:
 database system is shut down

Expceted bahavior, free space on file system for WAL was 14MB, so not
enough for next WAL file to be saved.

Once falied logical replica was back up & running, we have extened
filesystem for WALs and started primary instance:

2019-09-30 08:21:44 UTC 13635 5d91bb18.3543 10[0]:LOG:  Auto
detecting pg_stat_kcache.linux_hz parameter...
2019-09-30 08:21:44 UTC 13635 5d91bb18.3543 20[0]:LOG:
 pg_stat_kcache.linux_hz is set to 100
2019-09-30 08:21:44 UTC 13635 5d91bb18.3543 30[0]:LOG:
 listening on IPv4 address "0.0.0.0", port 5432
2019-09-30 08:21:44 UTC 13635 5d91bb18.3543 40[0]:LOG:
 listening on IPv6 address "::", port 5432
2019-09-30 08:21:44 UTC 13635 5d91bb18.3543 50[0]:LOG:
 listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2019-09-30 08:21:44 UTC 13637 5d91bb18.3545 10[0]:LOG:
 database system was shut down at 2019-09-29 19:26:59 UTC
2019-09-30 08:21:44 UTC 13637 5d91bb18.3545 20[0]:LOG:
 recovered replication state of node 1 to CF3/442D0758
2019-09-30 08:21:44 UTC 13646 5d91bb18.354e 10[0]:LOG:
 pg_partman master background worker master process initialized with role
postgres
2019-09-30 08:21:44 UTC 13635 5d91bb18.3543 60[0]:LOG:
 database system is ready to accept connections
2019-09-30 08:21:44 UTC 13645 5d91bb18.354d 10 2/0   [0]:LOG:
 pg_cron scheduler started
2019-09-30 08:21:44 UTC 13647 5d91bb18.354f 10 3/0   [0]:LOG:  POWA
connected to database powa

So primary instance stated, all logical replications streams connected and
as soon as logical replication for failed subscriber process WALs,
unnecessery WALs were deleted as expected. Until this point, all works like
a charm  from primary instance point of view.


Form this primary instance we are running wall shipping replica (pgBackRest
is used) and this is where issues started.

WAL recovery replica:
PostgreSQL 11.3 (Ubuntu 11.3-1.pgdg18.04+1) on x86_64-pc-linux-gnu,
compiled by gcc (Ubuntu 7.4.0-1ubuntu1~18.04) 7.4.0, 64-bit

WAL files were restored from backup till last one backed up before primary
instance shut down.

2019-09-29 19:24:31.390 P00   INFO: found 00010FED0037 in the
archive
2019-09-29 19:24:31.391 P00   INFO: archive-get command end: completed
successfully (43ms)
2019-09-29 19:24:31 UTC 3062 5d76145f.bf6 1810120 1/0   [0]:LOG:
 restored log file "00010FED0037" from archive
2019-09-29 19:24:31.919 P00   IN

Re: Wall shiping replica failed to recover database with error: invalid contrecord length 1956 at FED/38FFE208

[Aleš Zelený]

Hello,

čt 3. 10. 2019 v 0:09 odesílatel Stephen Frost  napsal:

> Greetings,
>
> * Aleš Zelený (zeleny.a...@gmail.com) wrote:
> > But recovery on replica failed to proceed WAL file
> > 00010FED0039  with log message: " invalid contrecord length
> > 1956 at FED/38FFE208".
>
> Err- you've drawn the wrong conclusion from that message (and you're
> certainly not alone- it's a terrible message and we should really have a
> HINT there or something).  That's an INFO-level message, not an error,
> and basically just means "oh, look, there's an invalid WAL record, guess
> we got to the end of the WAL available from this source."  If you had
> had primary_conninfo configured in your recovery.conf, PG would likely
> have connected to the primary and started replication.  One other point
> is that if you actually did a promotion in this process somewhere, then
> you might want to set recovery_target_timeline=latest, to make sure the
> replica follows along on the timeline switch that happens when a
> promotion happens.
>
> Thanks (for all comments form others as well) for this explanation. I've
failed to describe properly our case. We are recovering  the replica
instance from WALs only, since the replica is in separate network (used as
source for zfs clonning for development), so there is no primary_conninfo
(replica can't influence primary instance any way, it juts consumes primary
instance WALs) and we did not performed replica promotion.

I'd guess, thath on out of disk space issue, last WAL might be incomplete,
but the size was expected 16777216 Bytes on primary instance disk and it
was binary identical to file restores on replica from backup. The issue
wsas, that replica emit this INFO message, but it was not able to move to
next wal file and started falling behind primary instance.

If the WAL was incomplete during out of space it probably might be
appeneded during instance start ( but I'll doubt incomplete archive_command
to be invoced on incomplete WAL), that is why I have checked the file on
primary (after it was back up&running) with restored one on replica
instance.

In orther words, if this log message will be emmited only once and recovery
continue retoring subsequent WALs, I'll be OK with that, but due to
recovery stucked at this WAL I'm in doubts whether I did something wrong
(e.g. improper recovery.conf ...) or what is possible workaround to enable
replica (if possible) proceed this wal and continue with recovery. The
database size is almost 2 TB, so that is why I'd like to avoid full
restores to create DEV environments and using ZFS clones instead.

Thanks for any hints how to let replica continue applying WAL files.

Kind regards Ales Zeleny

Logical replication issue

[Aleš Zelený]

Hello,

we are using logical replication from  PostgreSQL 10.8 (Ubuntu
10.8-1.pgdg14.04+1)  to PostgreSQL 11.3 (Ubuntu 11.3-1.pgdg18.04+1). Thre
are 1305 replicated tables within 3 schemas. The tables are from small
almost static lookup tables to larger tables up to ~40GB holding 44
millions of rows. In production, the replication works like a charm.

But we are experiencing an issue when we create clones of production
databases to the development environment. Development is in a separated
network, loaded from a testing data feed therefore development publisher
database contains data in almost identical volumes and the same structure,
but it is being continuously updated from the testing data feed.

To let all test work properly, replicated tables are truncated after
subscriber database is cloned to the development environment (all restored
subscriptions are dropped) and a new subscription to development publisher
database is created with copy_data =  true option to ensure data
consistency.

Such an approach works well for more than a year using 2 of the present 3
schemas (most of the above-mentioned table count is in the long-used two
schemas). While we have added the third schema with only 7 tables from 35
MB to 40 GB in size, we are experiencing an initial synchronization issue.
The total volume of the three schemas is several hundreds of GB, so the
initial table synchronization lasts usually for several hours.
surprisingly, all of the 7 tables in the third schema, despite their size
or row count fail due to primary key violation, like - duplicate key value
violates unique constraint "party_pkey".
Such behavior makes me very surprised - based on the docs:
https://www.postgresql.org/docs/11/logical-replication-architecture.html,

31.5.1. Initial Snapshot, I expect that after some time necessary for the
table copy and afterward applied changes from WAL, there can't be a chance
for duplicate rows, since both the publisher and the subscriber are using
the same primary key as replica identity.

LOG:  logical replication table synchronization worker for subscription
"sub_anl_dsos_usd", table "party" has started
ERROR:  duplicate key value violates unique constraint "party_pkey"
DETAIL:  Key (party_id)=(\x0003dd00131add0a) already exists.
CONTEXT:  COPY party, line 1

If, once this happens (the table was truncated before the subscription was
created) I truncate the table on the subscriber, copy succeeded and from
that moment replication works like a charm. I'm not aware of using
replication different way then than for the two schemas we stared with and
for them, the synchronization including the application of changes
subsequent to subscription creation works without any issues.

Thanks for any hints on how to diagnose this issue, I can't find where I
did a mistake and I did not expect that this might be related to higher
change rate on publisher tables than the other tables.

Ales

Logical replication - ERROR: could not send data to WAL stream: cannot allocate memory for input buffer

[Aleš Zelený]

Hello,

we are using logical replication for more than 2 years and today I've found
new not yet know error message from wal receiver. The replication was in
catchup mode (on publisher side some new tables were created and added to
publication, on subscriber side they were missing).

RDBMS version:PostgreSQL 11.4 (Ubuntu 11.4-1.pgdg18.04+1) on
x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 7.4.0-1ubuntu1~18.04.1) 7.4.0,
64-bit
OS: Ubuntu 18.04.2 LTS

RDBMS was installed from pgdg packages.

The error message:
2020-06-05 20:00:08 UTC 19753 5edaa378.4d29 20 540/1132087
[XX000]:ERROR:  could not send data to WAL stream: cannot allocate memory
for input buffer
2020-06-05 20:00:08 UTC 867 5df8a0b4.363 286130[0]:LOG:
 background worker "logical replication worker" (PID 19753) exited with
exit code 1

Repeated several times, finally it proceeded and switch into streaming
state. The OS has 64GB RAM, OS + database instance are using usually 20GB
rest is used as OS buffers. I've checked monitoring (sampled every 10
seconds) and no memory usage peak was visible, so unless it was a very
short memory usage peak, I'd not expect the system running out of memory.

Is there something I can do to diagnose and avoid this issue?

Thanks Ales

Re: Logical replication - ERROR: could not send data to WAL stream: cannot allocate memory for input buffer

[Aleš Zelený]

Thanks for the comment.

from what I was able to monitor memory usage was almost stable and there
were about 20GB allocated as cached memory. Memory overcommit is disabled
on the database server. Might it be a memory issue, since wit was
synchronizing newly added tables with a sum of 380 GB of data containing
JSONB columns (60 bytes to 100kBytes). The problem is, that I was not able
to reproduce it since in dev environment it wors like a charm an as usual
on PROD we were facing this issue.

It is clear that for memory allocation issues testcase would be
appropriate, but I was not able to build reproducible testcase.

Thanks Ales

po 8. 6. 2020 v 8:41 odesílatel Michael Paquier 
napsal:

> On Fri, Jun 05, 2020 at 10:57:46PM +0200, Aleš Zelený wrote:
> > we are using logical replication for more than 2 years and today I've
> found
> > new not yet know error message from wal receiver. The replication was in
> > catchup mode (on publisher side some new tables were created and added to
> > publication, on subscriber side they were missing).
>
> This comes from pqCheckInBufferSpace() in libpq when realloc() fails,
> most probably because this host ran out of memory.
>
> > Repeated several times, finally it proceeded and switch into streaming
> > state. The OS has 64GB RAM, OS + database instance are using usually 20GB
> > rest is used as OS buffers. I've checked monitoring (sampled every 10
> > seconds) and no memory usage peak was visible, so unless it was a very
> > short memory usage peak, I'd not expect the system running out of memory.
> >
> > Is there something I can do to diagnose and avoid this issue?
>
> Does the memory usage increase slowly over time?  Perhaps it was not a
> peak and the memory usage was not steady?  One thing that could always
> be tried if you are able to get a rather reproducible case would be to
> use valgrind and check if it is able to detect any leaks.  And I am
> afraid that it is hard to act on this report without more information.
> --
> Michael
>

Database cluster binary compatibility accross CPU platforms

[Aleš Zelený]

Hello,

is it supported to restore binary backup (pg_basebackup) taken on an amd64
platform on arm64 while using the same PostgreSQL version?

I'd like to know, whether there is binary file compatibility to save time
needed for dump & restore migration scenario or all the complexity of using
logical replication to migrate databases already utilizing logical
replication.

Kind regards Ales Zeleny

Re: Database cluster binary compatibility accross CPU platforms

[Aleš Zelený]

Thanks for the explanation!
We are still not using ICU, so the reindex (endians - based on what I've
found about Graviton ARM64 cpu are same, but no information about datatype
alignment) will be a pain, so if we really opt for the platform we can give
it a try, but generally I'll expect restoring database from pg_dump taken
backup.

Kind regards Ales Zeleny

čt 27. 8. 2020 v 1:33 odesílatel Tom Lane  napsal:

> =?UTF-8?B?QWxlxaEgWmVsZW7DvQ==?=  writes:
> > is it supported to restore binary backup (pg_basebackup) taken on an
> amd64
> > platform on arm64 while using the same PostgreSQL version?
>
> I wouldn't say it's "supported", but you might get away with it,
> if the endianness and datatype alignment rules are the same.
> The database does do some basic checks on that using known values
> stored in the pg_control file, so it's likely you'd find out
> immediately at startup if any of those things don't match.
>
> What's significantly more risky, and which we do *not* have good
> checks for, is that unless these are different builds of the same
> version of the same operating system, the two platforms may not sort
> strings the same way; resulting in all your text indexes being
> corrupt.  You can recover from that by reindexing, but it's hardly
> a painless transition.
>
> regards, tom lane
>

LISTEN - ERROR: could not access status of transaction 3021015672

[Aleš Zelený]

Hello,

I've found in our server ( PostgreSQL 13.5 on x86_64-pc-linux-gnu, compiled
by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit ) following error:

2022-03-31 09:29:58 CEST [15490]: [1-1]
user=app,db=main,host=192.168.1.231,app=[unknown] ERROR:  could not access
status of transaction 3021015672
2022-03-31 09:29:58 CEST [15490]: [2-1]
user=app,db=main,host=192.168.1.231,app=[unknown] DETAIL:  Could not open
file "pg_xact/0B41": Adresář nebo soubor neexistuje.
2022-03-31 09:29:58 CEST [15490]: [3-1]
user=app,db=main,host=192.168.1.231,app=[unknown] STATEMENT:  LISTEN
"CONFIG"

Since we have enabled track_commit_timestamp, I' tried:
prematch=# show track_commit_timestamp ;
 track_commit_timestamp

 on
(1 row)


prematch=# select * from pg_xact_commit_timestamp('3021015672');
 pg_xact_commit_timestamp
--

(1 row)

Since this was not helpful, searching in the archives, I've found the
thread:

"BUG #16961: Could not access status of transaction"
https://www.postgresql.org/message-id/flat/VE1PR03MB531295B1BDCFE422441B15FD92499%40VE1PR03MB5312.eurprd03.prod.outlook.com#7e36d1fdca921b5292e92c7017984ffa

But it looks not to have any result.
Unfortunately, I have no isolated test case, so I'd like to ask for advice
on what set of information to collect if it happened next time, to be able
to supply some valuable bug reports.
If it is a known configuration issue or an application logic issue, any
advice is welcome (the scenario described in the abovementioned thread is
not our application case).

Thanks, Ales

Pg14 possible index corruption after reindex concurrently

[Aleš Zelený]

Hello,

we have a problem with an index on a database we recently upgraded from
PG13 to Pg14.3 using pg_upgrade. After all the upgrade steps including
analyze in stages, we run  "vacuumdb -Fvaz -j 8" and the user workload was
started afterward.
In order to get one of the Pg14 benefits (b-tree deduplication), we decided
to rebuild all indexes:

-- CONCURRENTLY can not be used for REINDEX DATABASE and system catalog was
brand new on the upgraded database, so no need to reindex system.
SELECT format('REINDEX SCHEMA CONCURRENTLY %I;', n.nspname)
FROM pg_catalog.pg_namespace n
WHERE n.nspname !~ '^pg_' AND n.nspname <> 'information_schema'
ORDER BY 1;
\gexec


PG Version: PostgreSQL 14.3 on x86_64-pc-linux-gnu, compiled by gcc (GCC)
4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit
OS: CentOS 7
Indexed columns are BIGINT (so no collation issues).

A few days later we realized, that some queries did not return the expected
data. By disabling indexscan and bitmapindex scan, expected row was found
using sequential scan.

Now we have a table (80GB, 314.108.951 rows) with a reproducible testcase
to demonstrate that using the primary key, requested data are returned
while using another index no rows are returned.

Testcase:

START TRANSACTION;
EXPLAIN ANALYZE SELECT * FROM opportunities.tab_odds WHERE id_odds =
1652734429;
  QUERY PLAN

--
 Index Scan using pk_tabodds_idodds on tab_odds  (cost=0.57..2.59 rows=1
width=229) (actual time=0.076..0.078 rows=1 loops=1)
   Index Cond: (id_odds = 1652734429)
 Planning Time: 0.152 ms
 Execution Time: 0.119 ms
(4 rows)

ALTER TABLE opportunities.tab_odds DROP CONSTRAINT pk_tabodds_idodds
CASCADE;

EXPLAIN ANALYZE SELECT * FROM opportunities.tab_odds WHERE id_odds =
1652734429;
 QUERY PLAN


 Index Scan using ix_tabodds_idodds_idopportunity on tab_odds
 (cost=0.57..2.59 rows=1 width=229) (actual time=0.026..0.027 rows=0
loops=1)
   Index Cond: (id_odds = 1652734429)
 Planning Time: 0.248 ms
 Execution Time: 0.072 ms
(4 rows)

ROLLBACK;

The indexes are:
Indexes:
"pk_tabodds_idodds" PRIMARY KEY, btree (id_odds)
"ix_tabodds_idodds_idopportunity" btree (id_odds, id_opportunity)

While we can do another reindex and check query results, we would like to
be able to identify such issues systematically rather than by en user
complaints.

I've tried to use amcheck extension to validate the index:

select * from
bt_index_check('opportunities.ix_tabodds_idodds_idopportunity'::regclass);
 bt_index_check


(1 row)

Running the pg_amcheck utility on the table (including its indexes):

/usr/pgsql-14/bin/pg_amcheck -d prematch -r opportunities.tab_odds -j 8 -P
; echo $?
heap table "prematch.opportunities.tab_odds", block 1579813, offset 62:
xmax 4051057343 precedes relation freeze threshold 2:3960858664
heap table "prematch.opportunities.tab_odds", block 1580759, offset 43:
xmin 4051053353 precedes relation freeze threshold 2:3960858664

heap table "prematch.opportunities.tab_odds", block 2164163, offset 5:
xmin 4051075211 precedes relation freeze threshold 2:3960858664
heap table "prematch.opportunities.tab_odds", block 2164163, offset 6:
xmin 4051075236 precedes relation freeze threshold 2:3960858664
heap table "prematch.opportunities.tab_odds", block 2164163, offset 7:
xmin 4051075236 precedes relation freeze threshold 2:3960858664
heap table "prematch.opportunities.tab_odds", block 2164164, offset 1:
xmin 4051075260 precedes relation freeze threshold 2:3960858664
2

The default access method check returns exit code2, while when using
--rootdescend option  return code is zero and no xmin/xmax messages:

/usr/pgsql-14/bin/pg_amcheck -d prematch -r opportunities.tab_odds
--rootdescend -j 8 -P ; echo $?

 0/15 relations (0%),0/16831435 pages (0%)
 9/15 relations (60%), 16831427/16831435 pages (99%)
10/15 relations (66%), 16831429/16831435 pages (99%)
11/15 relations (73%), 16831431/16831435 pages (99%)
12/15 relations (80%), 16831433/16831435 pages (99%)
13/15 relations (86%), 16831434/16831435 pages (99%)
14/15 relations (93%), 16831435/16831435 pages (100%)
15/15 relations (100%), 16831435/16831435 pages (100%)
0

I've thought about using pageinspect to dump the invalid index page, but
haven't found a way how to identify the index block number.

Is there a way, how to diagnose such corruption to make sure that after
(and ideally also before) upgrading the database no such corruption
happened (I'd like to test the diagnostic approach before rebuilding the
index)?

Unfortunately, the cluster was so old, and planned outage was limited -
page checksums were not enable

Re: Pg14 possible index corruption after reindex concurrently

[Aleš Zelený]

Thanks for the bug link, I haven't found it.

Ales

út 24. 5. 2022 v 21:58 odesílatel Thomas Munro 
napsal:

> On Wed, May 25, 2022 at 6:17 AM Aleš Zelený  wrote:
> > SELECT format('REINDEX SCHEMA CONCURRENTLY %I;', n.nspname)
>
> This may be related to bug #17485, discussed at:
>
>
> https://www.postgresql.org/message-id/flat/17485-396609c6925b982d%40postgresql.org
>

Re: Pg14 possible index corruption after reindex concurrently

[Aleš Zelený]

Hello,

you are right it looks to be related, on our running system with connected
users such an issue happens not only on primary keys but also on other
(non-unique) indexes.

I've checked all indexes using amcheck:

select * from bt_index_check(index =>
'prematch.opportunities.pk_tabodds_idodds'::regclass::oid, heapallindexed
=> true);

Failed one rebuild and check again to ensure all things are OK.

Still have a problem and haven't found any explanation in the manuals:

Run amcheck to validate a table and its indexes:

/usr/pgsql-14/bin/pg_amcheck -d prematch -r opportunities.tab_odds
--heapallindexed -j 16 -Pv ; echo $?
...
btree index "prematch.opportunities.pk_tabodds_idodds":
ERROR:  heap tuple (2199116,5) from table "tab_odds" lacks matching
index tuple within index "pk_tabodds_idodds"
HINT:  Retrying verification using the function bt_index_parent_check()
might provide a more specific error.
2


OK, rebuild the index (first give it a try to use the concurrently option):
prematch=# REINDEX INDEX CONCURRENTLY
prematch.opportunities.pk_tabodds_idodds;

REINDEX
prematch=#
prematch=# select * from bt_index_check(index =>
'prematch.opportunities.pk_tabodds_idodds'::regclass::oid, heapallindexed
=> true);


 bt_index_check


(1 row)

Looks we were lucky.

Just to be sure, one more check from the command line:

/usr/pgsql-14/bin/pg_amcheck -d prematch -r opportunities.tab_odds
--heapallindexed -j 16 -P ; echo $?
 0/15 relations (0%),0/16807950 pages (0%)
heap table "prematch.opportunities.tab_odds", block 1649057, offset 47:
xmin 4062380236 precedes relation freeze threshold 2:3960858664
heap table "prematch.opportunities.tab_odds", block 1649057, offset 48:
xmax 4062380236 precedes relation freeze threshold 2:3960858664
...
xmax 4062380813 precedes relation freeze threshold 2:3960858664
heap table "prematch.opportunities.tab_odds", block 2210728, offset 8:
xmax 4062380814 precedes relation freeze threshold 2:3960858664
2

So I got non-zero exit code, but no errors in the log file:

-bash-4.2$ grep -i ERROR 20220525_1710_prematch.opportunities.tab_odds.log
-bash-4.2$

We have multiple DB servers upgraded to 14, only a few amchecks:

( time /usr/pgsql-14/bin/pg_amcheck -a --heapallindexed -j 16 -P ; echo $?
) |& tee -a `date +%Y%m%d_%H%M`_`hostname`_amcheck.log

finished with zero exit code, most of them returned 2, within the xmin/xmax
messages as shown above. Is that an issue (since missing entries in the
index cause ERRRO reported in the log, but after rebuilding the indexes it
was not the case anymore)?
If it is an issue, is there a way to fix it?

Thanks Ales

út 24. 5. 2022 v 21:58 odesílatel Thomas Munro 
napsal:

> On Wed, May 25, 2022 at 6:17 AM Aleš Zelený  wrote:
> > SELECT format('REINDEX SCHEMA CONCURRENTLY %I;', n.nspname)
>
> This may be related to bug #17485, discussed at:
>
>
> https://www.postgresql.org/message-id/flat/17485-396609c6925b982d%40postgresql.org
>

pg_amcheck warnings after upgrade to 14.4

[Aleš Zelený]

Hello,

we have suffered from BUG #17485, so we have upgraded our databases to 14.4.

When (on 14.3 we discovered the issue all affected indexes were rebuilt
[not concurrently]), so subsequent pg_amcheck --heapallindexed was without
errors or warnings.

After the upgrade to 14.4, we run pg_amcheck --heapallindexed again to
ensure all indexes are in a good shape, and on some databases, pg_amcheck
yields some messages (supposed to be wanings since pg_amcheck exit code was
zero).

On some tables, running vacuum freeze resolved all of the warning messages,
but we have at least one table where vacuum freeze (have no chance to run
vacuum full to completely rewrite the table) did not resolve the warnings.

Table vacuum:
live=# VACUUM (DISABLE_PAGE_SKIPPING, VERBOSE)
live.live_opportunities.tab_odds_history;
INFO:  aggressively vacuuming "live_opportunities.tab_odds_history"
INFO:  table "tab_odds_history": index scan bypassed: 50245 pages from
table (0.20% of total) have 3361027 dead item identifiers
INFO:  launched 1 parallel vacuum worker for index cleanup (planned: 1)
INFO:  table "tab_odds_history": found 0 removable, 583340008 nonremovable
row versions in 25325175 out of 25325175 pages
DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 4076779300
Skipped 0 pages due to buffer pins, 0 frozen pages.
CPU: user: 81.77 s, system: 122.32 s, elapsed: 243.07 s.
INFO:  aggressively vacuuming "pg_toast.pg_toast_18089"
INFO:  table "pg_toast_18089": found 0 removable, 0 nonremovable row
versions in 0 out of 0 pages
DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 4076806500
Skipped 0 pages due to buffer pins, 0 frozen pages.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
VACUUM

pg_amcheck warnings:
$ /usr/pgsql-14/bin/pg_amcheck --heapallindexed -t
live.live_opportunities.tab_odds_history -P |& tee -a
20220630_amcheck.03.log
0/5 relations (0%),0/2770 pages (0%)
heap table "live.live_opportunities.tab_odds_history", block 2955073,
offset 48:
xmin 4075979939 precedes relation freeze threshold 1:4075978425
...
heap table "live.live_opportunities.tab_odds_history", block 2955076,
offset 27:
xmin 4075980540 precedes relation freeze threshold 1:4075978425

Checked the XIDs:
live=# select relfrozenxid, relminmxid from pg_class where oid =
'live_opportunities.tab_odds_history'::regclass::oid;
 relfrozenxid | relminmxid
--+
   4075978425 | 1144161405
(1 row)

live=# select now(), pg_xact_commit_timestamp('4075978425'::xid) AS
relfrozenxid_time, pg_xact_commit_timestamp('4075979939'::xid) as
block_2955073_xmin;
  now  |   relfrozenxid_time   |
 block_2955073_xmin
---+---+---
 2022-06-30 11:57:42.800162+02 | 2022-06-30 11:33:00.729004+02 | 2022-06-30
11:33:57.208792+02
(1 row)

live=# select now(), pg_xact_commit_timestamp('4075978425'::xid) AS
relfrozenxid_time, pg_xact_commit_timestamp('4075980540'::xid) as
block_2955076_xmin;
 now  |   relfrozenxid_time   |
 block_2955076_xmin
--+---+---
 2022-06-30 11:53:39.05382+02 | 2022-06-30 11:33:00.729004+02 | 2022-06-30
11:34:28.281048+02
(1 row)

The table relfrozenxid is less than the tuple xmin reported by pg_amcheck,
that makes me confused by the pg_amcheck messages - so probably I did not
understand the warning message properly.

What is the meaning of the warning (if they are really only warnings)
message?

The key question is - are these pg_amcheck messages listed above a reason
to take an remedy action (if yes, what is the suggested action?) or they
can be safely ignored?

Thanks Ales Zeleny

PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Hello,

we are experiencing out-of-memory issues after Postygres upgrade from 14.3
to 14.4 on CentOS7.

OS: CenotOS7

No OOM killer messages in the syslog. SWAP is disabled.

-bash-4.2$ sysctl -q vm.overcommit_memory
vm.overcommit_memory = 2

[root@sts-uat-pgsql100 ~]# swapon -vs
[root@sts-uat-pgsql100 ~]#

[root@sts-uat-pgsql100 ~]# sysctl -q vm.overcommit_ratio
vm.overcommit_ratio = 95


-bash-4.2$ uname -r
3.10.0-1160.42.2.el7.x86_64

-bash-4.2$ free -h
  totalusedfree  shared  buff/cache
available
Mem:39G7,8G220M 10G 31G
20G
Swap:0B  0B  0B



postgres=# show shared_buffers ;
 shared_buffers

 10GB
(1 row)

postgres=# show  work_mem ;
 work_mem
--
 4MB
(1 row)

postgres=# show maintenance_work_mem ;
 maintenance_work_mem
--
 512MB
(1 row)

postgres=# show max_parallel_workers;
 max_parallel_workers
--
 8
(1 row)

postgres=# show max_parallel_maintenance_workers ;
 max_parallel_maintenance_workers
--
 2
(1 row)

postgres=# select count(*) from pg_stat_activity ;
 count
---
93
(1 row)

postgres=# show max_connections ;
 max_connections
-
 1000
(1 row)

No changes on the application side were made before the out-of-memory
happened.



So far, it has happened three times (during a single week) from the 14.3 ->
14.4 upgrade, before 14.4 we haven't suffered from such an issue.

Questions:
1)  Can we safely downgrade from 14.4 to 14.3 by shutting down the instance
and reinstalling 14.3 PG packages (to prove, that the issue disappear)?
2) What is the best way to diagnose what is the root cause?

What we have started to collect:
- vmstat -nwt (per second)
- vmstat -nawt (per second)

~onece a minute
df  for /dev/shm
/proc/meminfo
proc//stat for all PG processes
proc//cmdline for all PG processes
proc//status for all PG processes
proc//smaps for all PG processes
list from pg_stat_activcity
pmap -x for all PG processes
ps aux listing
smem -u --abbreviate
smem -m --abbreviate
smem -w -k

Except the "pmpap" all of the metrics were already collected before the
last out of meory issue.


Error messages:
--
postgresql-Fri.log:2022-07-01 06:49:53 CEST [4476]: [20-1]
user=,db=,host=,app= LOG:  could not fork worker process: Cannot allocate
memory
postgresql-Fri.log:2022-07-01 06:49:53 CEST [4476]: [21-1]
user=,db=,host=,app= LOG:  could not fork worker process: Cannot allocate
memory
postgresql-Fri.log:2022-07-01 06:50:02 CEST [4476]: [22-1]
user=,db=,host=,app= LOG:  could not fork new process for connection:
Cannot allocate memory
postgresql-Fri.log:2022-07-01 06:50:02 CEST [4476]: [23-1]
user=,db=,host=,app= LOG:  could not fork new process for connection:
Cannot allocate memory
postgresql-Fri.log:2022-07-01 06:50:02 CEST [4476]: [24-1]
user=,db=,host=,app= LOG:  could not fork new process for connection:
Cannot allocate memory
...
2022-07-02 14:48:07 CEST [3930]: [2-1] user=,db=,host=,app= LOG:  automatic
vacuum of table "prematch.monitoring.tab_replication_clock": index scans: 0
pages: 0 removed, 36 remain, 0 skipped due to pins, 34 skipped
frozen
tuples: 0 removed, 203 remain, 201 are dead but not yet removable,
oldest xmin: 269822444
index scan not needed: 0 pages from table (0.00% of total) had 0
dead item identifiers removed
I/O timings: read: 0.000 ms, write: 0.000 ms
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
buffer usage: 67 hits, 0 misses, 0 dirtied
WAL usage: 1 records, 0 full page images, 245 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
TopMemoryContext: 279360 total in 10 blocks; 15384 free (9 chunks); 263976
used
  TopTransactionContext: 8192 total in 1 blocks; 7280 free (12 chunks); 912
used
  TOAST to main relid map: 65536 total in 4 blocks; 35168 free (15 chunks);
30368 used
  AV worker: 16384 total in 2 blocks; 10080 free (10 chunks); 6304 used
Autovacuum Portal: 8192 total in 1 blocks; 7720 free (0 chunks); 472
used
  Vacuum: 8192 total in 1 blocks; 7768 free (0 chunks); 424 used
  Operator class cache: 8192 total in 1 blocks; 552 free (0 chunks); 7640
used
  smgr relation table: 16384 total in 2 blocks; 4592 free (2 chunks); 11792
used
  pgstat TabStatusArray lookup hash table: 8192 total in 1 blocks; 1448
free (0 chunks); 6744 used
  TransactionAbortContext: 32768 total in 1 blocks; 32504 free (0 chunks);
264 used
  Portal hash: 8192 total in 1 blocks; 552 free (0 chunks); 7640 used
  TopPortalContext: 8192 total in 1 blocks; 7928 free (0 chunks); 264 used
  Relcache by OID: 16384 total in 2 blocks; 3504 free (2 chunks); 12880 used
  CacheMemoryContext: 524288 total in 7 blocks; 123552 free (4 chunks);
400736 used
index info: 1024 total in 1 blocks; 0 free (0 chunks); 1024 used:
tab_queue_tmp_pkey
index info: 2048 total in 2 blocks; 952 free 

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Hello,

po 11. 7. 2022 v 14:47 odesílatel Pavel Stehule 
napsal:

> Hi
>
> It's looks like memory leak
>

As we are collecting some data for Postgres processes, I've found processes
using Rss Anonymous memory allocations:

Some examples:
2022-07-08T14:50:24+0200 Name: postmaster Pid: 31522 RssAnon:  742600 kB
2022-07-08T14:51:13+0200 Name: postmaster Pid: 31522 RssAnon:  742600 kB
2022-07-08T14:52:05+0200 Name: postmaster Pid: 31522 RssAnon:  742852 kB
2022-07-08T14:52:58+0200 Name: postmaster Pid: 31522 RssAnon:  743112 kB
2022-07-08T14:53:50+0200 Name: postmaster Pid: 31522 RssAnon:  743112 kB
2022-07-08T14:50:24+0200 Name: postmaster Pid: 31647 RssAnon:  684632 kB
2022-07-08T14:51:13+0200 Name: postmaster Pid: 31647 RssAnon:  684632 kB
2022-07-08T14:52:05+0200 Name: postmaster Pid: 31647 RssAnon:  684676 kB
2022-07-08T14:52:58+0200 Name: postmaster Pid: 31647 RssAnon:  684700 kB
2022-07-08T14:53:50+0200 Name: postmaster Pid: 31647 RssAnon:  684824 kB
2022-07-08T14:50:27+0200 Name: postmaster Pid: 7866 RssAnon: 1180960 kB
2022-07-08T14:51:16+0200 Name: postmaster Pid: 7866 RssAnon: 1180960 kB
2022-07-08T14:52:08+0200 Name: postmaster Pid: 7866 RssAnon: 1180960 kB
2022-07-08T14:53:01+0200 Name: postmaster Pid: 7866 RssAnon: 1180960 kB
2022-07-08T14:53:53+0200 Name: postmaster Pid: 7866 RssAnon: 1180960 kB

other processes uses less memory:
2022-07-08T14:52:08+0200 Name: postmaster Pid: 3869 RssAnon:3256 kB
2022-07-08T14:53:02+0200 Name: postmaster Pid: 3869 RssAnon:3256 kB
2022-07-08T14:53:54+0200 Name: postmaster Pid: 3869 RssAnon:3256 kB
2022-07-08T14:50:27+0200 Name: postmaster Pid: 4217 RssAnon:2532 kB
2022-07-08T14:51:16+0200 Name: postmaster Pid: 4217 RssAnon:2532 kB



And Shared memory:
2022-07-08T14:59:12+0200 Name: postmaster Pid: 5719 RssShmem:  908264 kB
2022-07-08T14:59:20+0200 Name: postmaster Pid: 5719 RssShmem:  908264 kB
2022-07-08T14:59:28+0200 Name: postmaster Pid: 5719 RssShmem:  908264 kB
2022-07-08T14:59:37+0200 Name: postmaster Pid: 5719 RssShmem:  908264 kB
2022-07-08T14:59:45+0200 Name: postmaster Pid: 5719 RssShmem:  908264 kB
2022-07-08T14:59:53+0200 Name: postmaster Pid: 5719 RssShmem:  908264 kB
2022-07-08T14:50:27+0200 Name: postmaster Pid: 5721 RssShmem: 1531656 kB
2022-07-08T14:51:16+0200 Name: postmaster Pid: 5721 RssShmem: 1531656 kB
2022-07-08T14:52:08+0200 Name: postmaster Pid: 5721 RssShmem: 1531656 kB
2022-07-08T14:53:01+0200 Name: postmaster Pid: 5721 RssShmem: 1531656 kB
2022-07-08T14:53:53+0200 Name: postmaster Pid: 5721 RssShmem: 1531656 kB

while other processes uses failry less of shared mem:

2022-07-08T14:55:25+0200 Name: postmaster Pid: 8521 RssShmem:1988 kB
2022-07-08T14:55:33+0200 Name: postmaster Pid: 8521 RssShmem:1988 kB
2022-07-08T14:55:40+0200 Name: postmaster Pid: 8521 RssShmem:2104 kB
2022-07-08T14:55:49+0200 Name: postmaster Pid: 8521 RssShmem:2104 kB
2022-07-08T14:55:57+0200 Name: postmaster Pid: 8521 RssShmem:2104 kB
2022-07-08T14:56:06+0200 Name: postmaster Pid: 8521 RssShmem:2104 kB
2022-07-08T14:56:15+0200 Name: postmaster Pid: 8521 RssShmem:2104 kB

Wich processes are better candidates for investigation, the ones using more
Anonymous memory or the ones using larger shared memory?
I can do the (tedious) work to get a list of statements that a given PID
executed (at least the statements that appear in the minute snapshots).


>   ErrorContext: 8192 total in 1 blocks; 7928 free (5 chunks); 264 used
>> Grand total: 1456224 bytes in 195 blocks; 378824 free (165 chunks);
>> 1077400 used
>> 2022-07-02 14:48:07 CEST [3930]: [3-1] user=,db=,host=,app= ERROR:  out
>> of memory
>> 2022-07-02 14:48:07 CEST [3930]: [4-1] user=,db=,host=,app= DETAIL:
>>  Failed on request of size 152094068 in memory context
>> "TopTransactionContext".
>> 2022-07-02 14:48:07 CEST [3930]: [5-1] user=,db=,host=,app= CONTEXT:
>>  automatic vacuum of table "prematch.replication.tab_queue_tmp"
>>
>> 2022-07-02 14:48:47 CEST [4476]: [42-1] user=,db=,host=,app= LOG:  could
>> not fork worker process: Cannot allocate memory
>> 2022-07-02 14:48:47 CEST [4476]: [43-1] user=,db=,host=,app= LOG:  could
>> not fork worker process: Cannot allocate memory
>> terminate called after throwing an instance of 'std::bad_alloc'
>>   what():  std::bad_alloc
>>
> 2022-07-02 14:48:47 CEST [4476]: [44-1] user=,db=,host=,app= LOG:
>>  background worker "parallel worker" (PID 4303) was terminated by signal 6:
>> Aborted
>>
>>
> But what you see is probably just side effect. Do you use some extension
> in C++? This is C++ message. This process kills Postgres.
>

These extensions are installed (and no change from 14.3):

List of installed extensions
Name| Version |   Schema   |
 Description
+-++
 amcheck| 1.3 | public | functions for verifying
relation integrity
 dblin

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

st 13. 7. 2022 v 2:20 odesílatel Michael Paquier 
napsal:

> On Mon, Jul 11, 2022 at 10:50:23AM +0200, Aleš Zelený wrote:
> > So far, it has happened three times (during a single week) from the 14.3
> ->
> > 14.4 upgrade, before 14.4 we haven't suffered from such an issue.
> >
> > Questions:
> > 1)  Can we safely downgrade from 14.4 to 14.3 by shutting down the
> instance
> > and reinstalling 14.3 PG packages (to prove, that the issue disappear)?
> > 2) What is the best way to diagnose what is the root cause?
>
> Hmm.  14.4 has nothing in its release notes that would point to a
> change in the vacuum or autovacuum's code paths:
> https://www.postgresql.org/docs/14/release-14-4.html#id-1.11.6.5.4
>
> There is nothing specific after a look at the changes as of, and I am
> not grabbing anything that would imply a change in memory context
> handling either:
> `git log --stat REL_14_3..REL_14_4`
> `git diff REL_14_3..REL_14_4 -- *.c`
>
> Saying that, you should be able to downgrade safely as there are no
> changes in WAL format or such that would break things.  Saying that,
> the corruption issue caused by CONCURRENTLY is something you'd still
> have to face.
>
>
Thanks, good to know that, we can use it for a test case, since we already
hit the CONCURRENTLY bug on 14.3.

> 2022-07-02 14:48:07 CEST [3930]: [3-1] user=,db=,host=,app= ERROR:  out of
> > memory
> > 2022-07-02 14:48:07 CEST [3930]: [4-1] user=,db=,host=,app= DETAIL:
> Failed
> > on request of size 152094068 in memory context "TopTransactionContext".
> > 2022-07-02 14:48:07 CEST [3930]: [5-1] user=,db=,host=,app= CONTEXT:
> >  automatic vacuum of table "prematch.replication.tab_queue_tmp"
>
> This is the interesting part.  Do you happen to use logical
> replication in a custom C++ plugin?
>

We are using logical replication to other instances (pg_output) and
decoderbufs
https://github.com/debezium/postgres-decoderbufs for other applications.


> > 2022-07-02 14:48:47 CEST [4476]: [43-1] user=,db=,host=,app= LOG:  could
> > not fork worker process: Cannot allocate memory
> > terminate called after throwing an instance of 'std::bad_alloc'
> >   what():  std::bad_alloc
> >
> > DETAIL: parameters: $1 = '1', $2 = '1748010445', $3 = '0', $4 = '1000'
> > terminate
> > called after throwing an instance of 'std::bad_alloc' terminate called
> > after throwing an instance of 'std::bad_alloc' what(): what():
> > std::bad_allocstd::bad_alloc 2022-07-08 14:54:23 CEST [4476]: [49-1]
> > user=,db=,host=,app= LOG: background worker "parallel worker" (PID 25251)
> > was terminated by signal 6: Aborted
> > 2022-07-08 14:54:23 CEST [4476]: [51-1] user=,db=,host=,app= LOG:
> >  terminating any other active server processes
>
> Looks like something is going wrong in the memory handling of one of
> your C++ extensions here.  If you can isolate an issue using a query
> without any custom code, that would be a Postgres problem, but I think
> that you are missing a trick in it.
>

Here are extensions installed in the database served by the cluster:
prematch=# \dx
List of installed extensions
Name| Version |   Schema   |
 Description
+-++
 amcheck| 1.3 | public | functions for verifying
relation integrity
 dblink | 1.2 | public | connect to other PostgreSQL
databases from within a database
 file_fdw   | 1.0 | public | foreign-data wrapper for flat
file access
 hstore | 1.8 | public | data type for storing sets of
(key, value) pairs
 hypopg | 1.3.1   | public | Hypothetical indexes for
PostgreSQL
 pageinspect| 1.9 | public | inspect the contents of
database pages at a low level
 pg_buffercache | 1.3 | public | examine the shared buffer cache
 pg_stat_kcache | 2.2.0   | public | Kernel statistics gathering
 pg_stat_statements | 1.9 | public | track planning and execution
statistics of all SQL statements executed
 pgcrypto   | 1.3 | public | cryptographic functions
 pgstattuple| 1.5 | public | show tuple-level statistics
 plpgsql| 1.0 | pg_catalog | PL/pgSQL procedural language
 plpgsql_check  | 2.1 | public | extended check for plpgsql
functions
 postgres_fdw   | 1.1 | public | foreign-data wrapper for
remote PostgreSQL servers
 tablefunc  | 1.0 | public | functions that manipulate
whole tables, including crosstab
(15 row

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Dne čt 14. 7. 2022 23:11 uživatel Tomas Vondra <
tomas.von...@enterprisedb.com> napsal:

>
>
> On 7/14/22 21:25, Aleš Zelený wrote:
> >
> > st 13. 7. 2022 v 2:20 odesílatel Michael Paquier  > <mailto:mich...@paquier.xyz>> napsal:
> >
> > On Mon, Jul 11, 2022 at 10:50:23AM +0200, Aleš Zelený wrote:
> > > So far, it has happened three times (during a single week) from
> > the 14.3 ->
> > > 14.4 upgrade, before 14.4 we haven't suffered from such an issue.
> > >
> > > Questions:
> > > 1)  Can we safely downgrade from 14.4 to 14.3 by shutting down the
> > instance
> > > and reinstalling 14.3 PG packages (to prove, that the issue
> > disappear)?
> > > 2) What is the best way to diagnose what is the root cause?
> >
> > Hmm.  14.4 has nothing in its release notes that would point to a
> > change in the vacuum or autovacuum's code paths:
> > https://www.postgresql.org/docs/14/release-14-4.html#id-1.11.6.5.4
> > <https://www.postgresql.org/docs/14/release-14-4.html#id-1.11.6.5.4>
> >
> > There is nothing specific after a look at the changes as of, and I am
> > not grabbing anything that would imply a change in memory context
> > handling either:
> > `git log --stat REL_14_3..REL_14_4`
> > `git diff REL_14_3..REL_14_4 -- *.c`
> >
> > Saying that, you should be able to downgrade safely as there are no
> > changes in WAL format or such that would break things.  Saying that,
> > the corruption issue caused by CONCURRENTLY is something you'd still
> > have to face.
> >
> >
> > Thanks, good to know that, we can use it for a test case, since we
> > already hit the CONCURRENTLY bug on 14.3.
> >
> > > 2022-07-02 14:48:07 CEST [3930]: [3-1] user=,db=,host=,app=
> > ERROR:  out of
> > > memory
> > > 2022-07-02 14:48:07 CEST [3930]: [4-1] user=,db=,host=,app=
> > DETAIL:  Failed
> > > on request of size 152094068 in memory context
> > "TopTransactionContext".
> > > 2022-07-02 14:48:07 CEST [3930]: [5-1] user=,db=,host=,app=
> CONTEXT:
> > >  automatic vacuum of table "prematch.replication.tab_queue_tmp"
> >
> > This is the interesting part.  Do you happen to use logical
> > replication in a custom C++ plugin?
> >
> >
> > We are using logical replication to other instances (pg_output) and
> > decoderbufs
> > https://github.com/debezium/postgres-decoderbufs
> > <https://github.com/debezium/postgres-decoderbufs> for other
> applications.
> >
>
> This is probably just a red herring - std:bad_alloc is what the process
> that runs into the overcommit limit gets. But the real issue (e.g.
> memory leak) is likely somewhere else - different part of the code,
> different process ...
>
> > ...
> >
> > Checking the RssAnon from proc/pid/status I've found some points where
> > RssAnon memory usage grew very steep for a minute, but no "suspicious"
> > queries/arguments were found in the instance logfile.
> >
> > Any hint, on how to get the root cause would be appreciated since so far
> > I've failed to isolate the issue reproducible testcase.
> > At least I hope that looking for the RssAnon process memory is an
> > appropriate metric, if not, let me know and I'll try to update the
> > monitoring to get the root cause.
> >
> > I can imagine a workaround with client application regular reconnect...,
> > but u to 14.3 it works, so I'd like to fix the issue either on our
> > application side or at PG side if it is a PG problem.
> >
>
> I think it's be interesting to get memory context stats from the
> processes consuming a lot of memory. If you know which processes are
> suspect (and it seems you know, bacause if a reconnect helps it's the
> backend handling the connection), you can attach a debugger and do
>
>$ gdb -p $PID
>call MemoryContextStats(TopMemoryContext)
>
> which will log info about memory contexts, just like autovacuum.
> Hopefully that tells us memory context is bloated, and that might point
> us to particular part of the code.
>

If the RssAnon memory is a good indicator, i can then determine the
backends and dump memory context.
It'll take me some time since I'm out of office for vacation, but I'll
manage that somewhat way.

Thanks for all to the hints!

Aleš

>
> regards
>
> --
> Tomas Vondra
> EnterpriseDB: http://www.enterprisedb.com
> The Enterprise PostgreSQL Company
>

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Hello,




čt 14. 7. 2022 v 23:31 odesílatel Aleš Zelený 
napsal:

>
>
> Dne čt 14. 7. 2022 23:11 uživatel Tomas Vondra <
> tomas.von...@enterprisedb.com> napsal:
>
>>
>>
>> On 7/14/22 21:25, Aleš Zelený wrote:
>> >
>> > st 13. 7. 2022 v 2:20 odesílatel Michael Paquier > > <mailto:mich...@paquier.xyz>> napsal:
>> >
>> > On Mon, Jul 11, 2022 at 10:50:23AM +0200, Aleš Zelený wrote:
>> > > So far, it has happened three times (during a single week) from
>> > the 14.3 ->
>> > > 14.4 upgrade, before 14.4 we haven't suffered from such an issue.
>> > >
>> > > Questions:
>> > > 1)  Can we safely downgrade from 14.4 to 14.3 by shutting down the
>> > instance
>> > > and reinstalling 14.3 PG packages (to prove, that the issue
>> > disappear)?
>> > > 2) What is the best way to diagnose what is the root cause?
>> >
>> > Hmm.  14.4 has nothing in its release notes that would point to a
>> > change in the vacuum or autovacuum's code paths:
>> > https://www.postgresql.org/docs/14/release-14-4.html#id-1.11.6.5.4
>> > <https://www.postgresql.org/docs/14/release-14-4.html#id-1.11.6.5.4
>> >
>> >
>> > There is nothing specific after a look at the changes as of, and I
>> am
>> > not grabbing anything that would imply a change in memory context
>> > handling either:
>> > `git log --stat REL_14_3..REL_14_4`
>> > `git diff REL_14_3..REL_14_4 -- *.c`
>> >
>> > Saying that, you should be able to downgrade safely as there are no
>> > changes in WAL format or such that would break things.  Saying that,
>> > the corruption issue caused by CONCURRENTLY is something you'd still
>> > have to face.
>> >
>> >
>> > Thanks, good to know that, we can use it for a test case, since we
>> > already hit the CONCURRENTLY bug on 14.3.
>> >
>> > > 2022-07-02 14:48:07 CEST [3930]: [3-1] user=,db=,host=,app=
>> > ERROR:  out of
>> > > memory
>> > > 2022-07-02 14:48:07 CEST [3930]: [4-1] user=,db=,host=,app=
>> > DETAIL:  Failed
>> > > on request of size 152094068 in memory context
>> > "TopTransactionContext".
>> > > 2022-07-02 14:48:07 CEST [3930]: [5-1] user=,db=,host=,app=
>> CONTEXT:
>> > >  automatic vacuum of table "prematch.replication.tab_queue_tmp"
>> >
>> > This is the interesting part.  Do you happen to use logical
>> > replication in a custom C++ plugin?
>> >
>> >
>> > We are using logical replication to other instances (pg_output) and
>> > decoderbufs
>> > https://github.com/debezium/postgres-decoderbufs
>> > <https://github.com/debezium/postgres-decoderbufs> for other
>> applications.
>> >
>>
>> This is probably just a red herring - std:bad_alloc is what the process
>> that runs into the overcommit limit gets. But the real issue (e.g.
>> memory leak) is likely somewhere else - different part of the code,
>> different process ...
>>
>> > ...
>> >
>> > Checking the RssAnon from proc/pid/status I've found some points where
>> > RssAnon memory usage grew very steep for a minute, but no "suspicious"
>> > queries/arguments were found in the instance logfile.
>> >
>> > Any hint, on how to get the root cause would be appreciated since so far
>> > I've failed to isolate the issue reproducible testcase.
>> > At least I hope that looking for the RssAnon process memory is an
>> > appropriate metric, if not, let me know and I'll try to update the
>> > monitoring to get the root cause.
>> >
>> > I can imagine a workaround with client application regular reconnect...,
>> > but u to 14.3 it works, so I'd like to fix the issue either on our
>> > application side or at PG side if it is a PG problem.
>> >
>>
>> I think it's be interesting to get memory context stats from the
>> processes consuming a lot of memory. If you know which processes are
>> suspect (and it seems you know, bacause if a reconnect helps it's the
>> backend handling the connection), you can attach a debugger and do
>>
>>$ gdb -p $PID
>>call MemoryContextStats(TopMemoryContext)
>>
>> which will log info about memory contexts, 

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

po 18. 7. 2022 v 16:25 odesílatel Tom Lane  napsal:

> =?UTF-8?B?QWxlxaEgWmVsZW7DvQ==?=  writes:
> > after some time, I've found a process consuming over 1GB of memory"
> > -bash-4.2$ grep RssAnon /proc/*/status | sort -nk2 | tail
> > /proc/17048/status:RssAnon: 1053952 kB
>
> > Here are memory contexts for PID 17048:
>
> > TopMemoryContext: 422592 total in 14 blocks; 42536 free (169 chunks);
> > 380056 used
> ...
> > Grand total: 14312808 bytes in 4752 blocks; 3920880 free (1043 chunks);
> > 10391928 used
>
> OK, so PG's normal memory consumption is only ~14MB.  Where'd the
> rest of it go?
>
> > -bash-4.2$ pmap 17048
> ...
> > 02d93000 838092K rw---   [ anon ]
> > 7fd999777000 180232K rw---   [ anon ]
> > 7fd9a8d75000  32772K rw---   [ anon ]
>

and a few hours later it even grew:

-bash-4.2$ cat 20220718_200230.pmap.17048.log | grep anon
00db3000200K rw---   [ anon ]
02d15000504K rw---   [ anon ]
02d93000 934476K rw---   [ anon ]
7fd989776000 311304K rw---   [ anon ]
7fd9a8d75000  32772K rw---   [ anon ]
7fd9acb65000 20K rw---   [ anon ]
7fd9affc1000372K rw---   [ anon ]

>From previous observation I know, that the process RssAnon memory grew over
time, sometimes there are some steps. Still, generally, the growth is
linear until the process finishes or we run out of memory, and the cluster
is reinitialized by the postmaster.
No such behavior on older versions until 14.3 (including).

...
> Probably the 838M chunk is shared memory?  Is that within hailing
> distance of your shared_buffers setting?
>

postgres=# show shared_buffers ;
 shared_buffers

 10GB
(1 row)

...
> > 7fd9b0551000 10827040K rw-s- zero (deleted)
>

These 10GB matches 10GB configured as shared buffers.


> ...
> And here we have the culprit, evidently ... but what the dickens
> is it?  I can't think of any mechanism within Postgres that would
> create such an allocation.
>
> regards, tom lane
>

Kind regards
Ales Zeleny

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Hello,

po 18. 7. 2022 v 21:04 odesílatel Tom Lane  napsal:

> =?UTF-8?B?QWxlxaEgWmVsZW7DvQ==?=  writes:
> > postgres=# show shared_buffers ;
> >  shared_buffers
> > 
> >  10GB
> > (1 row)
>
> Oh!  In that case, there is absolutely nothing to see here.
> This chunk:
>
> > 7fd9b0551000 10827040K rw-s- zero (deleted)
>
> must be your shared-memory region, and it's accounting for just
> about all of the process's memory space.  There is no reason
> to suspect a leak.
>

I agree this 10 GB is expected to be accounted for shared buffers (just a
size correlation) and therefore no memory leak here.



> I think you've been fooled by the fact that "top" and some other
> tools frequently don't report a shared-memory page as part of a
> process's usage until that process touches that particular page.
> Thus, the reported memory usage of a Postgres backend will grow
> over time as it randomly happens to touch different buffers within
> the shared buffer arena.  That does not constitute a leak, but
> it does make such tools next door to useless for detecting
> actual leaks :-(.  You can only believe there's a leak if the
> reported usage doesn't level off after reaching the vicinity of
> your shared memory size.
>

On the other hand, if we do have 10GB of shared buffers plus ~14MB reported
by Top Memory Context (even if /proc//status reports RssAnon memory
when touched, the process VM peak is ~12 GB?
-bash-4.2$ cat 20220718_200230.status.17048.log
Name: postmaster
Umask: 0077
State: S (sleeping)
Tgid: 17048
Ngid: 0
Pid: 17048
PPid: 4476
TracerPid: 0
Uid: 26 26 26 26
Gid: 26 26 26 26
FDSize: 1024
Groups: 26
VmPeak: 12477752 kB
VmSize: 12439740 kB
VmLck:   0 kB
VmPin:   0 kB
VmHWM: 9811560 kB
VmRSS: 9811560 kB
RssAnon: 1283964 kB
RssFile:   15784 kB
RssShmem: 8511812 kB
VmData: 1282860 kB
VmStk: 132 kB
VmExe:7816 kB
VmLib:   85312 kB
VmPTE:   23716 kB
VmSwap:   0 kB
Threads: 1
SigQ: 0/160197
SigPnd: 
ShdPnd: 
SigBlk: 0040
SigIgn: 01701800
SigCgt: 0001a0006287
CapInh: 
CapPrm: 
CapEff: 
CapBnd: 001f
CapAmb: 
NoNewPrivs: 0
Seccomp: 0
Speculation_Store_Bypass: thread vulnerable
Cpus_allowed: ff
Cpus_allowed_list: 0-23
Mems_allowed:
,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,0003
Mems_allowed_list: 0-1
voluntary_ctxt_switches: 5273344
nonvoluntary_ctxt_switches: 13651

I'd expect VMPeak size close to 10GB  (suppose that all shared memory pages
were touched) shared_buffers plus ~14MB of private memory, but
VMPeak: 12477752 [kB] - 10485760 shared buffers [kB] = 1991992 kB Which is
a bit more than reported RssAnon: 1283964 kB  memory for the process, but
very close.

pmap taken in the same time:

-bash-4.2$ cat 20220718_200230.pmap.17048.log | grep -e anon -e deleted
00db3000200K rw---   [ anon ]
02d15000504K rw---   [ anon ]
02d93000 934476K rw---   [ anon ]  <<<= this is suspected to be
responsible for the OutOfMemory -> failing fork(), reinitialize the cluser
7fd989776000 311304K rw---   [ anon ]  <<<= togehter with this one
7fd9a8d75000  32772K rw---   [ anon ]
7fd9acb65000 20K rw---   [ anon ]
7fd9affc1000372K rw---   [ anon ]
7fd9b023d000   1028K rw---   [ anon ]
7fd9b054b000 24K rw---   [ anon ]
7fd9b0551000 10827040K rw-s- zero (deleted)   <<<= expected to be
shared_buffers
7fdc45f18000 16K rw---   [ anon ]
7fdc4d50c000184K rw---   [ anon ]
7fdc4de16000  4K rw---   [ anon ]
7fdc4e03c000  8K rw---   [ anon ]
7fdc4fd1e000 84K rw---   [ anon ]
7fdc4ff6f000  8K rw---   [ anon ]
7fdc508d7000  8K rw---   [ anon ]
7fdc50d59000  4K rw---   [ anon ]
7fdc5139e000  8K rw---   [ anon ]
7fdc520f3000 40K rw---   [ anon ]
7fdc52902000 20K rw---   [ anon ]
7fdc52ead000 16K rw---   [ anon ]
7fdc532af000  4K rw---   [ anon ]
7fdc53e2b000 16K rw---   [ anon ]
7fdc544db000 16K rw---   [ anon ]
7fdc54cc8000  8K rw---   [ anon ]
7fdc54f1a000   1588K rw---   [ anon ]
7fdc550dc000104K rw---   [ anon ]
7fdc550fc000  8K r-x--   [ anon ]
7fdc550ff000  4K rw---   [ anon ]
7fdc55102000  4K rw---   [ anon ]
7fffd38f  8K r-x--   [ anon ]
ff60  4K r-x--   [ anon ]


The machine has 40GB of RAM. It is a dedicated DB server, only a single PG
instance is running there. Since we again run out of memory from my last
reply, now it looks  healthy:

-bash-4.2$ psql -c "select count(*) from pg_stat_activity"
 count
---
   336
(1 row)

$-bash-4.2$ sudo smem -u
User Count Swap  

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Hello,

I did some testing and the result is that on pg12 there are no such
problems. Pg13 and Pg 14.3 tests will follow but based on monitoring
processed RssAnon memory, I've found a correlation that only processes by a
single user are suffering from the memory allocation (it looks to be a
memory leak to me).
For the given DB user, I've configured log_min_duration_stattement to 0 and
afterward analyzed the Postgres server log with all the statements in the
time window when I spot a significant memory growth for a single process in
a short time (a few minutes).
This correlation points my attention to a SQL function called frequently
and I've tried to do some testing with it.



CREATE OR REPLACE FUNCTION tescase (_id_data_provider integer, _external_id
bigint DEFAULT NULL::bigint, _external_complete_id character varying
DEFAULT NULL::character varying)
 RETURNS TABLE(id_gm bigint, id_opp bigint, id_opp_state integer)
 LANGUAGE sql
AS $function$
SELECT ... simple join of two tables...
 WHERE opd.id_data_provider = _id_data_provider
   AND CASE WHEN _external_id IS NULL
THEN external_id IS NULL
ELSE external_id = _external_id
   END
   AND CASE WHEN _external_complete_id IS NULL
THEN _external_complete_id IS NULL
ELSE external_complete_id = _external_complete_id
   END;
$function$
;

It is a kind of creative construct for me, but it works. The key here is
that if I replace at least one of the "CASEd" where conditions, it seems
not to suffer from the memory leak issue.

Finally, I've found, that even having the function as is and before the
test disabling JIT (SET jit = off;) and calling the function 100k times,
RssAnon memory for the given process is stable and only 3612 kB, while when
JIT is enabled (the default setting on the server suffering from the memory
leak, RssAnon memory for the given process growth in a linear manner over
time (canceled when it reached 5GB).
Tested on real application data I could not share, but if I got a chance to
give try to the preparation of a synthetic test case, then I thought it'll
be time to submit it as a bug.

In the smaps for the given process, it is possible to identify the address
of a heap allocated memory wich constantly grows every execution (while
other mapped heap segment's size is static ), but I have no clue whether it
might help, it looks like:

while :; do date; sed -n '/^02d93000.*/,/^VmFlags/p' /proc/31600/smaps;
sleep 2; done

Út srp  2 17:10:18 CEST 2022
02d93000-20fe1000 rw-p  00:00 0
 [heap]
Size: 493880 kB
Rss:  492784 kB
Pss:  492784 kB
Shared_Clean:  0 kB
Shared_Dirty:  0 kB
Private_Clean: 0 kB
Private_Dirty:492784 kB
Referenced:   492560 kB
Anonymous:492784 kB
AnonHugePages: 0 kB
Swap:  0 kB
KernelPageSize:4 kB
MMUPageSize:   4 kB
Locked:0 kB
VmFlags: rd wr mr mp me ac sd
Út srp  2 17:10:20 CEST 2022
02d93000-21003000 rw-p  00:00 0
 [heap]
Size: 494016 kB
Rss:  493660 kB
Pss:  493660 kB
Shared_Clean:  0 kB
Shared_Dirty:  0 kB
Private_Clean: 0 kB
Private_Dirty:493660 kB
Referenced:   493436 kB
Anonymous:493660 kB
AnonHugePages: 0 kB
Swap:  0 kB
KernelPageSize:4 kB
MMUPageSize:   4 kB
Locked:0 kB
VmFlags: rd wr mr mp me ac sd

Thanks for any hints or comments.
Ales

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Hello,

thanks for the information and the link!

Ales

čt 4. 8. 2022 v 1:05 odesílatel Tom Lane  napsal:

> =?UTF-8?B?QWxlxaEgWmVsZW7DvQ==?=  writes:
> > CREATE OR REPLACE FUNCTION tescase (_id_data_provider integer,
> _external_id
> > bigint DEFAULT NULL::bigint, _external_complete_id character varying
> > DEFAULT NULL::character varying)
> >  RETURNS TABLE(id_gm bigint, id_opp bigint, id_opp_state integer)
> >  LANGUAGE sql
> > AS $function$
> > SELECT ... simple join of two tables...
> >  WHERE opd.id_data_provider = _id_data_provider
> >AND CASE WHEN _external_id IS NULL
> > THEN external_id IS NULL
> > ELSE external_id = _external_id
> >END
> >AND CASE WHEN _external_complete_id IS NULL
> > THEN _external_complete_id IS NULL
> > ELSE external_complete_id = _external_complete_id
> >END;
> > $function$
> > ;
>
> > It is a kind of creative construct for me, but it works. The key here is
> > that if I replace at least one of the "CASEd" where conditions, it seems
> > not to suffer from the memory leak issue.
>
> > Finally, I've found, that even having the function as is and before the
> > test disabling JIT (SET jit = off;) and calling the function 100k times,
> > RssAnon memory for the given process is stable and only 3612 kB, while
> when
> > JIT is enabled (the default setting on the server suffering from the
> memory
> > leak, RssAnon memory for the given process growth in a linear manner over
> > time (canceled when it reached 5GB).
>
> Ah.  I bet this is another instance of the known memory leakage problems
> with JIT inlining [1].  Per Andres' comments in that thread, it seems
> hard to solve properly.  For now all I can recommend is to disable that.
>
> regards, tom lane
>
> [1]
> https://www.postgresql.org/message-id/flat/20201001021609.GC8476%40telsasoft.com
>

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Hello,

the construct surprised me when I saw it in the function the first time,
but it is correct and works as expected - it allows writing the function as
SQL instead of PLPGSQL while it ensures that for a parameter null value it
evaluates to true instead of filtering the resultset.
What is the issue/better solution proposal?

Kind regards Ales Zeleny


čt 4. 8. 2022 v 23:15 odesílatel Joe Conway  napsal:

> On 8/4/22 08:34, Aleš Zelený wrote:
> >> SELECT ... simple join of two tables...
> >>  WHERE opd.id_data_provider = _id_data_provider
> >>AND CASE WHEN _external_id IS NULL
> >> THEN external_id IS NULL
> >> ELSE external_id = _external_id
> >>END
> >>AND CASE WHEN _external_complete_id IS NULL
> >> THEN _external_complete_id IS NULL
>
> Unrelated to your question, but shouldn't that actually read:
>
> AND CASE WHEN _external_complete_id IS NULL
>  THEN external_complete_id IS NULL
>  ^^^
>
> >> ELSE external_complete_id = _external_complete_id
> >>END;
> >> $function$
>
> --
> Joe Conway
> RDS Open Source Databases
> Amazon Web Services: https://aws.amazon.com
>

Re: PostgreSQL 14.4 ERROR: out of memory issues

[Aleš Zelený]

Hello,

The problem Joe spotted is that a variable name is misspelled in one
> place. It should (probably) be external_complete_id, not
> _external_complete_id).


Oh, copy-paste issue :-)


> > better solution proposal?
>
> I think you can make that clearer by using IS [NOT] DISTINCT FROM:
>
> SELECT ... simple join of two tables...
> WHERE opd.id_data_provider = _id_data_provider
> AND external_id IS NOT DISTINCT FROM _external_id
> AND external_complete_id IS NOT DISTINCT FROM _external_complete_id
> ;
>
> However, your version may be faster, as last time I looked (it's been
> some time) the optimizer wasn't especially good at handlung DISTINCT
> FROM (probably because it's so rarely used).g
>
> Distinct from was the original version, but it ignores indexes, 130ms  vs
0.3 ms, you are absolutely correct.

Kind regards
Ales Zeleny

Logical replication hangs up.

[Aleš Zelený]

Hello,

we are suing logical replication on 10.4  and it now hangs. After some
timeout it is retarted again, replaying 18GB of data and then hangs (while
7GB of wals remains to be proceeded).

The backlog of 18GB comes from a failed migration adding new table to
replication while replication user was not granted to select the table.
This was clear from log files and once resolved by adding select privilege,
I thought that all will work as usual (same happened in test env. many
times and adding missing grant for select was sufficient to get it
working... these were issues on tests).

RDBMS Version:
PostgreSQL 10.4 (Ubuntu 10.4-2.pgdg16.04+1) on x86_64-pc-linux-gnu,
compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.9) 5.4.0 20160609, 64-bit

Publication (master) instance error message from log:

2018-11-02 18:34:14 UTC 7974 5bdc8d27.1f26 7 192.168.23.11(58884)
master_prod repusr 0 5/0 sub_eur idle [0]:LOG:  terminating walsender
process due to replication timeout

Subscription instance log:

2018-11-02 18:34:14 UTC 8657 5bdc8d26.21d1 20 3/0   [XX000]:ERROR:
could not receive data from WAL stream: SSL connection has been closed
unexpectedly
2018-11-02 18:34:14 UTC 24699 5b923b1c.607b 12093970[0]:LOG:
worker process: logical replication worker for subscription 37932 (PID
8657) exited with exit code 1

While it seems to be a network issue, it is may be not - we have checked
the network and even monitoring, all the time some packets were exchanged.

We do have 3 subscriptions(thus repl. slots) for one publication, one
subscriber instance is within same datacenter as master, remainig
subscribers are remote.


>> select * from pg_replication_slots
++--+---++-+---+++--+--+--+-+
| slot_name  | plugin   | slot_type | datoid | database| temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn  |
confirmed_flush_lsn |
++--+---++-+---+++--+--+--+-+
| sub_usd| pgoutput | logical   | 16421  | master_prod | False |
True   | 16604  |  | 5536488  | 426/AAE55A68 |
426/AAE55A68|
| sub_cad| pgoutput | logical   | 16421  | master_prod | False |
True   | 22875  |  | 5536488  | 426/AAE55A68 |
426/AAE55A68|
| sub_eur| pgoutput | logical   | 16421  | master_prod | False |
True   | 16605  |  | 5536488  | 426/AAE55A68 |
426/AAE55A68|
++--+---++-+---+++--+--+--+-+


Once  after the error occurs, wal senders are re/started and they reads wal
files until they reach restart_lsn wal file:

>> select pg_walfile_name('426/AAE55A68')
+--+
| pg_walfile_name  |
+--+
| 0001042600AA |
+--+

# changing file names until they reach this one:
root@master-db:/pgsql/pgcluster/10/master_prod# lsof -p 1560 -p 5758 -p
5790| grep pg_wal
postgres 1560 postgres   10r  REG  259,3  16777216 115766007
/pgsql/pgcluster/10/master_prod/pg_wal/000104290069
postgres 5758 postgres   10r  REG  259,3  16777216 115766007
/pgsql/pgcluster/10/master_prod/pg_wal/000104290069
postgres 5790 postgres   10r  REG  259,3  16777216 115766007
/pgsql/pgcluster/10/master_prod/pg_wal/000104290069


At this moment sent_lsn stops growing and nothing is happening for a while.

select * from pg_stat_replication;

  pid  | usesysid | usename |  application_name  | client_addr   |
client_hostname | client_port | backend_start |
backend_xmin |  state  |   sent_lsn   |  write_lsn   |  flush_lsn   |
replay_lsn  | write_lag | flush_lag | replay_lag | sync_priority |
sync_state
---+--+-++---+-+-+---+--+-+--+--+--+--+---+---++---+
 16604 |37868 | repusr  | sub_usd| 192.168.21.11
| |   35010 | 2018-11-02 23:52:22.059157+00
|  | catchup | 429/69E9CC60 | 426/AAE55A68 | 426/AAE55A68 |
426/AAE55A68 |   |   || 0 | async
 16605 |37868 | repusr  | sub_eur| 192.168.23.11
| |   36388 | 2018-11-02 23:52:24.75038+00
|  | catchup | 429/69E9CC60 | 426/AAE55A68 | 426/AAE55A68 |
426/AAE55A68 |   |   || 0 | async
 12387 |37868 | repusr  | sub_cad| 192.168.22.11
| |   51982 | 2018-11-02 23:30:31.372404+00
|  | catchup | 429/69E9CC60 | 426/A

Re: Logical replication hangs up.

[Aleš Zelený]

Hello,

wal_sender_timeout did not help (from default 60s to 600s), but I haven't
tested receiver timeout since it was sender complaining and receiver loops
over ( recvfrom with "Resource  temporarily unavailable" result, so i
thought it is waiting for master sender to provide some data), thanks for
the tip.

Since the behavior is all the time deterministic - works as expected until
sender reaches 429/69E9CC60 (  wal 000104290069 ) and it stuck
it seems to me, that the issue is somewhat related to content of this file.

Another consideration is, why restart_lsn ( flush_lsn   /  replay_lsn on
master ) never goes through 426/AAE55A68. May be, it is due to lack of my
knowledge, but I'd expect that within almost 11GB of wal data would be some
committed changes and it is lot behind maximum sent_lsn reported by wal
sender - I would expect reply_lsn to more/less follow sent_lsn but I have
no clue what what is root cause (stuck sender at certain sent_lsn or
logical replication bg worker not applying/reporting so keeping restart_lsn
constant). That is why I've tried to find whatever suspicious using
pg_waldump in wal files corresponding to restart_lsn and sent_lsn.

Kind regards Ales

so 3. 11. 2018 v 17:02 odesílatel Jerry Sievers 
napsal:

> Aleš Zelený  writes:
>
> > Hello,
> >
> > we are suing logical replication on 10.4  and it now hangs. After
> > some timeout it is retarted again, replaying 18GB of data and then
> > hangs (while 7GB of wals remains to be proceeded).
>
> Timeout...
>
> Have a look at the 2 setting wal sender/receiver timeout and you
> probably need to raise the sender timeout value.
>
> HTH
>
> >
> > The backlog of 18GB comes from a failed migration adding new table to
> > replication while replication user was not granted to select the
> > table. This was clear from log files and once resolved by adding
> > select privilege, I thought that all will work as usual (same
> > happened in test env. many times and adding missing grant for select
> > was sufficient to get it working... these were issues on tests).
> >
> > RDBMS Version:
> > PostgreSQL 10.4 (Ubuntu 10.4-2.pgdg16.04+1) on x86_64-pc-linux-gnu,
> > compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.9) 5.4.0 20160609,
> > 64-bit
> >
> > Publication (master) instance error message from log:
> >
> > 2018-11-02 18:34:14 UTC 7974 5bdc8d27.1f26 7 192.168.23.11(58884)
> > master_prod repusr 0 5/0 sub_eur idle [0]:LOG:  terminating
> > walsender process due to replication timeout
> >
> > Subscription instance log:
> >
> > 2018-11-02 18:34:14 UTC 8657 5bdc8d26.21d1 20 3/0
> > [XX000]:ERROR:  could not receive data from WAL stream: SSL
> > connection has been closed unexpectedly
> > 2018-11-02 18:34:14 UTC 24699 5b923b1c.607b 12093970
> > [0]:LOG:  worker process: logical replication worker for
> > subscription 37932 (PID 8657) exited with exit code 1
> >
> > While it seems to be a network issue, it is may be not - we have
> > checked the network and even monitoring, all the time some packets
> > were exchanged.
> >
> > We do have 3 subscriptions(thus repl. slots) for one publication, one
> > subscriber instance is within same datacenter as master, remainig
> > subscribers are remote.
> >
> >
> >>> select * from pg_replication_slots
> >
> ++--+---++-+---+++--+--+--+-+
> > | slot_name  | plugin   | slot_type | datoid | database|
> > temporary | active | active_pid | xmin | catalog_xmin | restart_lsn
> > | confirmed_flush_lsn |
> >
> ++--+---++-+---+++--+--+--+-+
> > | sub_usd| pgoutput | logical   | 16421  | master_prod |
> > False | True   | 16604  |  | 5536488  | 426/AAE55A68
> > | 426/AAE55A68|
> > | sub_cad| pgoutput | logical   | 16421  | master_prod |
> > False | True   | 22875  |  | 5536488  | 426/AAE55A68
> > | 426/AAE55A68|
> > | sub_eur| pgoutput | logical   | 16421  | master_prod |
> > False | True   | 16605  |  | 5536488  | 426/AAE55A68
> > | 426/AAE55A68|
> >
> ++--+---++-+---+++--+--+--+-+
> >
> >
> > Once  after the error occurs, wal senders are re/started and they
> > reads wal files until they reach restart_lsn wal f

Re: Logical replication hangs up.

[Aleš Zelený]

 = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-6900.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-6A00.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-6B00.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-6C00.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-6D00.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-6E00.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-6F00.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7000.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7100.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7200.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7300.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7400.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7500.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7600.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7700.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7800.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489825-lsn-429-7900.snap",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("pg_replslot/sub_anl_master_usd/xid-6489826-lsn-429-6200.snap",
O_RDONLY) = 28
read(28, "\334\0\0\0\0\0\0\0\370^Tb)\4\0\0\0\0\0\0\0\0\0\0\177\6\0\0%@\0\0"...,
72) = 72
read(28, "|\0\0\0\377\377\377\377\0\0\0\0\0\0\0\0p'
\17\316U\0\0\0\0\0\0\0\0\0\0"..., 148) = 148
read(28, "", 72)= 0
close(28)   = 0

there are no error messages in postgres log indicating missng WAL to be
decoded... as I've mentioned:

I've copied databases to different machine for investigation and it behaves
same way there:

LOG:  replication connection authorized: user=repusr SSL enabled
(protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, compression=off)
LOG:  starting logical decoding for slot "sub_usd"
DETAIL:  streaming transactions committing after 426/AAE55A68, rea
ding WAL from 426/AAE55A68
LOG:  logical decoding found consistent point at 426/AAE55A68
DETAIL:  There are no running transactions.

So it look-like it takes too long to checks for all xid/lsn snap files and
it seems to be the reason.

And at least with upgraded Postgres to 10.5 having both timeouts set to 10
minutes replication was able to cross the "magic freezing" LSN.

If there will be a change, I'll try to test it with 10.4 (as what we do
have on prod) to see whether timeouts were solution or upgrade to 10.5 was
also necessary.

it consumes reasonable amount of memory:
db:~$ ps -u -p 4232
USER   PID %CPU %MEMVSZ   RSS TTY  STAT START   TIME COMMAND
postgres  4232 12.2 23.9 16202616 7636624 ?Ds   21:38   8:32 postgres:
anl_master_prod: wal sender process repusr 10.30.100.77(60866) idle

and from logs we know that sever starts swapping (there are usually 4GB of
free memory), therefore load raises and whole response time become bad and
could be why we start hitting timeouts (and due to high volume of WAL).

It terminates after the 10 minutes timeout, but it was able to confirm
higher restart_lsn, so next round did not start at 18GB of WAL but only on
4GB of and finally get streaming state.

After the restart wal sender (having to process much less volume of WAL)
sucees to reach streaming state and it also consumes reasonable amount of
memory:

db:~$ ps -u -p 4232
USER   PID %CPU %MEMVSZ   RSS TTY  STAT START   TIME COMMAND
postgres  4232 12.2 23.9 16202616 7636624 ?Ds   21:38   8:32 postgres:
anl_master_prod: wal sender process repusr 10.30.100.77(60866) idle

Thanks a lot to all inputs! 10.5 and raised both timeouts seems to be
solution.

Kind regards Ales Zeleny

po 5. 11. 2018 v 10:26 odesílatel Achilleas Mantzios <
ach...@matrix

Logical replication did not use primary key as replica identity

[Aleš Zelený]

Hello,

we are using logical replication for half a year and now, when we were
adding new tables to replication, we have found a unexpected issue in log
file.

New tables were created on publication database (Ubuntu 16.04, PG 10.6) ,
subscription side is PostgreSQL 10.4 (Ubuntu 10.4-2.pgdg16.04+1) on
x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.9) 5.4.0
20160609, 64-bit.

I've realized, that by a mistake, there were UNIQUE index and primary key
on same set of columns, but dropping unintended unique index and refreshing
subscription did not helped. Also manually defining replica identity did
not resolve the issue. Tables are identical on publisher and subscriber
databases.

postgres=# \c stage_dev
You are now connected to database "stage_dev" as user "postgres".
stage_dev=# \d stage_data.asset_info
Table "stage_data.asset_info"
Column |Type | Collation | Nullable
| Default
---+-+---+--+-
 asset_id  | bytea   |   | not null
|
 call_code | character(3)|   | not null
|
 price_final   | double precision|   |
|
 primary_code_id   | integer |   | not null
|

 updmgr_last_chg_dt| timestamp without time zone |   |
|
Indexes:
"asset_info_pkey" PRIMARY KEY, btree (asset_id, primary_code_id,
call_code)
"asset_info_key" UNIQUE, btree (asset_id, primary_code_id, call_code)
"asset_info_updmgr_idx" btree (updmgr_last_chg_dt) WHERE
updmgr_last_chg_dt IS NOT NULL
Publications:
"pub_stage_dev"

stage_dev=# alter table stage_data.asset_info replica identity using INDEX
asset_info_pkey;
ALTER TABLE
stage_dev=#

Subscription refresh did not helped, neither dropping the mistaken unique
index.

2018-11-18 19:09:31 UTC 22142 5bf1b8df.567e 3 [local] anl_master_dev
postgres 0 14/6766 psql idle [0]:LOG:  statement: alter subscription
sub_stage_dev refresh publication ;

2018-11-18 19:12:22 UTC 23427 5bf1b996.5b83 10 8/40767   [0]:LOG:
logical replication apply worker for subscription "sub_stage_dev" has
started

2018-11-18 19:12:22 UTC 23427 5bf1b996.5b83 20 8/40771
[55000]:ERROR:  logical replication target relation "stage_data.asset_info"
has neither REPLICA IDENTITY index nor PRIMARY KEY and published relation
does not have REPLICA IDENTITY FULL

Any advices, how to find out what I've done wrong and how to resolve the
issue are welcomed. Also I'm interested, why PK is not classified as
suitable replica identity.

Kind regards Ales Zeleny

Logical replication issue with row level trigger

[Aleš Zelený]

Hello,

I've found an issue with logical replication causing
1) large memory allocation by wal sender process (RSS 60GB)
2) large amount of "xid" files in $PGDATA/pg_replslot/
directory - seems to be amount of rows handled by trigger + few more

Having several millions of files in a single directory for replication slot
makes it hard to work on (tested ext4 and zfs).
Regarding the memory - such large allocation was no expected and as result
swap was used with all performance impact expected.

Environment and conditions to reproduce:

PostgreSQL 10.6 (Ubuntu 10.6-1.pgdg16.04+1) on x86_64-pc-linux-gnu,
compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.10) 5.4.0 20160609, 64-bit

create trigger function with:
1) DML modifying data in another table
2) use EXCEPTION clause (implicit subtransaction [
https://www.postgresql.org/docs/10/plpgsql-structure.html])

Note, that is does not matter, whether tables used for testcase are
replicated or no (this is what I use in testcase).

# publication side
pg_createcluster -d /pgsql/pgclusterzfs/i_pub/10/ipub -p 5532 10 ipub -- -k
pg_ctlcluster 10 ipub start
psql -p 5532 -c "alter system set wal_level=logical;"
pg_ctlcluster 10 ipub restart

psql -p 5532 <

Logical replication - DDL sub transactions for script executed in single transaction?

[Aleš Zelený]

Hello,

I've learned that logical replication might have performance problem if
there are lot of sub transactions within transaction (at least because it
enforces spill files in pg_replslot and if there are many - like 80mio,
EXT4 did not perform  well - in my case it was caused bu misuse of
exception handling in trigger function) and once we get rid of this usage
pattern logical replication works like a charm.
Until we have applied schema migration patch creating 700+ tables by
flyway, therefore whole file was applied in single transaction (like psql
-1 -f ) and it effectively blocked our replication for 22 hours. No
failures, wal sender processed did not consumed huge amount of memory (what
happened in past wiht 80mi sub-trans caused by trigger), all wal senders
did IO very rarely, most of the time they dwell on CPU.

The spill files were not so big:
# du -sh xid-924361123-lsn-FBC-C700.snap
224Kxid-924361123-lsn-FBC-C700.snap

It takes about 1 minute (all the time 100% CPU used by was sender) to move
to following file.

Version, OS:
PostgreSQL 10.6 (Ubuntu 10.6-1.pgdg16.04+1) on x86_64-pc-linux-gnu,
compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.10) 5.4.0 20160609, 64-bit

Perf:
Overhead  Command   Shared Object  Symbol
  57.79%  postgres  postgres   [.] hash_seq_search
  14.70%  postgres  postgres   [.] hash_search_with_hash_value
   5.93%  postgres  postgres   [.] LocalExecuteInvalidationMessage
   3.60%  postgres  postgres   [.] RelfilenodeMapInvalidateCallback
   2.99%  postgres  postgres   [.] hash_uint32
   2.50%  postgres  postgres   [.] hash_search
   1.91%  postgres  postgres   [.] CatCacheInvalidate
   1.83%  postgres  postgres   [.] CallSyscacheCallbacks
   1.37%  postgres  postgres   [.] hash_seq_init
   1.24%  postgres  postgres   [.] hash_seq_term
   1.02%  postgres  postgres   [.] RelationCacheInvalidateEntry
   0.97%  postgres  postgres   [.] ReorderBufferCommit
   0.97%  postgres  pgoutput.so[.] rel_sync_cache_relation_cb
   0.78%  postgres  postgres   [.] uint32_hash
   0.73%  postgres  postgres   [.] PlanCacheRelCallback
   0.60%  postgres  postgres   [.] InvalidateCatalogSnapshot
   0.58%  postgres  postgres   [.] SysCacheInvalidate
   0.35%  postgres  postgres   [.] GetCurrentTransactionNestLevel
   0.13%  postgres  pgoutput.so[.] _init
   0.00%  postgres  [kernel.kallsyms]  [k] __do_softirq
   0.00%  postgres  [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
   0.00%  postgres  postgres   [.] ResourceOwnerEnlargeRelationRefs

My suspect is that psql (of flyway) while processing a file with many
create table and grant statements in single transaction mode might create
sub transactions, but I haven't found it in docs.

Does you have similar experience? What is root cause for this issue?

Workaround is clear - do not create that large amount of DDL in single
transaction, but it would be nice to know root cause to eliminate
scripts/usage patterns causing this issue generally.

On the other hand, following transaction (100GB of spill files) , almost
150 mio rows deleted (and archived by statement trigger) behaves expected
way - wal sender process was reading from disk (something like 130MB/s) and
after ~20 minutes replication was in sync, all spill files were removed, so
transaction changes volume itself does not seems to be any issue.

Thanks for any advice!

Kind regards Ales Zeleny
P.S.: PostgreSQL log facility is superb, having DDL statements logged and
XID in log line prefix I was able to identify the issue source in this case.

Streaming replica failure

[Aleš Zelený]

Hello,

we are using PostgreSQL 12.4 on CentOS 7. The hot standby failed:

2021-04-24 09:19:27 CEST [20956]: [747-1] user=,db=,host=,app= LOG:
 recovery restart point at 3D8C/352B4CE8
2021-04-24 09:19:27 CEST [20956]: [748-1] user=,db=,host=,app= DETAIL:
 Last completed transaction was at log time 2021-04-24 09:19:27.221313+02.
2021-04-24 09:20:57 CEST [20956]: [749-1] user=,db=,host=,app= LOG:
 restartpoint starting: time
2021-04-24 09:24:27 CEST [20956]: [750-1] user=,db=,host=,app= LOG:
 restartpoint complete: wrote 171233 buffers (13.4%); 0 WAL file(s) added,
68 removed, 0 recycled; write
=209.663 s, sync=0.012 s, total=209.963 s; sync files=283, longest=0.001 s,
average=0.000 s; distance=684762 kB, estimate=684762 kB
2021-04-24 09:24:27 CEST [20956]: [751-1] user=,db=,host=,app= LOG:
 recovery restart point at 3D8C/5EF6B858
2021-04-24 09:24:27 CEST [20956]: [752-1] user=,db=,host=,app= DETAIL:
 Last completed transaction was at log time 2021-04-24 09:24:27.288115+02.
2021-04-24 09:25:15 CEST [20955]: [11-1] user=,db=,host=,app= WARNING:
 page 366603 of relation base/20955/10143636 is uninitialized
2021-04-24 09:25:15 CEST [20955]: [12-1] user=,db=,host=,app= CONTEXT:  WAL
redo at 3D8C/D79F6500 for Heap2/VISIBLE: cutoff xid 3806260577 flags 0x01
2021-04-24 09:25:15 CEST [20955]: [13-1] user=,db=,host=,app= PANIC:  WAL
contains references to invalid pages
2021-04-24 09:25:15 CEST [20955]: [14-1] user=,db=,host=,app= CONTEXT:  WAL
redo at 3D8C/D79F6500 for Heap2/VISIBLE: cutoff xid 3806260577 flags 0x01
2021-04-24 09:25:16 CEST [20953]: [11-1] user=,db=,host=,app= LOG:  startup
process (PID 20955) was terminated by signal 6: Neúspěšně ukončen (SIGABRT)
2021-04-24 09:25:16 CEST [20953]: [12-1] user=,db=,host=,app= LOG:
 terminating any other active server processes

The relation base/20955/10143636 is a standard table.

Version details:
postgres=# select version();
 version

-
 PostgreSQL 12.4 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5
20150623 (Red Hat 4.8.5-39), 64-bit
(1 row)

Settings:
postgres=# select name, setting, category from pg_settings where category =
'Write-Ahead Log / Settings';
  name  |  setting  |  category
+---+
 commit_delay   | 0 | Write-Ahead Log / Settings
 commit_siblings| 5 | Write-Ahead Log / Settings
 fsync  | on| Write-Ahead Log / Settings
 full_page_writes   | on| Write-Ahead Log / Settings
 synchronous_commit | on| Write-Ahead Log / Settings
 wal_buffers| 2048  | Write-Ahead Log / Settings
 wal_compression| off   | Write-Ahead Log / Settings
 wal_init_zero  | on| Write-Ahead Log / Settings
 wal_level  | logical   | Write-Ahead Log / Settings
 wal_log_hints  | off   | Write-Ahead Log / Settings
 wal_recycle| on| Write-Ahead Log / Settings
 wal_sync_method| fdatasync | Write-Ahead Log / Settings
 wal_writer_delay   | 200   | Write-Ahead Log / Settings
 wal_writer_flush_after | 128   | Write-Ahead Log / Settings
(14 rows)

pg_waldump output:
-bash-4.2$ /usr/pgsql-12/bin/pg_waldump 00013D8C00D7 2>&1 | tail
rmgr: Btree   len (rec/tot): 64/64, tx: 3812802559, lsn:
3D8C/D7CF5A98, prev 3D8C/D7CF5A58, desc: INSERT_LEAF off 360, blkref #0:
rel 1663/20955/11280092 blk 19
509
rmgr: Transaction len (rec/tot): 46/46, tx: 3812802557, lsn:
3D8C/D7CF5AD8, prev 3D8C/D7CF5A98, desc: COMMIT 2021-04-24 09:25:16.160687
CEST
rmgr: Heaplen (rec/tot):159/   159, tx: 3812802559, lsn:
3D8C/D7CF5B08, prev 3D8C/D7CF5AD8, desc: INSERT off 8 flags 0x08, blkref
#0: rel 1663/20955/11280066 bl
k 165603
rmgr: Btree   len (rec/tot): 64/64, tx: 3812802559, lsn:
3D8C/D7CF5BA8, prev 3D8C/D7CF5B08, desc: INSERT_LEAF off 317, blkref #0:
rel 1663/20955/11280073 blk 15
340
rmgr: Btree   len (rec/tot): 64/64, tx: 3812802559, lsn:
3D8C/D7CF5BE8, prev 3D8C/D7CF5BA8, desc: INSERT_LEAF off 130, blkref #0:
rel 1663/20955/11280091 blk 22
003
rmgr: Heaplen (rec/tot): 80/80, tx: 3812802559, lsn:
3D8C/D7CF5C28, prev 3D8C/D7CF5BE8, desc: INSERT off 61 flags 0x08, blkref
#0: rel 1663/20955/11280082 b
lk 38917
rmgr: Btree   len (rec/tot): 64/64, tx: 3812802559, lsn:
3D8C/D7CF5C78, prev 3D8C/D7CF5C28, desc: INSERT_LEAF off 73, blkref #0: rel
1663/20955/11280088 blk 421
25
rmgr: Btree   len (rec/tot): 64/64, tx: 3812802559, lsn:
3D8C/D7CF5CB8, prev 3D8C/D7CF5C78, desc: INSERT_LEAF off 361, blkref #0:
rel 1663/20955/11280092 blk 19
509
rmgr: Transaction len (rec/tot): 46/46, tx: 3812802559, lsn:
3D8C/D7CF5CF8, prev 3D8C/D7CF5CB8, desc: COMMIT 2021-04-24 09:25:16.161036
CEST
pg_waldump: fatal: er

RPM package issue

[Aleš Zelený]

Hello all,

I've found on the wiki ( https://wiki.postgresql.org/wiki/Packagers ) that
the packagers list Is closed, so the first question is how to properly
report a package issue?

Particularly I've realized, that in the repository list
/etc/yum.repos.d/pgdg-redhat-all.repo provided by
https://download.postgresql.org/pub/repos/yum/reporpms/EL-7-x86_64/pgdg-redhat-repo-latest.noarch.rpm
pgdg14-updates-debuginfo repository definition is missing.

Tested on CentOS7 VM:

[root@centos7-base ~]# yum -y repolist --enablerepo=pgdg*
...
repo id

repo name


status
base/7/x86_64

CentOS-7 - Base


10 072
epel/x86_64

Extra Packages for Enterprise Linux 7 - x86_64


 13 687
extras/7/x86_64

CentOS-7 - Extras


 500
pgdg-common/7/x86_64

 PostgreSQL common RPMs for RHEL/CentOS 7 - x86_64


 342
pgdg-common-srpm-testing/7/x86_64

PostgreSQL common testing SRPMs for RHEL/CentOS 7 -
x86_64

189
pgdg-common-testing/7/x86_64

 PostgreSQL common testing RPMs for RHEL/CentOS 7 -
x86_64

 342
pgdg-source-common/7/x86_64

PostgreSQL 12 for RHEL/CentOS 7 - x86_64 - Source


 189
pgdg10/7/x86_64

PostgreSQL 10 for RHEL/CentOS 7 - x86_64


1 003
pgdg10-source/7/x86_64

 PostgreSQL 10 for RHEL/CentOS 7 - x86_64 - Source


 519
pgdg10-updates-debuginfo/7/x86_64

PostgreSQL 10 for RHEL/CentOS 7 - x86_64 -
Debuginfo

405
pgdg11/7/x86_64

PostgreSQL 11 for RHEL/CentOS 7 - x86_64


1 111
pgdg11-source/7/x86_64

 PostgreSQL 11 for RHEL/CentOS 7 - x86_64 - Source


 535
pgdg11-source-updates-testing/7/x86_64

 PostgreSQL 11 for RHEL/CentOS 7 - x86_64 - Source
update testing

0
pgdg11-updates-debuginfo/7/x86_64

PostgreSQL 11 for RHEL/CentOS 7 - x86_64 -
Debuginfo

411
pgdg11-updates-testing/7/x86_64

PostgreSQL 11 for RHEL/CentOS 7 - x86_64 - Updates
testing

  6
pgdg11-updates-testing-debuginfo/7/x86_64

PostgreSQL 11 for RHEL/CentOS 7 - x86_64 -
Debuginfo

  1
pgdg12/7/x86_64

PostgreSQL 12 for RHEL/CentOS 7 - x86_64


693
pgdg12-source/7/x86_64

 PostgreSQL 12 for RHEL/CentOS 7 - x86_64 - Source


 379
pgdg12-source-updates-testing/7/x86_64

 PostgreSQL 12 for RHEL/CentOS 7 - x86_64 - Source
update testing

0
pgdg12-updates-debuginfo/7/x86_64

PostgreSQL 12 for RHEL/CentOS 7 - x86_64 -
Debuginfo

283
pgdg12-updates-testing/7/x86_64

PostgreSQL 12 for RHEL/CentOS 7 - x86_64 - Updates
testing

  0
pgdg12-updates-testing-debuginfo/7/x86_64

PostgreSQL 12 for RHEL/CentOS 7 - x86_64 -
Debuginfo

  0
pgdg13/7/x86_64

PostgreSQL 13 for RHEL/CentOS 7 - x86_64


436
pgdg13-source-updates-testing/7/x86_64

 PostgreSQL 13 for RHEL/CentOS 7 - x86_64 - Source
updates testing

   0
pgdg13-updates-debuginfo/7/x86_64

PostgreSQL 13 for RHEL/CentOS 7 - x86_64 -
Debuginfo

176
pgdg13-updates-testing/7/x86_64

PostgreSQL 13 for RHEL/CentOS 7 - x86_64 - Updates
testing

  0
pgdg13-updates-testing-debuginfo/7/x86_64

PostgreSQL 13 for RHEL/CentOS 7 - x86_64 -
Debuginfo

  0
pgdg14/7/x86_64

PostgreSQL 14 for RHEL/CentOS 7 - x86_64


173
pgdg14-source-updates-testing/7/x86_64

 PostgreSQL 14 for RHEL/CentOS 7 - x86_64 - Source
updates testing

   0
pgdg14-updates-testing/7/x86_64

PostgreSQL 14 for RHEL/CentOS 7 - x86_64 - Updates
testing

  1
pgdg14-updates-testing-debuginfo/7/x86_64

PostgreSQL 14 for RHEL/CentOS 7 - x86_64 -
Debuginfo

  1
pgdg15-updates-testing/7/x86_64

PostgreSQL 15 for RHEL/CentOS 7 - x86_64 - Updates
testing

 77
pgdg96/7/x86_64

PostgreSQL 9.6 for RHEL/CentOS 7 - x86_64


 959
pgdg96-source/7/x86_64

 PostgreSQL 9.6 for RHEL/CentOS 7 - x86_64 - Source


481
pgdg96-updates-debuginfo/7/x86_64

PostgreSQL 9.6 for RHEL/CentOS 7 - x86_64 -
Debuginfo

   394
updates/7/x86_64

 CentOS-7 - Updates


2 963
repolist: 36 328

[root@centos7-base ~]# yum -y info postgresql14-debuginfo
Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile
 * base: mirror.karneval.cz
 * epel: mirror.karneval.cz
 * extras: mirror.karneval.cz
 * updates: mirror.karneval.cz
Error: No matching Packages to list


Adding the missing repository section:

# Debuginfo/debugsource packages for stable repos

Re: RPM package issue

[Aleš Zelený]

Hi Adrian,

thanks for the hint!

Ales

st 24. 11. 2021 v 18:16 odesílatel Adrian Klaver 
napsal:

> On 11/24/21 08:47, Aleš Zelený wrote:
> > Hello all,
> >
> > I've found on the wiki ( https://wiki.postgresql.org/wiki/Packagers
> > <https://wiki.postgresql.org/wiki/Packagers> ) that the packagers list
> > Is closed, so the first question is how to properly report a package
> issue?
>
> https://www.postgresql.org/download/linux/redhat/ -->:
>
> https://yum.postgresql.org/ -->:
>
> https://yum.postgresql.org/contact/
>
> Or issue tracker:
>
> https://redmine.postgresql.org/projects/pgrpms/
>
> though you will need to setup/have a Postgres community account to access.
>
> >
> > Particularly I've realized, that in the repository list
> > /etc/yum.repos.d/pgdg-redhat-all.repo provided by
> >
> https://download.postgresql.org/pub/repos/yum/reporpms/EL-7-x86_64/pgdg-redhat-repo-latest.noarch.rpm
> > <
> https://download.postgresql.org/pub/repos/yum/reporpms/EL-7-x86_64/pgdg-redhat-repo-latest.noarch.rpm>
>
> >
> > pgdg14-updates-debuginfo repository definition is missing.
>
> > Kind regards Ales Zeleny
>
>
> --
> Adrian Klaver
> adrian.kla...@aklaver.com
>

Re: PostgreSQL 17.5 - could not map dynamic shared memory segment

[Aleš Zelený]

Hi,
Thanks for the good point:

$ sysctl vm.overcommit_memory
vm.overcommit_memory = 0

That is a difference, the old pg11 running on Ubuntu 18.4 had
disabled overcommit  (vm.overcommit_memory = 2).

Anyway, on a dedicated DB server box with 123GB RAM running only vacuum (14
parallel processes (2GB maintenance workmen)) and shared buffers 22GB seems
to me unlikely to hit available memory.

During Sunday (low load) and Monday so far, it has not reoccurred.

Kind regards Ales Zeleny

ne 22. 6. 2025 v 0:44 odesílatel Tomas Vondra  napsal:

> On 6/21/25 23:09, Aleš Zelený wrote:
> > Hello,
> > ...
> >
> > The application benefits from parallel queries, so despite the first
> > temptation to disable parallel queries (based on log entries correlation
> > only, but is that the root cause?) I did not want to disable parallel
> > queries, if there is another workaround/solution/fix available.
> >
> > Thanks for any hints on how to provide more information if needed, as
> > well as for fix/workaround advice.
> >
>
> Could it be that you simply ran out of memory, or perhaps hit the
> overcommit? What does sysctl say?
>
>   sysctl vm.overcommit_memory
>
> And what's CommitLimit/Committed_AS in /proc/meminfo? IIRC the shmem is
> counted against the limit, and if the system does not have significant
> swap, it's not uncommon to hit that (esp. with overcommit_memory=2).
>
>
> regards
>
> --
> Tomas Vondra
>
>

PostgreSQL 17.5 - could not map dynamic shared memory segment

[Aleš Zelený]

Hello,

After upgrading from (old good no longer supported Pg11) to PostgreSQL 17.5
via pg_dump & pg_restore vacuum started reporting errors:

ERROR:  could not map dynamic shared memory segment

Vacuumdb was invoked:

/usr/lib/postgresql/17/bin/vacuumdb -p 5433 -Fvaz -j 12 -v

The vacuum finished exit code was 0, but in PostgreSQL instance log files,
the errors above were logged.

Example error messages from the PostgreSQL log file:
2025-06-21 16:29:56.095 UTC [306130] ERROR:  could not map dynamic shared
memory segment
2025-06-21 16:29:56.095 UTC [306131] ERROR:  could not map dynamic shared
memory segment
2025-06-21 16:29:56.097 UTC [135978] LOG:  background worker "parallel
worker" (PID 306130) exited with exit code 1
2025-06-21 16:29:56.097 UTC [135978] LOG:  background worker "parallel
worker" (PID 306131) exited with exit code 1
2025-06-21 16:30:23.677 UTC [300930] postgres@fin LOG:  could not send data
to client: Broken pipe
2025-06-21 16:30:23.677 UTC [300930] postgres@fin CONTEXT:  while scanning
relation "core.cusip"
2025-06-21 16:30:23.677 UTC [300930] postgres@fin STATEMENT:  VACUUM
(SKIP_DATABASE_STATS, FREEZE, VERBOSE) core.cusip;
2025-06-21 16:30:23.677 UTC [300930] postgres@fin FATAL:  connection to
client lost
2025-06-21 16:30:23.677 UTC [300930] postgres@fin CONTEXT:  while scanning
relation "core.cusip"
2025-06-21 16:30:23.677 UTC [300930] postgres@fin STATEMENT:  VACUUM
(SKIP_DATABASE_STATS, FREEZE, VERBOSE) core.cusip;
2025-06-21 16:30:23.678 UTC [306190] ERROR:  could not map dynamic shared
memory segment
2025-06-21 16:30:23.680 UTC [135978] LOG:  background worker "parallel
worker" (PID 306190) exited with exit code 1

PostgreSQL version:
psql -d postgres -c "select version();"
  version

---
 PostgreSQL 17.5 (Ubuntu 17.5-1.pgdg22.04+1) on x86_64-pc-linux-gnu,
compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit
(1 row)

Configuration parameters:
listen_addresses = '*' # what IP address(es) to listen on;
port = 5432 # (change requires restart)
max_connections = 400 # (change requires restart)
unix_socket_directories = '/var/run/postgresql' # comma-separated list of
directories
tcp_keepalives_idle = 60 # TCP_KEEPIDLE, in seconds;
tcp_keepalives_interval = 5 # TCP_KEEPINTVL, in seconds;
tcp_keepalives_count = 3 # TCP_KEEPCNT;
tcp_user_timeout = 75s # TCP_USER_TIMEOUT, in milliseconds;
client_connection_check_interval = 75s # time between checks for client
shared_buffers = 22GB # min 128kB
huge_pages = on # on, off, or try
temp_buffers = 32MB # min 800kB
work_mem = 64MB # min 64kB
maintenance_work_mem = 2GB # min 64kB
dynamic_shared_memory_type = posix # the default is usually the first option
bgwriter_delay = 10ms # 10-1ms between rounds
bgwriter_lru_maxpages = 1000 # max buffers written/round, 0 disables
bgwriter_lru_multiplier = 10.0 # 0-10.0 multiplier on buffers scanned/round
max_worker_processes = 24 # (change requires restart)
wal_level = logical # minimal, replica, or logical
wal_log_hints = on # also do full page writes of non-critical updates
checkpoint_timeout = 30min # range 30s-1d
checkpoint_completion_target = 0.8 # checkpoint target duration, 0.0 - 1.0
max_wal_size = 120GB
min_wal_size = 10GB
archive_timeout = 1800 # force a WAL file switch after this
max_wal_senders = 12 # max number of walsender processes
max_replication_slots = 12 # max number of replication slots
wal_sender_timeout = 600s # in milliseconds; 0 disables
track_commit_timestamp = on # collect timestamp of transaction commit
wal_receiver_timeout = 600s # time that receiver waits for
jit = off # allow JIT compilation
log_min_duration_statement = 1000 # -1 is disabled, 0 logs all statements
log_autovacuum_min_duration = 0 # log autovacuum activity;
log_checkpoints = on
track_activity_query_size = 32768 # (change requires restart)
track_io_timing = on
track_functions = all # none, pl, all
idle_in_transaction_session_timeout = 120 # in milliseconds, 0 is
disabled
shared_preload_libraries =
'pg_stat_statements,pg_stat_kcache,pg_qualstats,pg_partman_bgw,pg_cron,pg_prewarm'
# (change requires restart)
max_locks_per_transaction = 128 # min 10


OS: Ubuntu 22.04.5 LTS, 16vCPUs, ~123 GB RAM
PostgreSQL apt package: postgresql-17/jammy-pgdg,now 17.5-1.pgdg22.04+1
amd64 [installed]

Memory:
grep -e Mem -e Huge /proc/meminfo
MemTotal:   129804320 kB
MemFree: 2127576 kB
MemAvailable:   100695068 kB
AnonHugePages: 0 kB
ShmemHugePages:0 kB
FileHugePages: 0 kB
HugePages_Total:   12672
HugePages_Free:10908
HugePages_Rsvd: 9818
HugePages_Surp:0
Hugepagesize:   2048 kB
Hugetlb:25952256 kB

It also happened during the application load test, but I've accidentally
copied a wrong log file, and now the server is decommissioned, so I have no
details on application que