Re: Apparent Wraparound?

Hi there,

I just found the following message in my logs:

Jun 8 10:38:38 caligula postgres[56868]: [1-1] : LOG: could not
truncate directory "pg_subtrans": apparent wraparound

Should I be worried or can I just ignore this one? My database is still
small (a pg_dumpall bzippe'd is still around 500KB) so I doubt that I'm
affected by any transaction id wraparound problems. I also vacuum
analyze once a day and have pg_autovacuum turned on.

Gunther

Gunther Mayer wrote:
> Hi there,
>
> I just found the following message in my logs:
>
> Jun 8 10:38:38 caligula postgres[56868]: [1-1] : LOG: could not
> truncate directory "pg_subtrans": apparent wraparound
>
> Should I be worried or can I just ignore this one? My database is still
> small (a pg_dumpall bzippe'd is still around 500KB) so I doubt that I'm
> affected by any transaction id wraparound problems. I also vacuum
> analyze once a day and have pg_autovacuum turned on.

What version are you running? This seems to match the description of a
bug fixed for 8.2 and 8.1.5:

revision 1.20
date: 2006-07-19 20:46:42 -0400; author: tgl; state: Exp; lines: +8 -3;
Don't try to truncate multixact SLRU files in checkpoints done during xlog
recovery. In the first place, it doesn't work because slru's
latest_page_number isn't set up yet (this is why we've been hearing reports
of strange "apparent wraparound" log messages during crash recovery, but
only from people who'd managed to advance their next-mxact counters some
considerable distance from 0). In the second place, it seems a bit unwise
to be throwing away data during crash recovery anwyway. This latter
consideration convinces me to just disable truncation during recovery,
rather than computing latest_page_number and pushing ahead.

--
Alvaro Herrera http://www.amazon.com/gp/registry/CTMLCN8V17R4
"La verdad no siempre es bonita, pero el hambre de ella sí"

On Jun 8, 3:23 pm, alvhe(dot)(dot)(dot)(at)commandprompt(dot)com (Alvaro Herrera) wrote:
> Gunther Mayer wrote:
> > Hi there,
>
> > I just found the following message in my logs:
>
> > Jun 8 10:38:38 caligula postgres[56868]: [1-1] : LOG: could not
> > truncate directory "pg_subtrans": apparent wraparound
>
> > Should I be worried or can I just ignore this one? My database is still
> > small (a pg_dumpall bzippe'd is still around 500KB) so I doubt that I'm
> > affected by any transaction id wraparound problems. I also vacuum
> > analyze once a day and have pg_autovacuum turned on.
>
> What version are you running? This seems to match the description of a
> bug fixed for 8.2 and 8.1.5:
>

I noticed the same message in my logfiles (once on each of two
servers). I'm running 8.1.8, and the server's been running flawless
for about 2 months.

Gerhard

On Jun 13, 2:35 pm, g(dot)hinterma(dot)(dot)(dot)(at)inode(dot)at wrote:
> On Jun 8, 3:23 pm, alvhe(dot)(dot)(dot)(at)commandprompt(dot)com (Alvaro Herrera) wrote:
>
>
>
> > Gunther Mayer wrote:
> > > Hi there,
>
> > > I just found the following message in my logs:
>
> > > Jun 8 10:38:38 caligula postgres[56868]: [1-1] : LOG: could not
> > > truncate directory "pg_subtrans": apparent wraparound
>
> > > Should I be worried or can I just ignore this one? My database is still
> > > small (a pg_dumpall bzippe'd is still around 500KB) so I doubt that I'm
> > > affected by any transaction id wraparound problems. I also vacuum
> > > analyze once a day and have pg_autovacuum turned on.
>
> > What version are you running? This seems to match the description of a
> > bug fixed for 8.2 and 8.1.5:
>
> I noticed the same message in my logfiles (once on each of two
> servers). I'm running 8.1.8, and the server's been running flawless
> for about 2 months.
>
> Gerhard

Can someone tell me if I should be concerned about this log entry ? My
database is quite large (~ 2G in PGDATA)

regards
Gerhard

On Jun 18, 11:08 am, g(dot)hinterma(dot)(dot)(dot)(at)inode(dot)at wrote:
> On Jun 13, 2:35 pm, g(dot)hinterma(dot)(dot)(dot)(at)inode(dot)at wrote:
>
> Can someone tell me if I should be concerned about this log entry ? My
> database is quite large (~ 2G in PGDATA)
>
> regards
> Gerhard

BTW, I do not use autovacuum, and run vacuumdb on a weekly basis.

regards
Gerhard

g(dot)hintermayer(at)inode(dot)at wrote:
> On Jun 18, 11:08 am, g(dot)hinterma(dot)(dot)(dot)(at)inode(dot)at wrote:
> > On Jun 13, 2:35 pm, g(dot)hinterma(dot)(dot)(dot)(at)inode(dot)at wrote:
> >
> > Can someone tell me if I should be concerned about this log entry ? My
> > database is quite large (~ 2G in PGDATA)
>
> BTW, I do not use autovacuum, and run vacuumdb on a weekly basis.

Ok, here is what I can tell you:

1. this message can only appear during checkpoint.

2. this message, by itself, is harmless. All it says is that it tried
to truncate (meaning, removing files previous to the segments in active
use) the multixact system (directory PGDATA/pg_multixact) and it
couldn't find an appropriate truncating point.

3. If it cannot find a truncating point, it logs this message and then
moves the "already truncated" point to the requested truncating point.
This means that some files might remain on disk. This is harmless
because they will be overwritten when the numbering mechanism wraps
around and creates the same files again.

Make sure we are actually talking about the same log message: it must
mention the directory "pg_multixact".

The only situation in which this could be an actual problem is when the
numbering is actually wrapping around very quickly, i.e. faster than
checkpoints. If you are using lots of multixacts then this may be
possible -- I am not sure. You use multixacts by creating shared tuple
locks, which in turn are created when foreign keys are checked by more
than one process at the same time.

Questions:
- what files are actually in PGDATA/pg_multixact/offsets and members?
- do the multixact counters increase quickly? You can check them with
pg_controldata

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

Aha, google thinks it's wise to make the last postings (probably if
more than n ?) show only the poster name and make the name clickable.
Not very userfriendly :-( but now i know it ;-)

Sorry if that wasn't clear. I'm getting the same log entry as the
original
poster, i.e.: LOG: could not truncate directory "pg_subtrans":
apparent
wraparound.

I'm just running an analysis of the "daily transaction id consumption"
on my databases to see, if the uptime of the server matches with the
time the wraparound was logged.

Gerhard

g(dot)hintermayer(at)inode(dot)at wrote:
> Aha, google thinks it's wise to make the last postings (probably if
> more than n ?) show only the poster name and make the name clickable.
> Not very userfriendly :-( but now i know it ;-)

I don't very much understand what you mean. I do see that you said "I
noticed the same message" that Gunther Meyer was reporting but you
weren't very explicit. I feared that the directory mentioned was
different.

> Sorry if that wasn't clear. I'm getting the same log entry as the
> original
> poster, i.e.: LOG: could not truncate directory "pg_subtrans":
> apparent
> wraparound.

Ok.

> I'm just running an analysis of the "daily transaction id consumption"
> on my databases to see, if the uptime of the server matches with the
> time the wraparound was logged.

Please check "MultiXact" id consumption. Do you mean that your server
has crashed?

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On Jun 18, 10:44 pm, alvhe(dot)(dot)(dot)(at)commandprompt(dot)com (Alvaro Herrera)
wrote:

>
> Please check "MultiXact" id consumption. Do you mean that your server
> has crashed?
>
How do I check MilitXact id consumption ? Is it "Latest checkpoint's
NextXID:" in the output of pg_controldata ?

transaction id consumption is ~ 350000 per day (extrapolated from 16
hours).
No, the Server has been up for about 2 month (regular reboot due to
kernel and postgresql upgrade to 8.1.8), was running before for 7
month flawless, and before that i migrated from 8.0 to 8.1.4 with a
complete dump/restore).

