Thread: Transaction ID wrap limit is log entries
Hi there,
We started seeing 1000s of messages like the ones below in our logs starting last night. There's been no changes but performance has dropped significantly.
It's Postgres 9.2.3
2013-05-19 12:50:30.423 UTC,,,1976,,5198ca96.7b8,1,,2013-05-19 12:50:30 UTC,8/0,0,DEBUG,00000,"autovacuum: processing database ""dddd_production""",,,,,,,,,""
2013-05-19 12:50:30.423 UTC,,,1976,,5198ca96.7b8,1,,2013-05-19 12:50:30 UTC,8/0,0,DEBUG,00000,"autovacuum: processing database ""dddd_production""",,,,,,,,,""
2013-05-19 12:50:30.434 UTC,,,1976,,5198ca96.7b8,2,,2013-05-19 12:50:30 UTC,8/159746,1173975322,DEBUG,00000,"transaction ID wrap limit is 2297797644, limited by database with OID 17671",,,,,,,,,""
Any ideas what would be causing this?
Kind regards,
Armand
On 19 May 2013 13:54, Armand du Plessis <adp@bank.io> wrote: > We started seeing 1000s of messages like the ones below in our logs starting > last night. There's been no changes but performance has dropped > significantly. > Any ideas what would be causing this? The database has not been issuing VACUUMs on some or all of the relations, so the system needs to issue "anti-transactional wraparound" VACUUMs. -- Simon Riggs http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
On Sun, May 19, 2013 at 6:08 PM, Simon Riggs <simon@2ndquadrant.com> wrote:
On 19 May 2013 13:54, Armand du Plessis <adp@bank.io> wrote:
> We started seeing 1000s of messages like the ones below in our logs starting
> last night. There's been no changes but performance has dropped
> significantly.> Any ideas what would be causing this?The database has not been issuing VACUUMs on some or all of the
relations, so the system needs to issue "anti-transactional
wraparound" VACUUMs.
Thanks, once I logged in with another user I saw there's one relation that is being vacuumed to prevent tx wraparound. The sheer number of those log entries made it seem like the autovacuum is in a loop.
--
Simon Riggs http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
On Sun, May 19, 2013 at 6:12 PM, Armand du Plessis <adp@bank.io> wrote:
Looking at that table's vacuum stats this morning, it finished an autovacuum "2013-05-20 07:25:51.040327+00" and immediately started again at "2013-05-20 07:26:45.448314+00 "
Armand
On Sun, May 19, 2013 at 6:08 PM, Simon Riggs <simon@2ndquadrant.com> wrote:On 19 May 2013 13:54, Armand du Plessis <adp@bank.io> wrote:
> We started seeing 1000s of messages like the ones below in our logs starting
> last night. There's been no changes but performance has dropped
> significantly.> Any ideas what would be causing this?The database has not been issuing VACUUMs on some or all of the
relations, so the system needs to issue "anti-transactional
wraparound" VACUUMs.Thanks, once I logged in with another user I saw there's one relation that is being vacuumed to prevent tx wraparound. The sheer number of those log entries made it seem like the autovacuum is in a loop.
--
Simon Riggs http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
The autovacuum completed (after many hours) however it didn't seem to have frozen any old pages as it just kicks off again right away with the same reason (VACUUM ANALYZE public.messages (to prevent wraparound))
Which makes sense if I look at the settings but what bugs me is that the max xid (as seen below) is still > autovacuum_freeze_max_age (1000000000) when it finished. Should this not be reset because now we're stuck in a really crippling loop.
postgres=# select max(age(datfrozenxid)) from pg_database;
max
------------
1043200153
As an interim measure I'm going to up the autovacuum_freeze_max_age and bite the bullet and restart postgres but something seems not right here. I'm planning to partition this specific table in the next week so it shouldn't be a problem running with the higher setting but ideally would like to track down what is happening here.
Kind regards,
Armand
Armand du Plessis <adp@bank.io> writes:
> The autovacuum completed (after many hours) however it didn't seem to have
> frozen any old pages as it just kicks off again right away with the same
> reason (VACUUM ANALYZE public.messages (to prevent wraparound))
I suspect it's unable to move the table's min XID forward at all because
there is some old open transaction preventing cleanup of very old dead
tuples. Look for old xact_start times in pg_stat_activity. Also look
for old entries in pg_prepared_xacts. If you find any, get rid of them.
regards, tom lane
On Mon, May 20, 2013 at 3:11 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Armand du Plessis <adp@bank.io> writes:I suspect it's unable to move the table's min XID forward at all because
> The autovacuum completed (after many hours) however it didn't seem to have
> frozen any old pages as it just kicks off again right away with the same
> reason (VACUUM ANALYZE public.messages (to prevent wraparound))
there is some old open transaction preventing cleanup of very old dead
tuples. Look for old xact_start times in pg_stat_activity. Also look
for old entries in pg_prepared_xacts. If you find any, get rid of them.
Thanks Tom, that sounds like it possibly could've caused it. I've since restarted the cluster (kicking myself) so there's no old transactions left in either table. (pg_prepared_xacts is actually empty). Will check there first if this happens again.
regards, tom lane
On Mon, May 20, 2013 at 3:21 PM, Armand du Plessis <adp@bank.io> wrote:
On Mon, May 20, 2013 at 3:11 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:Armand du Plessis <adp@bank.io> writes:I suspect it's unable to move the table's min XID forward at all because
> The autovacuum completed (after many hours) however it didn't seem to have
> frozen any old pages as it just kicks off again right away with the same
> reason (VACUUM ANALYZE public.messages (to prevent wraparound))
there is some old open transaction preventing cleanup of very old dead
tuples. Look for old xact_start times in pg_stat_activity. Also look
for old entries in pg_prepared_xacts. If you find any, get rid of them.
This now had a full vacuum on the table but the table's xid is still increasing.
"messages";1061103361;"62 GB"
It's gone up from 105xxx yesterday. I've confirmed there's no old transactions in pg_stat_activity or pg_prepared_xacts and everything else seems fine. I can see the completion in the log and see it reflected as last_vacuum in pg_stat_user_tables.
2013-05-21 08:01:44.910 UTC,"postgres","datase",6921,"[local]",519a9497.1b09,3,"VACUUM",2013-05-20 21:24:39 UTC,51/0,0,LOG,00000,"duration: 38210856.820 ms statement: vacuum messages;",,,,,,,,,"psql"
I've bumped up the autovacuum_freeze_max_age yesterday so this was a normal vacuum unlike the wrap-around autovacuums from the original post.
Settings :
autovacuum_freeze_max_age : 1500000000
vacuum_freeze_min_age : 25000000
vacuum_freeze_table_age: 150000000
It's Postgres 9.2.3.
I might just be missing something but it's worrying me that it's just increasing even after the vacuum.
Kind regards,
Armand
Just one thing to add, this is not a table that's gone for long periods without a vacuum, it's been autovacuumed regularly and still is without affecting the transaction id. Also double checked for storage parameters on the table that might affect it and nothing there.
On Mon, May 20, 2013 at 3:21 PM, Armand du Plessis <adp@bank.io> wrote:On Mon, May 20, 2013 at 3:11 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:Armand du Plessis <adp@bank.io> writes:I suspect it's unable to move the table's min XID forward at all because
> The autovacuum completed (after many hours) however it didn't seem to have
> frozen any old pages as it just kicks off again right away with the same
> reason (VACUUM ANALYZE public.messages (to prevent wraparound))
there is some old open transaction preventing cleanup of very old dead
tuples. Look for old xact_start times in pg_stat_activity. Also look
for old entries in pg_prepared_xacts. If you find any, get rid of them.This now had a full vacuum on the table but the table's xid is still increasing."messages";1061103361;"62 GB"It's gone up from 105xxx yesterday. I've confirmed there's no old transactions in pg_stat_activity or pg_prepared_xacts and everything else seems fine. I can see the completion in the log and see it reflected as last_vacuum in pg_stat_user_tables.2013-05-21 08:01:44.910 UTC,"postgres","datase",6921,"[local]",519a9497.1b09,3,"VACUUM",2013-05-20 21:24:39 UTC,51/0,0,LOG,00000,"duration: 38210856.820 ms statement: vacuum messages;",,,,,,,,,"psql"I've bumped up the autovacuum_freeze_max_age yesterday so this was a normal vacuum unlike the wrap-around autovacuums from the original post.Settings :autovacuum_freeze_max_age : 1500000000vacuum_freeze_min_age : 25000000vacuum_freeze_table_age: 150000000It's Postgres 9.2.3.I might just be missing something but it's worrying me that it's just increasing even after the vacuum.Kind regards,Armand