Обсуждение: Frequent pg_clog on system

Hi all,

I'm using postgresql 8.1.8 on Ubuntu 6.10, it's mainly a
sandbox/playground machine to crunch data and do some stats analysis.
System info:
2.6.17-11-server (SMP)
Intel(R) Pentium(R) 4 CPU 3.00GHz
4GB RAM
500GB disk

Size of the db is ~7GB with 16 tables, 2 tables A and B holding
respectively 4GB (6M rows) and 2GB(3M rows) of data
I do at this time about 600K insert / day  in one go.
In some occasion there is a lot of duplicate inserts (the data I get, is
sometimes duplicated and I rely on unique constraint)

Since I started to play with it, I got too many times the pg_clog error
such as:
ERROR:  could not access status of transaction 778793573
DETAIL:  could not open file "pg_clog/02E6": No such file or directory

Each time the pg_clog file is way beyond the existing files I have on my
system (in this case, the 'latest file' is 0023)

It seems to happen after a sql query performs a long scan of table A or B.
That's very weird since each time it seems to happen after performing
more or less the same query several times (trial and error narrowing
them data) and suddenly I have this error happening and I'm cooked
(fwiw, there is no insert/update happening at all during this period,
only select and a single user)

Anyone has any idea what could be the cause of this ? It's a bit too
recurrent to me and it's a definite annoyance.


Cheers,

-- stephane

Anything in /var/log/messages at this time?  Try turning up the
debugging for transaction logging?

~BAS

On Fri, 2007-05-18 at 12:08 +0200, Stephane Bailliez wrote:
> n after a sql query performs a long scan of table A or B.
> That's very weird since each time it seems to happen after performing
> more or less the same query several times (trial and error narrowing
> them data) and suddenly I have this error happening and I'm cooked
> (fwiw, there is no insert/update happening at all during this period,
> only select and a single user)
>
> Anyone has any idea what could be the cause of this ? It's a bit too
> recurrent to me and it's a definite annoyance.

Hi Brian,

Brian A. Seklecki wrote:
> Anything in /var/log/messages at this time?  Try turning up the
> debugging for transaction logging?
>
Will do.
FWIW forgot to mention, chance of memory issue is low, memory was
entirely changed a couple of days ago while upgrading from 1GB to 4GB

The first time it appeared, I had 02E6, some 600K inserts and the
pg_clog changed, some queries to identify corrupted data and it changed
again. Server went down apparently while querying on the console.

Nothing special in /var/log/messages but here's some messages from
/var/log/postgresql...