pg_multixact/members shows:
-rw------- 1 postgres postgres 8192 Aug 30 2006 0000
pg_multixact/offsets shows:
-rw------- 1 postgres postgres 8192 Apr 13 15:03 0000

pg_controldata shows:
pg_control version number: 812
Catalog version number: 200510211
Database system identifier: 4969068620492422615
Database cluster state: in production
pg_control last modified: Tue Jun 19 08:00:36 2007
Current log file ID: 10
Next log file segment: 102
Latest checkpoint location: A/65362150
Prior checkpoint location: A/652E091C
Latest checkpoint's REDO location: A/65362150
Latest checkpoint's UNDO location: 0/0
Latest checkpoint's TimeLineID: 1
Latest checkpoint's NextXID: 99983151
Latest checkpoint's NextOID: 7758309
Latest checkpoint's NextMultiXactId: 1
Latest checkpoint's NextMultiOffset: 0
Time of latest checkpoint: Tue Jun 19 08:00:36 2007
Maximum data alignment: 4
Database block size: 8192
Blocks per segment of large relation: 131072
Bytes per WAL segment: 16777216
Maximum length of identifiers: 64
Maximum columns in an index: 32
Date/time type storage: floating-point numbers
Maximum length of locale name: 128
LC_COLLATE: C
LC_CTYPE: C

regards
Gerhard

g(dot)hintermayer(at)inode(dot)at wrote:
> On Jun 18, 10:44 pm, alvhe(dot)(dot)(dot)(at)commandprompt(dot)com (Alvaro Herrera)
> wrote:
>
> >
> > Please check "MultiXact" id consumption. Do you mean that your server
> > has crashed?
> >
> How do I check MilitXact id consumption ? Is it "Latest checkpoint's
> NextXID:" in the output of pg_controldata ?

No, it is these lines:

> Latest checkpoint's NextMultiXactId: 1
> Latest checkpoint's NextMultiOffset: 0

Which are the initial values. This means that you haven't use
MultiXacts at all! The message about failing to truncate the dir is
certainly a bug, and certainly harmless.

> transaction id consumption is ~ 350000 per day (extrapolated from 16
> hours).
> No, the Server has been up for about 2 month (regular reboot due to
> kernel and postgresql upgrade to 8.1.8), was running before for 7
> month flawless, and before that i migrated from 8.0 to 8.1.4 with a
> complete dump/restore).

And when was the message logged?

--
Alvaro Herrera http://www.advogato.org/person/alvherre
"Saca el libro que tu religión considere como el indicado para encontrar la
oración que traiga paz a tu alma. Luego rebootea el computador
y ve si funciona" (Carlos Duclós)

> And when was the message logged?
>

after the server was running with version 8.1.8 for about 2 month
(actually it was Jun 13 on one server and Apr 5 on the other) and no
similar log entries since then.

Gerhard