WAL-files is not removing authomaticaly
Hello,
Have Streaming replica with 2 hosts, master and slave with PostgreSQL 10.6.
Replica works fine and data from master copying to slave without any
problem,
but on slave have a problem: wal-files in catalog ${PGDATA}/pg_wal is not
removing authomaticaly and may be collects over some years.
Both, master (1.1.1.1) and slave (2.2.2.2), have simmilar replication slots:
master=# select * from pg_replication_slots;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
---------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+---------------------
standby_slot | | physical | | | f | t
| 1184 | | | 8/1C16C508 |
(1 row)
slave=# select * from pg_replication_slots;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
---------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+---------------------
standby_slot | | physical | | | f | t
| 1184 | | | 8/1C16C508 |
(1 row)
which seted in ${PGDATA}/recovery.done on master:
standby_mode = 'on'
primary_conninfo = 'user=pgadmin host=1.1.1.1 port=5432 user=pgadmin
sslmode=prefer sslcompression=1'
recovery_target_timeline = 'latest'
trigger_file = 'failover'
restore_command = 'cp /opt/archivelog/%f %p'
archive_cleanup_command = '/usr/pgsql-10/bin/pg_archivecleanup
/opt/archivelog %r'
primary_slot_name = 'standby_slot'
and seted in ${PGDATA}/recovery.conf on slave:
standby_mode = 'on'
primary_conninfo = 'user=pgadmin host=2.2.2.2 port=5432 user=pgadmin
sslmode=prefer sslcompression=1'
recovery_target_timeline = 'latest'
trigger_file = 'failover'
restore_command = 'cp /opt/archivelog/%f %p'
archive_cleanup_command = '/usr/pgsql-10/bin/pg_archivecleanup
/opt/archivelog %r'
primary_slot_name = 'standby_slot'
Both archive_cleanup_command's on both hosts works fine in console and no
needs to set permissions on /opt/archivelog or
/usr/pgsql-10/bin/pg_archivecleanup.
In ${PGDATA}/postgresql.conf on both hosts sets:
max_wal_size = 8GB
wal_keep_segments = 32
But yesterday pg_wal was 16G and had 1018 files inside, thats why there was
no other way except deleting its manualy, but not of all,
just 6 hundreds files, which had modification time before September 2020
except 000000010000000000000034.00000028.backup.
Trying to rebuild slave from master with: making pg_start_backup, copying
${PGDATA} files from master to slave (without removing on slave any files
in ${PGDATA}),
pg_stop_backup, tunning settings on slave and run it again had no any
success, wal-files still is not removing automaticaly.
Does anybody knows how to fix it ?
Regards, Andrew
On Wed, 2021-03-10 at 14:34 +0200, Forum Writer wrote:
Have Streaming replica with 2 hosts, master and slave with PostgreSQL 10.6.
Replica works fine and data from master copying to slave without any problem,
but on slave have a problem: wal-files in catalog ${PGDATA}/pg_wal is not
removing authomaticaly and may be collects over some years.Both, master (1.1.1.1) and slave (2.2.2.2), have simmilar replication slots:
master=# select * from pg_replication_slots;
slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn
---------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+---------------------
standby_slot | | physical | | | f | t | 1184 | | | 8/1C16C508 |
(1 row)and seted in ${PGDATA}/recovery.conf on slave:
standby_mode = 'on'
primary_conninfo = 'user=pgadmin host=2.2.2.2 port=5432 user=pgadmin sslmode=prefer sslcompression=1'
recovery_target_timeline = 'latest'
trigger_file = 'failover'
restore_command = 'cp /opt/archivelog/%f %p'
archive_cleanup_command = '/usr/pgsql-10/bin/pg_archivecleanup /opt/archivelog %r'
primary_slot_name = 'standby_slot'In ${PGDATA}/postgresql.conf on both hosts sets:
max_wal_size = 8GB
wal_keep_segments = 32But yesterday pg_wal was 16G and had 1018 files inside, thats why there was no other
way except deleting its manualy, but not of all,
just 6 hundreds files, which had modification time before September 2020 except
000000010000000000000034.00000028.backup.
Trying to rebuild slave from master with: making pg_start_backup, copying ${PGDATA}
files from master to slave (without removing on slave any files in ${PGDATA}),
pg_stop_backup, tunning settings on slave and run it again had no any success,
wal-files still is not removing automaticaly.
Does anybody knows how to fix it ?
Never, ever, remove WAL files manually.
A crash might render your database unrecoverable.
You'll have to figure out what is blocking WAL removal.
Are there archive failures reported in "pg_stat_archiver" and the log?
You say that replication is working fine, but try
SELECT pg_current_wal_lsn();
on the primary and compare that with the "restart_lsn" of the replication slot.
Look for strange messages in the log file on both servers.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
Never, ever, remove WAL files manually.
A crash might render your database unrecoverable.
You're right, it's not a good idea.
You'll have to figure out what is blocking WAL removal.
This is my favorite dream!
Are there archive failures reported in "pg_stat_archiver" and the log?
master=# select * from pg_stat_archiver;
archived_count | last_archived_wal | last_archived_time
| failed_count | last_failed_wal | last_failed_time | stats_reset
----------------+--------------------------+-------------------------------+--------------+-----------------+------------------+------------------------------
3021 | 000000010000000B000000C9 | 2021-03-11 08:53:56.133796+02
| 0 | | | 2021-01-06
14:33:40.70147+02
(1 row)
In today's logs there is no any errors:
$ grep "FATAL\|WARNING" /opt/pglogs/master.log
$
$ grep "FATAL\|WARNING" /opt/pglogs/slave.log
$
You say that replication is working fine, but try
SELECT pg_current_wal_lsn();
on the primary and compare that with the "restart_lsn" of the replication
slot.
It parameters is differ:
master=# SELECT pg_current_wal_lsn();
pg_current_wal_lsn
--------------------
B/CB099398
(1 row)
master=# select * from pg_replication_slots;
slot_name | plugin | slot_type | datoid | database | temporary
| active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
----------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+---------------------
standby_slot | | physical | | | f | t
| 2631806 | | | B/CB0AC068 |
(1 row)
But when I add new data to the table on master, it apears on slave.
Look for strange messages in the log file on both servers.
Looking for strange messages gives nothing, in today's logs there is no any
strange messages, just about connects of applications.
Regards, Andrew
ср, 10 мар. 2021 г. в 19:40, Laurenz Albe <laurenz.albe@cybertec.at>:
Show quoted text
On Wed, 2021-03-10 at 14:34 +0200, Forum Writer wrote:
Have Streaming replica with 2 hosts, master and slave with PostgreSQL
10.6.
Replica works fine and data from master copying to slave without any
problem,
but on slave have a problem: wal-files in catalog ${PGDATA}/pg_wal is not
removing authomaticaly and may be collects over some years.Both, master (1.1.1.1) and slave (2.2.2.2), have simmilar replication
slots:
master=# select * from pg_replication_slots;
slot_name | plugin | slot_type | datoid | database |temporary | active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn---------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+---------------------
standby_slot | | physical | | | f | t
| 1184 | | | 8/1C16C508 |
(1 row)
and seted in ${PGDATA}/recovery.conf on slave:
standby_mode = 'on'
primary_conninfo = 'user=pgadmin host=2.2.2.2 port=5432 user=pgadminsslmode=prefer sslcompression=1'
recovery_target_timeline = 'latest'
trigger_file = 'failover'
restore_command = 'cp /opt/archivelog/%f %p'
archive_cleanup_command = '/usr/pgsql-10/bin/pg_archivecleanup/opt/archivelog %r'
primary_slot_name = 'standby_slot'
In ${PGDATA}/postgresql.conf on both hosts sets:
max_wal_size = 8GB
wal_keep_segments = 32But yesterday pg_wal was 16G and had 1018 files inside, thats why there
was no other
way except deleting its manualy, but not of all,
just 6 hundreds files, which had modification time before September 2020except
000000010000000000000034.00000028.backup.
Trying to rebuild slave from master with: making pg_start_backup,copying ${PGDATA}
files from master to slave (without removing on slave any files in
${PGDATA}),
pg_stop_backup, tunning settings on slave and run it again had no any
success,
wal-files still is not removing automaticaly.
Does anybody knows how to fix it ?Never, ever, remove WAL files manually.
A crash might render your database unrecoverable.You'll have to figure out what is blocking WAL removal.
Are there archive failures reported in "pg_stat_archiver" and the log?
You say that replication is working fine, but try
SELECT pg_current_wal_lsn();
on the primary and compare that with the "restart_lsn" of the replication
slot.Look for strange messages in the log file on both servers.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
On Thu, 2021-03-11 at 09:43 +0200, Andrew Anderson wrote:
Never, ever, remove WAL files manually.
A crash might render your database unrecoverable.You're right, it's not a good idea.
You'll have to figure out what is blocking WAL removal.
This is my favorite dream!
Are there archive failures reported in "pg_stat_archiver" and the log?
master=# select * from pg_stat_archiver;
archived_count | last_archived_wal | last_archived_time | failed_count | last_failed_wal | last_failed_time | stats_reset
----------------+--------------------------+-------------------------------+--------------+-----------------+------------------+------------------------------
3021 | 000000010000000B000000C9 | 2021-03-11 08:53:56.133796+02 | 0 | | | 2021-01-06 14:33:40.70147+02
(1 row)In today's logs there is no any errors:
$ grep "FATAL\|WARNING" /opt/pglogs/master.log
$$ grep "FATAL\|WARNING" /opt/pglogs/slave.log
$You say that replication is working fine, but try
SELECT pg_current_wal_lsn();
on the primary and compare that with the "restart_lsn" of the replication slot.
It parameters is differ:
master=# SELECT pg_current_wal_lsn();
pg_current_wal_lsn
--------------------
B/CB099398
(1 row)master=# select * from pg_replication_slots;
slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn
----------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+---------------------
standby_slot | | physical | | | f | t | 2631806 | | | B/CB0AC068 |
(1 row)But when I add new data to the table on master, it apears on slave.
Look for strange messages in the log file on both servers.
Looking for strange messages gives nothing, in today's logs there is no any strange messages, just about connects of applications.
All that looks fine.
If that happens again, set "log_min_messages" to "debug2".
Then the log file will contain information abotu the WAL segments that
PostgreSQL is trying to remove. That might give you some insight.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
The situation didn't changes, WAL segments not removing automatically. The
streaming replication works fine, here is the log files:
from master:
2021-03-16 06:28:51.787 EET [94341] [walreceiver] [pgadmin] [[unknown]]
[2.2.2.2]DEBUG: write 145/ED10A8E8 flush 145/ED10A8E8 apply 145/ED10A8E8
2021-03-16 06:28:51.869 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64662 socket=11
2021-03-16 06:28:51.874 EET [40017] [] [] [] []DEBUG: server process (PID
64662) exited with exit code 0
2021-03-16 06:28:51.878 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64664 socket=11
2021-03-16 06:28:51.882 EET [40017] [] [] [] []DEBUG: server process (PID
64664) exited with exit code 0
2021-03-16 06:28:51.886 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64666 socket=11
2021-03-16 06:28:51.890 EET [40017] [] [] [] []DEBUG: server process (PID
64666) exited with exit code 0
2021-03-16 06:28:55.896 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64673 socket=11
2021-03-16 06:28:55.902 EET [40017] [] [] [] []DEBUG: server process (PID
64673) exited with exit code 0
2021-03-16 06:28:56.909 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64679 socket=11
2021-03-16 06:28:56.913 EET [40017] [] [] [] []DEBUG: server process (PID
64679) exited with exit code 0
2021-03-16 06:28:57.919 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64682 socket=11
2021-03-16 06:28:57.925 EET [40017] [] [] [] []DEBUG: server process (PID
64682) exited with exit code 0
2021-03-16 06:28:59.940 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64687 socket=11
2021-03-16 06:28:59.946 EET [40017] [] [] [] []DEBUG: server process (PID
64687) exited with exit code 0
2021-03-16 06:28:59.951 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64689 socket=11
2021-03-16 06:28:59.956 EET [40017] [] [] [] []DEBUG: server process (PID
64689) exited with exit code 0
2021-03-16 06:28:59.960 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64691 socket=11
2021-03-16 06:28:59.964 EET [40017] [] [] [] []DEBUG: server process (PID
64691) exited with exit code 0
2021-03-16 06:28:59.968 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64693 socket=11
2021-03-16 06:28:59.973 EET [40017] [] [] [] []DEBUG: server process (PID
64693) exited with exit code 0
2021-03-16 06:28:59.977 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64695 socket=11
2021-03-16 06:28:59.980 EET [40017] [] [] [] []DEBUG: server process (PID
64695) exited with exit code 0
2021-03-16 06:28:59.984 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64697 socket=11
2021-03-16 06:28:59.987 EET [40017] [] [] [] []DEBUG: server process (PID
64697) exited with exit code 0
2021-03-16 06:28:59.990 EET [40017] [] [] [] []DEBUG: forked new backend,
pid=64700 socket=11
2021-03-16 06:28:59.993 EET [40017] [] [] [] []DEBUG: server process (PID
64700) exited with exit code 0
2021-03-16 06:29:00.820 EET [40024] [] [] [] []DEBUG: received inquiry for
database 0
2021-03-16 06:29:00.820 EET [40024] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:29:00.820 EET [40024] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:29:00.833 EET [64702] [] [] [] []DEBUG: autovacuum:
processing database "postgres"
2021-03-16 06:29:00.833 EET [40024] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 06:29:00.833 EET [40024] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:29:00.833 EET [40024] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 06:29:00.833 EET [40024] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:29:00.845 EET [40017] [] [] [] []DEBUG: server process (PID
64702) exited with exit code 0
2021-03-16 06:29:01.810 EET [94341] [walreceiver] [pgadmin] [[unknown]]
[2.2.2.2]DEBUG: write 145/ED10A8E8 flush 145/ED10A8E8 apply 145/ED10A8E8
from slave:
2021-03-16 06:31:41.115 EET [97581] [] [] [] []DEBUG: checkpointer updated
shared memory configuration values
2021-03-16 06:31:42.456 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35706 socket=11
2021-03-16 06:31:42.466 EET [97575] [] [] [] []DEBUG: server process (PID
35706) exited with exit code 0
2021-03-16 06:31:42.474 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35708 socket=11
2021-03-16 06:31:42.483 EET [97575] [] [] [] []DEBUG: server process (PID
35708) exited with exit code 0
2021-03-16 06:31:42.493 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35710 socket=11
2021-03-16 06:31:42.501 EET [97575] [] [] [] []DEBUG: server process (PID
35710) exited with exit code 0
2021-03-16 06:31:48.310 EET [97585] [] [] [] []DEBUG: sending write
145/ED1310C8 flush 145/ED1310C8 apply 145/ED1310C8 (reply requested)
2021-03-16 06:31:48.310 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
06:31:48.310858+02 receipttime 2021-03-16 06:31:48.310745+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 06:31:48.951 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35721 socket=11
2021-03-16 06:31:48.961 EET [97575] [] [] [] []DEBUG: server process (PID
35721) exited with exit code 0
2021-03-16 06:31:52.772 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35728 socket=11
2021-03-16 06:31:52.778 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 06:31:52.778 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:31:52.778 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 06:31:52.778 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:31:52.793 EET [97575] [] [] [] []DEBUG: server process (PID
35728) exited with exit code 0
2021-03-16 06:31:52.799 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35730 socket=11
2021-03-16 06:31:52.806 EET [97575] [] [] [] []DEBUG: server process (PID
35730) exited with exit code 0
2021-03-16 06:31:53.816 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35733 socket=11
2021-03-16 06:31:53.821 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 06:31:53.821 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:31:53.821 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 06:31:53.821 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:31:53.835 EET [97575] [] [] [] []DEBUG: server process (PID
35733) exited with exit code 0
2021-03-16 06:31:53.842 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35735 socket=11
2021-03-16 06:31:53.850 EET [97575] [] [] [] []DEBUG: server process (PID
35735) exited with exit code 0
2021-03-16 06:31:53.858 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35737 socket=11
2021-03-16 06:31:53.866 EET [97575] [] [] [] []DEBUG: server process (PID
35737) exited with exit code 0
2021-03-16 06:31:57.183 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35744 socket=11
2021-03-16 06:31:57.190 EET [97575] [] [] [] []DEBUG: server process (PID
35744) exited with exit code 0
2021-03-16 06:31:58.333 EET [97585] [] [] [] []DEBUG: sending write
145/ED1310C8 flush 145/ED1310C8 apply 145/ED1310C8
2021-03-16 06:31:59.658 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35747 socket=11
2021-03-16 06:31:59.663 EET [35747] [[unknown]] [user_user] [database]
[172.16.2.35]DEBUG: parse <unnamed>: show transaction_read_only
2021-03-16 06:31:59.663 EET [35747] [[unknown]] [user_user] [database]
[172.16.2.35]DEBUG: bind <unnamed> to <unnamed>
2021-03-16 06:31:59.666 EET [97575] [] [] [] []DEBUG: server process (PID
35747) exited with exit code 0
2021-03-16 06:32:03.897 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35753 socket=11
2021-03-16 06:32:03.901 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 06:32:03.901 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:32:03.901 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 06:32:03.901 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:32:03.915 EET [97575] [] [] [] []DEBUG: server process (PID
35753) exited with exit code 0
2021-03-16 06:32:07.924 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35760 socket=11
2021-03-16 06:32:07.928 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 06:32:07.928 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:32:07.928 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 06:32:07.928 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:32:07.941 EET [97575] [] [] [] []DEBUG: server process (PID
35760) exited with exit code 0
2021-03-16 06:32:07.953 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35762 socket=11
2021-03-16 06:32:07.964 EET [97575] [] [] [] []DEBUG: server process (PID
35762) exited with exit code 0
2021-03-16 06:32:07.973 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35764 socket=11
2021-03-16 06:32:07.983 EET [97575] [] [] [] []DEBUG: server process (PID
35764) exited with exit code 0
2021-03-16 06:32:08.355 EET [97585] [] [] [] []DEBUG: sending write
145/ED1310C8 flush 145/ED1310C8 apply 145/ED1310C8
2021-03-16 06:32:16.557 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35768 socket=11
2021-03-16 06:32:16.562 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 06:32:16.562 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:32:16.562 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 06:32:16.562 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:32:16.575 EET [97575] [] [] [] []DEBUG: server process (PID
35768) exited with exit code 0
2021-03-16 06:32:17.583 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35770 socket=11
2021-03-16 06:32:17.587 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 06:32:17.587 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:32:17.587 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 06:32:17.588 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:32:17.601 EET [97575] [] [] [] []DEBUG: server process (PID
35770) exited with exit code 0
2021-03-16 06:32:18.377 EET [97585] [] [] [] []DEBUG: sending write
145/ED1310C8 flush 145/ED1310C8 apply 145/ED1310C8 (reply requested)
2021-03-16 06:32:18.378 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
06:32:18.378397+02 receipttime 2021-03-16 06:32:18.378306+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 06:32:20.419 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35773 socket=11
2021-03-16 06:32:20.428 EET [97575] [] [] [] []DEBUG: server process (PID
35773) exited with exit code 0
2021-03-16 06:32:20.995 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35775 socket=11
2021-03-16 06:32:21.000 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 06:32:21.000 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 06:32:21.000 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 06:32:21.000 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 06:32:21.013 EET [97575] [] [] [] []DEBUG: server process (PID
35775) exited with exit code 0
2021-03-16 06:32:21.021 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=35777 socket=11
чт, 11 мар. 2021 г. в 11:18, Laurenz Albe <laurenz.albe@cybertec.at>:
Show quoted text
On Thu, 2021-03-11 at 09:43 +0200, Andrew Anderson wrote:
Never, ever, remove WAL files manually.
A crash might render your database unrecoverable.You're right, it's not a good idea.
You'll have to figure out what is blocking WAL removal.
This is my favorite dream!
Are there archive failures reported in "pg_stat_archiver" and the log?
master=# select * from pg_stat_archiver;
archived_count | last_archived_wal | last_archived_time| failed_count | last_failed_wal | last_failed_time |
stats_reset----------------+--------------------------+-------------------------------+--------------+-----------------+------------------+------------------------------
3021 | 000000010000000B000000C9 | 2021-03-11
08:53:56.133796+02 | 0 | | |
2021-01-06 14:33:40.70147+02(1 row)
In today's logs there is no any errors:
$ grep "FATAL\|WARNING" /opt/pglogs/master.log
$$ grep "FATAL\|WARNING" /opt/pglogs/slave.log
$You say that replication is working fine, but try
SELECT pg_current_wal_lsn();
on the primary and compare that with the "restart_lsn" of the
replication slot.
It parameters is differ:
master=# SELECT pg_current_wal_lsn();
pg_current_wal_lsn
--------------------
B/CB099398
(1 row)master=# select * from pg_replication_slots;
slot_name | plugin | slot_type | datoid | database |temporary | active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn----------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+---------------------
standby_slot | | physical | | | f | t
| 2631806 | | | B/CB0AC068 |
(1 row)
But when I add new data to the table on master, it apears on slave.
Look for strange messages in the log file on both servers.
Looking for strange messages gives nothing, in today's logs there is no
any strange messages, just about connects of applications.
All that looks fine.
If that happens again, set "log_min_messages" to "debug2".
Then the log file will contain information abotu the WAL segments that
PostgreSQL is trying to remove. That might give you some insight.Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
On Tue, 2021-03-16 at 09:33 +0200, Andrew Anderson wrote:
The situation didn't changes, WAL segments not removing automatically.
The streaming replication works fine, here is the log files:from master:
[log with debug2, but without WAL segment delete messages]
Could you set "log_checkpoints = on" and tell us what "checkpoint_timeout"
is set to? WAL segments are only deleted after checkpoints.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
postgres=# show checkpoint_timeout;
checkpoint_timeout
--------------------
5min
(1 row)
Added log_checkpoints = on to postgresql.conf on slave, and here is the log
from slave:
2021-03-16 09:43:42.509 EET [97581] [] [] [] []DEBUG: checkpointer updated
shared memory configuration values
2021-03-16 09:43:42.916 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68951 socket=11
2021-03-16 09:43:42.921 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 09:43:42.921 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 09:43:42.921 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 09:43:42.921 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 09:43:42.934 EET [97575] [] [] [] []DEBUG: server process (PID
68951) exited with exit code 0
2021-03-16 09:43:44.581 EET [97585] [] [] [] []DEBUG: sending write
145/EED56AF0 flush 145/EED56AF0 apply 145/EED56AF0
2021-03-16 09:43:44.945 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68959 socket=11
2021-03-16 09:43:44.950 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 09:43:44.950 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 09:43:44.950 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 09:43:44.950 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 09:43:44.963 EET [97575] [] [] [] []DEBUG: server process (PID
68959) exited with exit code 0
2021-03-16 09:43:45.972 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68961 socket=11
2021-03-16 09:43:45.982 EET [97575] [] [] [] []DEBUG: server process (PID
68961) exited with exit code 0
2021-03-16 09:43:45.991 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68963 socket=11
2021-03-16 09:43:46.003 EET [97575] [] [] [] []DEBUG: server process (PID
68963) exited with exit code 0
2021-03-16 09:43:47.013 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68968 socket=11
2021-03-16 09:43:47.024 EET [97575] [] [] [] []DEBUG: server process (PID
68968) exited with exit code 0
2021-03-16 09:43:47.033 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68974 socket=11
2021-03-16 09:43:47.041 EET [97575] [] [] [] []DEBUG: server process (PID
68974) exited with exit code 0
2021-03-16 09:43:47.050 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68976 socket=11
2021-03-16 09:43:47.060 EET [97575] [] [] [] []DEBUG: server process (PID
68976) exited with exit code 0
2021-03-16 09:43:47.516 EET [97581] [] [] [] []DEBUG: updated min recovery
point to 145/EED56AF0 on timeline 2
2021-03-16 09:43:47.517 EET [97581] [] [] [] []DEBUG: performing
replication slot checkpoint
2021-03-16 09:43:48.070 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68979 socket=11
2021-03-16 09:43:48.079 EET [97575] [] [] [] []DEBUG: server process (PID
68979) exited with exit code 0
2021-03-16 09:43:48.085 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68981 socket=11
2021-03-16 09:43:48.094 EET [97575] [] [] [] []DEBUG: server process (PID
68981) exited with exit code 0
2021-03-16 09:43:48.099 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68983 socket=11
2021-03-16 09:43:48.109 EET [97575] [] [] [] []DEBUG: server process (PID
68983) exited with exit code 0
2021-03-16 09:43:48.115 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68985 socket=11
2021-03-16 09:43:48.122 EET [97575] [] [] [] []DEBUG: server process (PID
68985) exited with exit code 0
2021-03-16 09:43:48.168 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68987 socket=11
2021-03-16 09:43:48.178 EET [97575] [] [] [] []DEBUG: server process (PID
68987) exited with exit code 0
2021-03-16 09:43:51.134 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=68997 socket=11
2021-03-16 09:43:51.141 EET [97575] [] [] [] []DEBUG: server process (PID
68997) exited with exit code 0
2021-03-16 09:43:54.605 EET [97585] [] [] [] []DEBUG: sending write
145/EED56AF0 flush 145/EED56AF0 apply 145/EED56AF0
2021-03-16 09:43:56.177 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=69014 socket=11
2021-03-16 09:43:56.186 EET [97575] [] [] [] []DEBUG: server process (PID
69014) exited with exit code 0
2021-03-16 09:43:57.196 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=69018 socket=11
2021-03-16 09:43:57.202 EET [97575] [] [] [] []DEBUG: server process (PID
69018) exited with exit code 0
2021-03-16 09:43:57.552 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=69020 socket=11
2021-03-16 09:43:57.556 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 09:43:57.556 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 09:43:57.556 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 09:43:57.557 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 09:43:57.570 EET [97575] [] [] [] []DEBUG: server process (PID
69020) exited with exit code 0
2021-03-16 09:43:57.577 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=69022 socket=11
2021-03-16 09:43:57.585 EET [97575] [] [] [] []DEBUG: server process (PID
69022) exited with exit code 0
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=1 file=base/16395/54933 time=0.008 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=2 file=base/16395/54933.1 time=0.004 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=3 file=base/16395/54923.1 time=0.004 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=4 file=base/16395/54923.4 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=5 file=base/16395/54923.5 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=6 file=base/16395/54923.7 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=7 file=base/16395/54923_fsm time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=8 file=base/16395/54923_vm time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=9 file=base/16395/40915.10 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=10 file=base/16395/40915_fsm time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=11 file=base/16395/54926 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=12 file=base/16395/54926.1 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=13 file=base/16395/2619 time=0.004 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=14 file=base/16395/54928 time=0.004 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=15 file=base/16395/54928.1 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=16 file=base/16395/46862.2 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=17 file=base/16395/54931 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=18 file=base/16395/54934 time=0.003 msec
2021-03-16 09:44:03.981 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=19 file=base/16395/54934.1 time=0.003 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=20 file=base/16395/54934.2 time=1.315 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=21 file=base/16395/54932 time=0.005 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=22 file=base/16395/54932.1 time=0.003 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=23 file=base/16395/54932.2 time=0.003 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=24 file=base/16395/40922.3 time=0.003 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=25 file=base/16395/40921.4 time=0.002 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=26 file=base/16395/40845.3 time=0.003 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=27 file=base/16395/54927 time=0.002 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=28 file=base/16395/54927.1 time=0.002 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=29 file=base/16395/40848 time=0.002 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=30 file=base/16395/40923.2 time=0.003 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=31 file=base/16395/40923.3 time=0.002 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=32 file=base/16395/40924 time=0.003 msec
2021-03-16 09:44:03.982 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=33 file=base/16395/40924.2 time=0.002 msec
2021-03-16 09:44:03.983 EET [97581] [] [] [] []DEBUG: checkpoint sync:
number=34 file=base/16395/54935 time=0.939 msec
2021-03-16 09:44:03.997 EET [97581] [] [] [] []DEBUG: attempting to remove
WAL segments older than log file 000000000000013E00000097
2021-03-16 09:44:03.999 EET [97581] [] [] [] []DEBUG: SlruScanDirectory
invoking callback on pg_subtrans/1EEF
2021-03-16 09:44:04.628 EET [97585] [] [] [] []DEBUG: sending write
145/EED56AF0 flush 145/EED56AF0 apply 145/EED56AF0 (reply requested)
2021-03-16 09:44:04.629 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:04.628572+02 receipttime 2021-03-16 09:44:04.62953+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 09:44:04.681 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=69032 socket=11
2021-03-16 09:44:04.688 EET [97575] [] [] [] []DEBUG: server process (PID
69032) exited with exit code 0
2021-03-16 09:44:05.215 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=69039 socket=11
2021-03-16 09:44:05.223 EET [97575] [] [] [] []DEBUG: server process (PID
69039) exited with exit code 0
2021-03-16 09:44:05.235 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=69043 socket=11
2021-03-16 09:44:05.241 EET [97575] [] [] [] []DEBUG: server process (PID
69043) exited with exit code 0
2021-03-16 09:44:07.115 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:07.114539+02 receipttime 2021-03-16 09:44:07.115687+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:07.115 EET [97585] [] [] [] []DEBUG: sending write
145/EED58B60 flush 145/EED56AF0 apply 145/EED56AF0
2021-03-16 09:44:07.118 EET [97585] [] [] [] []DEBUG: sending write
145/EED58B60 flush 145/EED58B60 apply 145/EED56AF0
2021-03-16 09:44:07.118 EET [97585] [] [] [] []DEBUG: sending write
145/EED58B60 flush 145/EED58B60 apply 145/EED58B60
2021-03-16 09:44:07.120 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:07.119335+02 receipttime 2021-03-16 09:44:07.120658+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:07.120 EET [97585] [] [] [] []DEBUG: sending write
145/EED60278 flush 145/EED58B60 apply 145/EED58B60
2021-03-16 09:44:07.126 EET [97585] [] [] [] []DEBUG: sending write
145/EED60278 flush 145/EED60278 apply 145/EED58B60
2021-03-16 09:44:07.126 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:07.121166+02 receipttime 2021-03-16 09:44:07.126213+02 replication
apply delay 0 ms transfer latency 5 ms
2021-03-16 09:44:07.126 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:07.123089+02 receipttime 2021-03-16 09:44:07.126253+02 replication
apply delay 0 ms transfer latency 3 ms
2021-03-16 09:44:07.126 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:07.124296+02 receipttime 2021-03-16 09:44:07.126275+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:07.126 EET [97585] [] [] [] []DEBUG: sending write
145/EED65B88 flush 145/EED60278 apply 145/EED60278
2021-03-16 09:44:07.126 EET [97585] [] [] [] []DEBUG: sending write
145/EED65B88 flush 145/EED65B88 apply 145/EED60278
2021-03-16 09:44:07.127 EET [97585] [] [] [] []DEBUG: sending write
145/EED65B88 flush 145/EED65B88 apply 145/EED62970
2021-03-16 09:44:07.127 EET [97585] [] [] [] []DEBUG: sending write
145/EED65B88 flush 145/EED65B88 apply 145/EED65B88
2021-03-16 09:44:07.129 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:07.128493+02 receipttime 2021-03-16 09:44:07.129383+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 09:44:07.129 EET [97585] [] [] [] []DEBUG: sending write
145/EED65BC8 flush 145/EED65B88 apply 145/EED65B88
2021-03-16 09:44:07.130 EET [97585] [] [] [] []DEBUG: sending write
145/EED65BC8 flush 145/EED65BC8 apply 145/EED65B88
2021-03-16 09:44:07.130 EET [97585] [] [] [] []DEBUG: sending write
145/EED65BC8 flush 145/EED65BC8 apply 145/EED65BC8
2021-03-16 09:44:07.402 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:07.401693+02 receipttime 2021-03-16 09:44:07.402781+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:07.402 EET [97585] [] [] [] []DEBUG: sending write
145/EED65F38 flush 145/EED65BC8 apply 145/EED65BC8
2021-03-16 09:44:07.404 EET [97585] [] [] [] []DEBUG: sending write
145/EED65F38 flush 145/EED65F38 apply 145/EED65BC8
2021-03-16 09:44:07.404 EET [97585] [] [] [] []DEBUG: sending write
145/EED65F38 flush 145/EED65F38 apply 145/EED65F38
2021-03-16 09:44:09.039 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.037128+02 receipttime 2021-03-16 09:44:09.039141+02 replication
apply delay 0 ms transfer latency 2 ms
2021-03-16 09:44:09.039 EET [97585] [] [] [] []DEBUG: sending write
145/EED767D0 flush 145/EED65F38 apply 145/EED65F38
2021-03-16 09:44:09.040 EET [97585] [] [] [] []DEBUG: sending write
145/EED767D0 flush 145/EED767D0 apply 145/EED65F38
2021-03-16 09:44:09.041 EET [97585] [] [] [] []DEBUG: sending write
145/EED767D0 flush 145/EED767D0 apply 145/EED767D0
2021-03-16 09:44:09.052 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.051438+02 receipttime 2021-03-16 09:44:09.052571+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.052 EET [97585] [] [] [] []DEBUG: sending write
145/EED79CB8 flush 145/EED767D0 apply 145/EED767D0
2021-03-16 09:44:09.053 EET [97585] [] [] [] []DEBUG: sending write
145/EED79CB8 flush 145/EED79CB8 apply 145/EED767D0
2021-03-16 09:44:09.053 EET [97585] [] [] [] []DEBUG: sending write
145/EED79CB8 flush 145/EED79CB8 apply 145/EED79CB8
2021-03-16 09:44:09.064 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.062875+02 receipttime 2021-03-16 09:44:09.064028+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.064 EET [97585] [] [] [] []DEBUG: sending write
145/EED7CAE8 flush 145/EED79CB8 apply 145/EED79CB8
2021-03-16 09:44:09.065 EET [97585] [] [] [] []DEBUG: sending write
145/EED7CAE8 flush 145/EED7CAE8 apply 145/EED79CB8
2021-03-16 09:44:09.065 EET [97585] [] [] [] []DEBUG: sending write
145/EED7CAE8 flush 145/EED7CAE8 apply 145/EED7CAE8
2021-03-16 09:44:09.071 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.070821+02 receipttime 2021-03-16 09:44:09.071892+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.071 EET [97585] [] [] [] []DEBUG: sending write
145/EED7DFB8 flush 145/EED7CAE8 apply 145/EED7CAE8
2021-03-16 09:44:09.072 EET [97585] [] [] [] []DEBUG: sending write
145/EED7DFB8 flush 145/EED7DFB8 apply 145/EED7CAE8
2021-03-16 09:44:09.073 EET [97585] [] [] [] []DEBUG: sending write
145/EED7DFB8 flush 145/EED7DFB8 apply 145/EED7DFB8
2021-03-16 09:44:09.082 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.081682+02 receipttime 2021-03-16 09:44:09.082764+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.082 EET [97585] [] [] [] []DEBUG: sending write
145/EED7FBA0 flush 145/EED7DFB8 apply 145/EED7DFB8
2021-03-16 09:44:09.083 EET [97585] [] [] [] []DEBUG: sending write
145/EED7FBA0 flush 145/EED7FBA0 apply 145/EED7DFB8
2021-03-16 09:44:09.083 EET [97585] [] [] [] []DEBUG: sending write
145/EED7FBA0 flush 145/EED7FBA0 apply 145/EED7FBA0
2021-03-16 09:44:09.092 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.091792+02 receipttime 2021-03-16 09:44:09.092881+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.092 EET [97585] [] [] [] []DEBUG: sending write
145/EED81DD8 flush 145/EED7FBA0 apply 145/EED7FBA0
2021-03-16 09:44:09.093 EET [97585] [] [] [] []DEBUG: sending write
145/EED81DD8 flush 145/EED81DD8 apply 145/EED7FBA0
2021-03-16 09:44:09.093 EET [97585] [] [] [] []DEBUG: sending write
145/EED81DD8 flush 145/EED81DD8 apply 145/EED81DD8
2021-03-16 09:44:09.103 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.102121+02 receipttime 2021-03-16 09:44:09.103193+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.103 EET [97585] [] [] [] []DEBUG: sending write
145/EED83280 flush 145/EED81DD8 apply 145/EED81DD8
2021-03-16 09:44:09.103 EET [97585] [] [] [] []DEBUG: sending write
145/EED83280 flush 145/EED83280 apply 145/EED81DD8
2021-03-16 09:44:09.104 EET [97585] [] [] [] []DEBUG: sending write
145/EED83280 flush 145/EED83280 apply 145/EED83280
2021-03-16 09:44:09.112 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.111162+02 receipttime 2021-03-16 09:44:09.112253+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.112 EET [97585] [] [] [] []DEBUG: sending write
145/EED84748 flush 145/EED83280 apply 145/EED83280
2021-03-16 09:44:09.113 EET [97585] [] [] [] []DEBUG: sending write
145/EED84748 flush 145/EED84748 apply 145/EED83280
2021-03-16 09:44:09.113 EET [97585] [] [] [] []DEBUG: sending write
145/EED84748 flush 145/EED84748 apply 145/EED84748
2021-03-16 09:44:09.120 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.119062+02 receipttime 2021-03-16 09:44:09.12016+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.120 EET [97585] [] [] [] []DEBUG: sending write
145/EED868E0 flush 145/EED84748 apply 145/EED84748
2021-03-16 09:44:09.121 EET [97585] [] [] [] []DEBUG: sending write
145/EED868E0 flush 145/EED868E0 apply 145/EED84748
2021-03-16 09:44:09.121 EET [97585] [] [] [] []DEBUG: sending write
145/EED868E0 flush 145/EED868E0 apply 145/EED868E0
2021-03-16 09:44:09.284 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:09.283417+02 receipttime 2021-03-16 09:44:09.284538+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:09.284 EET [97585] [] [] [] []DEBUG: sending write
145/EED86918 flush 145/EED868E0 apply 145/EED868E0
2021-03-16 09:44:09.285 EET [97585] [] [] [] []DEBUG: sending write
145/EED86918 flush 145/EED86918 apply 145/EED868E0
2021-03-16 09:44:09.285 EET [97585] [] [] [] []DEBUG: sending write
145/EED86918 flush 145/EED86918 apply 145/EED86918
2021-03-16 09:44:17.780 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:17.778827+02 receipttime 2021-03-16 09:44:17.779977+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:17.780 EET [97585] [] [] [] []DEBUG: sending write
145/EED88910 flush 145/EED86918 apply 145/EED86918
2021-03-16 09:44:17.780 EET [97585] [] [] [] []DEBUG: sending write
145/EED88910 flush 145/EED88910 apply 145/EED86918
2021-03-16 09:44:17.780 EET [97585] [] [] [] []DEBUG: sending write
145/EED88910 flush 145/EED88910 apply 145/EED88910
2021-03-16 09:44:17.794 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:17.793372+02 receipttime 2021-03-16 09:44:17.79478+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:17.794 EET [97585] [] [] [] []DEBUG: sending write
145/EED92370 flush 145/EED88910 apply 145/EED88910
2021-03-16 09:44:17.795 EET [97585] [] [] [] []DEBUG: sending write
145/EED92370 flush 145/EED92370 apply 145/EED88910
2021-03-16 09:44:17.795 EET [97585] [] [] [] []DEBUG: sending write
145/EED92370 flush 145/EED92370 apply 145/EED92370
2021-03-16 09:44:17.798 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:17.797854+02 receipttime 2021-03-16 09:44:17.798819+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 09:44:17.798 EET [97585] [] [] [] []DEBUG: sending write
145/EED93660 flush 145/EED92370 apply 145/EED92370
2021-03-16 09:44:17.799 EET [97585] [] [] [] []DEBUG: sending write
145/EED93660 flush 145/EED93660 apply 145/EED92370
2021-03-16 09:44:17.799 EET [97585] [] [] [] []DEBUG: sending write
145/EED93660 flush 145/EED93660 apply 145/EED93660
2021-03-16 09:44:17.804 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:17.803065+02 receipttime 2021-03-16 09:44:17.804053+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 09:44:17.804 EET [97585] [] [] [] []DEBUG: sending write
145/EED94918 flush 145/EED93660 apply 145/EED93660
2021-03-16 09:44:17.804 EET [97585] [] [] [] []DEBUG: sending write
145/EED94918 flush 145/EED94918 apply 145/EED93660
2021-03-16 09:44:17.804 EET [97585] [] [] [] []DEBUG: sending write
145/EED94918 flush 145/EED94918 apply 145/EED94918
2021-03-16 09:44:17.809 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:17.808038+02 receipttime 2021-03-16 09:44:17.809083+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:17.809 EET [97585] [] [] [] []DEBUG: sending write
145/EED95BC8 flush 145/EED94918 apply 145/EED94918
2021-03-16 09:44:17.809 EET [97585] [] [] [] []DEBUG: sending write
145/EED95BC8 flush 145/EED95BC8 apply 145/EED94918
2021-03-16 09:44:17.809 EET [97585] [] [] [] []DEBUG: sending write
145/EED95BC8 flush 145/EED95BC8 apply 145/EED95BC8
2021-03-16 09:44:17.906 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:17.905067+02 receipttime 2021-03-16 09:44:17.906031+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 09:44:17.906 EET [97585] [] [] [] []DEBUG: sending write
145/EED95C08 flush 145/EED95BC8 apply 145/EED95BC8
2021-03-16 09:44:17.906 EET [97585] [] [] [] []DEBUG: sending write
145/EED95C08 flush 145/EED95C08 apply 145/EED95BC8
2021-03-16 09:44:17.907 EET [97585] [] [] [] []DEBUG: sending write
145/EED95C08 flush 145/EED95C08 apply 145/EED95C08
2021-03-16 09:44:18.038 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:18.036967+02 receipttime 2021-03-16 09:44:18.038009+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:18.038 EET [97585] [] [] [] []DEBUG: sending write
145/EED95D38 flush 145/EED95C08 apply 145/EED95C08
2021-03-16 09:44:18.038 EET [97585] [] [] [] []DEBUG: sending write
145/EED95D38 flush 145/EED95D38 apply 145/EED95C08
2021-03-16 09:44:18.038 EET [97585] [] [] [] []DEBUG: sending write
145/EED95D38 flush 145/EED95D38 apply 145/EED95D38
2021-03-16 09:44:18.779 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:18.778734+02 receipttime 2021-03-16 09:44:18.779953+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:18.780 EET [97585] [] [] [] []DEBUG: sending write
145/EED97DA0 flush 145/EED95D38 apply 145/EED95D38
2021-03-16 09:44:18.780 EET [97585] [] [] [] []DEBUG: sending write
145/EED97DA0 flush 145/EED97DA0 apply 145/EED95D38
2021-03-16 09:44:18.780 EET [97585] [] [] [] []DEBUG: sending write
145/EED97DA0 flush 145/EED97DA0 apply 145/EED97DA0
2021-03-16 09:44:18.787 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:18.786521+02 receipttime 2021-03-16 09:44:18.787955+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:18.788 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA13E8 flush 145/EED97DA0 apply 145/EED97DA0
2021-03-16 09:44:18.788 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA13E8 flush 145/EEDA13E8 apply 145/EED97DA0
2021-03-16 09:44:18.789 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA13E8 flush 145/EEDA13E8 apply 145/EEDA13E8
2021-03-16 09:44:18.791 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:18.790535+02 receipttime 2021-03-16 09:44:18.791493+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 09:44:18.791 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA2550 flush 145/EEDA13E8 apply 145/EEDA13E8
2021-03-16 09:44:18.791 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA2550 flush 145/EEDA2550 apply 145/EEDA13E8
2021-03-16 09:44:18.792 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA2550 flush 145/EEDA2550 apply 145/EEDA2550
2021-03-16 09:44:18.793 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:18.792741+02 receipttime 2021-03-16 09:44:18.793759+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:18.793 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA3C70 flush 145/EEDA2550 apply 145/EEDA2550
2021-03-16 09:44:18.794 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA3C70 flush 145/EEDA3C70 apply 145/EEDA2550
2021-03-16 09:44:18.794 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA3C70 flush 145/EEDA3C70 apply 145/EEDA3C70
2021-03-16 09:44:18.795 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:18.794123+02 receipttime 2021-03-16 09:44:18.795082+02 replication
apply delay 0 ms transfer latency 0 ms
2021-03-16 09:44:18.795 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5E50 flush 145/EEDA3C70 apply 145/EEDA3C70
2021-03-16 09:44:18.795 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5E50 flush 145/EEDA5E50 apply 145/EEDA3C70
2021-03-16 09:44:18.795 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5E50 flush 145/EEDA5E50 apply 145/EEDA5E50
2021-03-16 09:44:18.908 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:18.907307+02 receipttime 2021-03-16 09:44:18.908412+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:18.908 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5E90 flush 145/EEDA5E50 apply 145/EEDA5E50
2021-03-16 09:44:18.909 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5E90 flush 145/EEDA5E90 apply 145/EEDA5E50
2021-03-16 09:44:18.909 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5E90 flush 145/EEDA5E90 apply 145/EEDA5E90
2021-03-16 09:44:19.033 EET [97585] [] [] [] []DEBUG: sendtime 2021-03-16
09:44:19.032755+02 receipttime 2021-03-16 09:44:19.033807+02 replication
apply delay 0 ms transfer latency 1 ms
2021-03-16 09:44:19.033 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5FC0 flush 145/EEDA5E90 apply 145/EEDA5E90
2021-03-16 09:44:19.034 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5FC0 flush 145/EEDA5FC0 apply 145/EEDA5E90
2021-03-16 09:44:19.034 EET [97585] [] [] [] []DEBUG: sending write
145/EEDA5FC0 flush 145/EEDA5FC0 apply 145/EEDA5FC0
2021-03-16 09:44:19.258 EET [97575] [] [] [] []DEBUG: forked new backend,
pid=69051 socket=11
2021-03-16 09:44:19.264 EET [97583] [] [] [] []DEBUG: received inquiry for
database 13212
2021-03-16 09:44:19.264 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2021-03-16 09:44:19.264 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_13212.stat"
2021-03-16 09:44:19.265 EET [97583] [] [] [] []DEBUG: writing stats file
"pg_stat_tmp/db_0.stat"
2021-03-16 09:44:19.278 EET [97575] [] [] [] []DEBUG: server process (PID
69051) exited with exit code 0
2021-03-16 09:44:19.849 EET [97577] [] [] [] []DEBUG: parameter
"log_checkpoints" removed from configuration file, reset to default
2021-03-16 09:44:19.849 EET [97581] [] [] [] []DEBUG: parameter
"log_checkpoints" removed from configuration file, reset to default
2021-03-16 09:44:19.849 EET [97582] [] [] [] []DEBUG: parameter
"log_checkpoints" removed from configuration file, reset to default
2021-03-16 09:44:19.850 EET [97583] [] [] [] []DEBUG: parameter
"log_checkpoints" removed from configuration file, reset to default
2021-03-16 09:44:19.851 EET [97576] [] [] [] []DEBUG: parameter
"log_checkpoints" removed from configuration file, reset to default
2021-03-16 09:44:19.937 EET [97585] [] [] [] []DEBUG: parameter
"log_checkpoints" removed from configuration file, reset to default
вт, 16 мар. 2021 г. в 09:40, Laurenz Albe <laurenz.albe@cybertec.at>:
Show quoted text
On Tue, 2021-03-16 at 09:33 +0200, Andrew Anderson wrote:
The situation didn't changes, WAL segments not removing automatically.
The streaming replication works fine, here is the log files:from master:
[log with debug2, but without WAL segment delete messages]Could you set "log_checkpoints = on" and tell us what "checkpoint_timeout"
is set to? WAL segments are only deleted after checkpoints.Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
On Tue, 2021-03-16 at 09:49 +0200, Andrew Anderson wrote:
2021-03-16 09:44:03.997 EET [97581] [] [] [] []DEBUG: attempting to remove WAL segments older than log file 000000000000013E00000097
That was the entry I was hoping to see.
So, are all older WAL segments deleted or recycled?
Is that a reasonably recent WAL segment?
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
In pg_wal catalog there is no file by that name:
$ ls pg_wal/ | grep 000000000000013E00000097
$
but there is files with very old time of creation:
$ ls -lart pg_wal/
total 30933220
-rw------- 1 postgres postgres 299 Dec 30 05:44
000000020000013E00000097.00000108.backup
-rw------- 1 postgres postgres 16777216 Dec 30 06:12
000000010000000000000001
-rw------- 1 postgres postgres 16777216 Dec 30 06:12
000000020000013E00000098
-rw------- 1 postgres postgres 44 Dec 30 06:29 00000002.history
-rw------- 1 postgres postgres 16777216 Dec 30 06:29
000000020000013E00000099
-rw------- 1 postgres postgres 16777216 Dec 30 09:01
000000020000013E0000009A
-rw------- 1 postgres postgres 16777216 Dec 30 09:57
000000020000013E0000009B
..... till now .....
-rw------- 1 postgres postgres 16777216 Mar 16 12:59
0000000200000145000000F2
-rw------- 1 postgres postgres 16777216 Mar 16 13:50
0000000200000145000000F3
-rw------- 1 postgres postgres 16777216 Mar 16 14:39
0000000200000145000000F4
drwx------ 2 postgres postgres 118784 Mar 16 14:39 archive_status
-rw------- 1 postgres postgres 16777216 Mar 16 15:19
0000000200000145000000F6
drwx------ 3 postgres postgres 94208 Mar 16 15:19 .
-rw------- 1 postgres postgres 16777216 Mar 16 15:25
0000000200000145000000F5
drwx------ 19 postgres postgres 4096 Mar 16 15:25 ..
and on master current WAL-file:
postgres=# select pg_walfile_name(pg_current_wal_lsn());
pg_walfile_name
--------------------------
0000000200000145000000F6
(1 row)
вт, 16 мар. 2021 г. в 14:21, Laurenz Albe <laurenz.albe@cybertec.at>:
Show quoted text
On Tue, 2021-03-16 at 09:49 +0200, Andrew Anderson wrote:
2021-03-16 09:44:03.997 EET [97581] [] [] [] []DEBUG: attempting to
remove WAL segments older than log file 000000000000013E00000097
That was the entry I was hoping to see.
So, are all older WAL segments deleted or recycled?
Is that a reasonably recent WAL segment?Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
On Tue, 2021-03-16 at 15:31 +0200, Andrew Anderson wrote:
вт, 16 мар. 2021 г. в 14:21, Laurenz Albe <laurenz.albe@cybertec.at>:
On Tue, 2021-03-16 at 09:49 +0200, Andrew Anderson wrote:
2021-03-16 09:44:03.997 EET [97581] [] [] [] []DEBUG: attempting to remove WAL segments older than log file 000000000000013E00000097
That was the entry I was hoping to see.
So, are all older WAL segments deleted or recycled?
Is that a reasonably recent WAL segment?but there is files with very old time of creation:
$ ls -lart pg_wal/
total 30933220
-rw------- 1 postgres postgres 299 Dec 30 05:44 000000020000013E00000097.00000108.backup
-rw------- 1 postgres postgres 16777216 Dec 30 06:12 000000010000000000000001
-rw------- 1 postgres postgres 16777216 Dec 30 06:12 000000020000013E00000098
-rw------- 1 postgres postgres 44 Dec 30 06:29 00000002.history
-rw------- 1 postgres postgres 16777216 Dec 30 06:29 000000020000013E00000099
-rw------- 1 postgres postgres 16777216 Dec 30 09:01 000000020000013E0000009A
-rw------- 1 postgres postgres 16777216 Dec 30 09:57 000000020000013E0000009B
..... till now .....
-rw------- 1 postgres postgres 16777216 Mar 16 12:59 0000000200000145000000F2
-rw------- 1 postgres postgres 16777216 Mar 16 13:50 0000000200000145000000F3
-rw------- 1 postgres postgres 16777216 Mar 16 14:39 0000000200000145000000F4
drwx------ 2 postgres postgres 118784 Mar 16 14:39 archive_status
-rw------- 1 postgres postgres 16777216 Mar 16 15:19 0000000200000145000000F6
drwx------ 3 postgres postgres 94208 Mar 16 15:19 .
-rw------- 1 postgres postgres 16777216 Mar 16 15:25 0000000200000145000000F5
drwx------ 19 postgres postgres 4096 Mar 16 15:25 ..and on master current WAL-file:
postgres=# select pg_walfile_name(pg_current_wal_lsn());
pg_walfile_name
--------------------------
0000000200000145000000F6
(1 row)
These things hold up deletion of WAL segments:
- checkpoint (not the problem here)
- replication slot (you said that is not it)
- archiver failure (also doesn't seem to be the problem)
- wal_keep_segments / wal_keep_size: what is your setting?
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
- replication slot (you said that is not it)
The replication slot is the same on master:
postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
stanby_slot | | physical | | | f | t
| 94341 | | | 145/F6ECC190 |
(1 row)
$ grep slot ${PGDATA}/recovery.done
primary_slot_name = 'stanby_slot'
and on slave:
postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
stanby_slot | | physical | | | f | f
| | | | 13E/981E2DD0 |
(1 row)
$ grep slot ${PGDATA}/recovery.conf
primary_slot_name = 'stanby_slot'
postgres=# show wal_keep_segments;
wal_keep_segments
-------------------
32
(1 row)
but on slave:
$ ls pg_wal/ | wc -l
1892
вт, 16 мар. 2021 г. в 15:53, Laurenz Albe <laurenz.albe@cybertec.at>:
Show quoted text
On Tue, 2021-03-16 at 15:31 +0200, Andrew Anderson wrote:
вт, 16 мар. 2021 г. в 14:21, Laurenz Albe <laurenz.albe@cybertec.at>:
On Tue, 2021-03-16 at 09:49 +0200, Andrew Anderson wrote:
2021-03-16 09:44:03.997 EET [97581] [] [] [] []DEBUG: attempting to
remove WAL segments older than log file 000000000000013E00000097
That was the entry I was hoping to see.
So, are all older WAL segments deleted or recycled?
Is that a reasonably recent WAL segment?but there is files with very old time of creation:
$ ls -lart pg_wal/
total 30933220
-rw------- 1 postgres postgres 299 Dec 30 05:44000000020000013E00000097.00000108.backup
-rw------- 1 postgres postgres 16777216 Dec 30 06:12
000000010000000000000001
-rw------- 1 postgres postgres 16777216 Dec 30 06:12
000000020000013E00000098
-rw------- 1 postgres postgres 44 Dec 30 06:29 00000002.history
-rw------- 1 postgres postgres 16777216 Dec 30 06:29000000020000013E00000099
-rw------- 1 postgres postgres 16777216 Dec 30 09:01
000000020000013E0000009A
-rw------- 1 postgres postgres 16777216 Dec 30 09:57
000000020000013E0000009B
..... till now .....
-rw------- 1 postgres postgres 16777216 Mar 16 12:590000000200000145000000F2
-rw------- 1 postgres postgres 16777216 Mar 16 13:50
0000000200000145000000F3
-rw------- 1 postgres postgres 16777216 Mar 16 14:39
0000000200000145000000F4
drwx------ 2 postgres postgres 118784 Mar 16 14:39 archive_status
-rw------- 1 postgres postgres 16777216 Mar 16 15:190000000200000145000000F6
drwx------ 3 postgres postgres 94208 Mar 16 15:19 .
-rw------- 1 postgres postgres 16777216 Mar 16 15:250000000200000145000000F5
drwx------ 19 postgres postgres 4096 Mar 16 15:25 ..
and on master current WAL-file:
postgres=# select pg_walfile_name(pg_current_wal_lsn());
pg_walfile_name
--------------------------
0000000200000145000000F6
(1 row)These things hold up deletion of WAL segments:
- checkpoint (not the problem here)
- replication slot (you said that is not it)
- archiver failure (also doesn't seem to be the problem)
- wal_keep_segments / wal_keep_size: what is your setting?
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
On Tue, 2021-03-16 at 16:11 +0200, Andrew Anderson wrote:
postgres=# show wal_keep_segments;
wal_keep_segments
-------------------
32
(1 row)
Ok, then I am out of ideas.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
Import Notes
Reply to msg id not found: CAHAzDin1=bTJnePeCFbq_qQhOwdSO3uOLfJyVeFX-pk9jH_f9g@mail.gmail.com
Andrew Anderson <forumwriter007@gmail.com> writes:
- replication slot (you said that is not it)
The replication slot is the same on master:
postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
stanby_slot | | physical | | | f | t
| 94341 | | | 145/F6ECC190 |
(1 row)
$ grep slot ${PGDATA}/recovery.done
primary_slot_name = 'stanby_slot'
and on slave:
postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
stanby_slot | | physical | | | f | f
| | | | 13E/981E2DD0 |
(1 row)
$ grep slot ${PGDATA}/recovery.conf
primary_slot_name = 'stanby_slot'
Uh ... that slot's restart_lsn seems to correspond to where the
standby is refusing to truncate WAL beyond. So I think your
problem is exactly that this slot isn't advancing. What's
using it?
regards, tom lane
You're right, restart_lsn on slave does not changes.
What's using it?
As I think, streaming replication is using this slot. Does anybody know how
to fix it ?
вт, 16 мар. 2021 г. в 17:44, Tom Lane <tgl@sss.pgh.pa.us>:
Show quoted text
Andrew Anderson <forumwriter007@gmail.com> writes:
- replication slot (you said that is not it)
The replication slot is the same on master:
postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
stanby_slot | | physical | | | f | t
| 94341 | | | 145/F6ECC190 |
(1 row)
$ grep slot ${PGDATA}/recovery.done
primary_slot_name = 'stanby_slot'and on slave:
postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
stanby_slot | | physical | | | f | f
| | | | 13E/981E2DD0 |
(1 row)
$ grep slot ${PGDATA}/recovery.conf
primary_slot_name = 'stanby_slot'Uh ... that slot's restart_lsn seems to correspond to where the
standby is refusing to truncate WAL beyond. So I think your
problem is exactly that this slot isn't advancing. What's
using it?regards, tom lane
Andrew Anderson <forumwriter007@gmail.com> writes:
What's using it?
As I think, streaming replication is using this slot. Does anybody know how
to fix it ?
Unless you need another replica that's downstream of the standby,
you should not be maintaining a replication slot on the standby.
There may be a way to have a slot that's not actually holding back
WAL cleanup while doing nothing, but I don't know what it is.
regards, tom lane
So, right now I have configuration of replication slots:
On master:
postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
stanby_slot | | physical | | | f | t
| 94341 | | | 145/FBAACBA8 |
(1 row)
On slave:
postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | temporary |
active | active_pid | xmin | catalog_xmin | restart_lsn |
confirmed_flush_lsn
------------------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
stanby_slot | | physical | | | f | f
| | | | 13E/981E2DD0 |
(1 row)
And I can do 'select pg_drop_replication_slot('stanby_slot');' on slave
without any risk to destroy streaming replication ? And will it fix the
automated removing of WAL-files ?
вт, 16 мар. 2021 г. в 19:39, Tom Lane <tgl@sss.pgh.pa.us>:
Show quoted text
Andrew Anderson <forumwriter007@gmail.com> writes:
What's using it?
As I think, streaming replication is using this slot. Does anybody know
how
to fix it ?
Unless you need another replica that's downstream of the standby,
you should not be maintaining a replication slot on the standby.There may be a way to have a slot that's not actually holding back
WAL cleanup while doing nothing, but I don't know what it is.regards, tom lane
But maybe there is a way to fix this ? Rebuilding slave from master with
erasing ${PGDATA} on slave does not help.
вт, 16 мар. 2021 г. в 16:56, Laurenz Albe <laurenz.albe@cybertec.at>:
Show quoted text
On Tue, 2021-03-16 at 16:11 +0200, Andrew Anderson wrote:
postgres=# show wal_keep_segments;
wal_keep_segments
-------------------
32
(1 row)Ok, then I am out of ideas.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
Deleting replication slot on slave resolve the issue, now WAL-files
removing automaticaly ! Thanks a lot for your answers !
ср, 17 мар. 2021 г. в 10:59, Andrew Anderson <forumwriter007@gmail.com>:
Show quoted text
But maybe there is a way to fix this ? Rebuilding slave from master with
erasing ${PGDATA} on slave does not help.вт, 16 мар. 2021 г. в 16:56, Laurenz Albe <laurenz.albe@cybertec.at>:
On Tue, 2021-03-16 at 16:11 +0200, Andrew Anderson wrote:
postgres=# show wal_keep_segments;
wal_keep_segments
-------------------
32
(1 row)Ok, then I am out of ideas.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com