LOG:  autovacuum: processing database "template1"
LOG:  incomplete startup packet
LOG:  autovacuum: processing database "sandbox"
LOG:  autovacuum: processing database "postgres"
LOG:  autovacuum: processing database "events"
LOG:  autovacuum: processing database "template1"
LOG:  autovacuum: processing database "sandbox"
LOG:  autovacuum: processing database "postgres"
LOG:  autovacuum: processing database "events"
LOG:  autovacuum: processing database "template1"
LOG:  autovacuum: processing database "sandbox"
LOG:  autovacuum: processing database "postgres"
LOG:  autovacuum: processing database "events"
LOG:  autovacuum: processing database "template1"
ERROR:  could not access status of transaction 778793573
DETAIL:  could not open file "pg_clog/02E6": No such file or directory
LOG:  unexpected EOF on client connection
LOG:  autovacuum: processing database "sandbox"
LOG:  autovacuum: processing database "postgres"
LOG:  autovacuum: processing database "events"
LOG:  autovacuum: processing database "template1"
LOG:  autovacuum: processing database "sandbox"
LOG:  autovacuum: processing database "postgres"
LOG:  autovacuum: processing database "events"
LOG:  autovacuum: processing database "template1"
LOG:  autovacuum: processing database "sandbox"
LOG:  autovacuum: processing database "postgres"
LOG:  autovacuum: processing database "events"
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
LOG:  autovacuum: processing database "template1"
ERROR:  could not access status of transaction 1088621376
DETAIL:  could not open file "pg_clog/040E": No such file or directory
ERROR:  could not access status of transaction 3523034880
DETAIL:  could not open file "pg_clog/0D1F": No such file or directory
ERROR:  could not access status of transaction 3523034880
DETAIL:  could not open file "pg_clog/0D1F": No such file or directory
LOG:  autovacuum: processing database "sandbox"
ERROR:  could not access status of transaction 3523034880
DETAIL:  could not open file "pg_clog/0D1F": No such file or directory
ERROR:  could not access status of transaction 3523034880
DETAIL:  could not open file "pg_clog/0D1F": No such file or directory
ERROR:  could not access status of transaction 3523034880
DETAIL:  could not open file "pg_clog/0D1F": No such file or directory
LOG:  autovacuum: processing database "postgres"
LOG:  autovacuum: processing database "events"
LOG:  server process (PID 32045) was terminated by signal 11
LOG:  terminating any other active server processes
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back
the current transaction and exit, because another server process exited
abnormally and possibly corrupte
d shared memory.
HINT:  In a moment you should be able to reconnect to the database and
repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back
the current transaction and exit, because another server process exited
abnormally and possibly corrupte
d shared memory.
HINT:  In a moment you should be able to reconnect to the database and
repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back
the current transaction and exit, because another server process exited
abnormally and possibly corrupte
d shared memory.
HINT:  In a moment you should be able to reconnect to the database and
repeat your command.
LOG:  all server processes terminated; reinitializing
LOG:  database system was interrupted at 2007-05-18 02:23:32 UTC
LOG:  checkpoint record is at A/D5A9184
LOG:  redo record is at A/D5A9184; undo record is at 0/0; shutdown FALSE
LOG:  next transaction ID: 37572637; next OID: 50006
LOG:  next MultiXactId: 236697; next MultiXactOffset: 485354
LOG:  database system was not properly shut down; automatic recovery in
progress
LOG:  record with zero length at A/D5A91C8
LOG:  redo is not required
FATAL:  the database system is starting up
LOG:  database system is ready
LOG:  transaction ID wrap limit is 1103367124, limited by database "events"
LOG:  server process (PID 32071) was terminated by signal 11
LOG:  terminating any other active server processes
LOG:  all server processes terminated; reinitializing
LOG:  database system was interrupted at 2007-05-18 14:08:57 UTC
LOG:  checkpoint record is at A/D5A91C8
LOG:  redo record is at A/D5A91C8; undo record is at 0/0; shutdown TRUE
LOG:  next transaction ID: 37572637; next OID: 50006
LOG:  next MultiXactId: 236697; next MultiXactOffset: 485354
LOG:  database system was not properly shut down; automatic recovery in
progress
LOG:  record with zero length at A/D5A920C





> ~BAS
>
> On Fri, 2007-05-18 at 12:08 +0200, Stephane Bailliez wrote:
>
>> n after a sql query performs a long scan of table A or B.
>> That's very weird since each time it seems to happen after performing
>> more or less the same query several times (trial and error narrowing
>> them data) and suddenly I have this error happening and I'm cooked
>> (fwiw, there is no insert/update happening at all during this period,
>> only select and a single user)
>>
>> Anyone has any idea what could be the cause of this ? It's a bit too
>> recurrent to me and it's a definite annoyance.
>>
>
>
>
>

Time to pop in memtest86+ and let it ride.  Sig11 = bad ram /
overheating / hardware. ~BAS


On Fri, 2007-05-18 at 17:45 +0200, Stephane Bailliez wrote:
> LOG:  server process (PID 32045) was terminated by signal 11
--
Brian A. Seklecki <bseklecki@collaborativefusion.com>
Collaborative Fusion, Inc.




IMPORTANT: This message contains confidential information and is intended only for the individual named. If the reader
ofthis message is not an intended recipient (or the individual responsible for the delivery of this message to an
intendedrecipient), please be advised that any re-use, dissemination, distribution or copying of this message is
prohibited. Please notify the sender immediately by e-mail if you have received this e-mail by mistake and delete this
e-mailfrom your system. 

Stephane Bailliez <sbailliez@gmail.com> writes:
> FWIW forgot to mention, chance of memory issue is low, memory was
> entirely changed a couple of days ago while upgrading from 1GB to 4GB

Hmm, did this all start happening after the RAM upgrade?  If so I'd say
the odds are real good that you got some bad memory there.

            regards, tom lane

Tom Lane wrote:
> Stephane Bailliez <sbailliez@gmail.com> writes:
>
>> FWIW forgot to mention, chance of memory issue is low, memory was
>> entirely changed a couple of days ago while upgrading from 1GB to 4GB
>>
>
> Hmm, did this all start happening after the RAM upgrade?  If so I'd say
> the odds are real good that you got some bad memory there.
>

No it was appearing before with only 1GB.  So I had hope to leave the
bad memory potential by having this brand new 4GB replacement and it was
ok for a week.
Did not run memtest86+ on it however, so that will be mission next week
I'm afraid.

Overheating is a possibility due to where machine is located right now.

-- stephane