SEO

We have now experienced index corruption on two separate but identical
slony clusters. In each case the slony subscriber failed after
attempting to insert a duplicate record. In each case reindexing the
sl_log_1 table on the provider fixed the problem.

The latest occurrence was on our production cluster yesterday. This has
only happened since we performed kernel upgrades and we are uncertain
whether this represents a kernel bug, or a postgres bug exposed by
different timings in the new kernel.

Our systems are:

Sun v40z 4 x Dual Core AMD Opteron(tm) Processor 875
Kernel 2.6.16.14 #8 SMP x86_64 x86_64 x86_64 GNU/Linux
kernel boot option: elevator=deadline
16 Gigs of RAM
postgresql-8.0.3-1PGDG
Bonded e1000/tg3 NICs with 8192 MTU.
Slony 1.1.0

NetApp FAS270 OnTap 7.0.3
Mounted with the NFS options
rw,nfsvers=3,hard,rsize=32768,wsize=32768,timeo=60 0,tcp,noac
Jumbo frames 8192 MTU.

All postgres data and logs are stored on the netapp.

In the latest episode, the index corruption was coincident with a
slony-induced vacuum. I don't know if this was the case with our test
system failures.

What can we do to help identify the cause of this? I believe we will be
able to reproduce this on a test system if there is some useful
investigation we can perform.

__
Marc

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.3 (GNU/Linux)

iD8DBQBEoq4eUBr6u+c2wkERAvtsAJ48n7VEVNUJcmci8W6T7y cr0fFBsACeNFo6
CuTJ9JRODuY1mZIkT7a1BcA=
=sTZB
-----END PGP SIGNATURE-----

Marc Munro <marc@bloodnok.com> writes:
> We have now experienced index corruption on two separate but identical
> slony clusters. In each case the slony subscriber failed after
> attempting to insert a duplicate record. In each case reindexing the
> sl_log_1 table on the provider fixed the problem.

Please be more specific about what you mean by "index corruption"
.... what were the exact symptoms?

> postgresql-8.0.3-1PGDG

The *first* thing you should do is update to 8.0.8 and see if the
problem is still there.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Marc Munro <marc@bloodnok.com> writes:
> On Tom Lane's advice, we upgraded to Postgres 8.0.8.

OK, so it's not an already-known problem.

> We were able to corrupt the index within 90 minutes of starting up our
> cluster. A slony-induced vacuum was under way on the provider at the
> time the subscriber failed.

You still haven't given any details. What do you mean by "corrupt the
index" --- what actual symptoms are you seeing?

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

On Thu, 2006-06-29 at 12:11 -0400, Tom Lane wrote:
> OK, so it's not an already-known problem.
>
> > We were able to corrupt the index within 90 minutes of starting up our
> > cluster. A slony-induced vacuum was under way on the provider at the
> > time the subscriber failed.
>
> You still haven't given any details. What do you mean by "corrupt the
> index" --- what actual symptoms are you seeing?

We have a two node slony cluster with load tests running againt the
provider node.

After resyncing the subscriber, and running load tests for about an
hour, the slony subscriber begins to fail. From the log file:

2006-06-28 17:58:43 PDT ERROR remoteWorkerThread_1: "insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520943','22001','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520943','22002','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520943','22003','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520943','22004','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520943','22005','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520943','22006','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520943','22007','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520943','22007','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520942','22009','0');
insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374520942','22010','0');
" ERROR: duplicate key violates unique constraint "table_trans_attr_pk"

As you see, slony is attempting to enter one tuple
('374520943','22007','0') two times.

Each previous time we have had this problem, rebuilding the indexes on
slony log table (sl_log_1) has fixed the problem. I have not reindexed
the table this time as I do not want to destroy any usable evidence.

__
Marc

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.3 (GNU/Linux)

iD8DBQBEo/5LUBr6u+c2wkERApJoAJ4mMmVOk7UoneEFZaDTsaDQzrNbKgCc Dda2
zKyKsqmk9/GFzQ0hJPtdMjs=
=9O+r
-----END PGP SIGNATURE-----

Marc Munro <marc@bloodnok.com> writes:
> As you see, slony is attempting to enter one tuple
> ('374520943','22007','0') two times.
> Each previous time we have had this problem, rebuilding the indexes on
> slony log table (sl_log_1) has fixed the problem. I have not reindexed
> the table this time as I do not want to destroy any usable evidence.

Good. How big is the log table --- would it be possible for you to send
me the physical table and index files? (Not a pg_dump, the actual disk
files)

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

We have reproduced the problem again. This time it looks like vacuum is
not part of the picture. From the provider's log:

2006-06-29 14:02:41 CST DEBUG2 cleanupThread: 101.057 seconds for vacuuming

And from the subscriber's:

2006-06-29 13:00:43 PDT ERROR remoteWorkerThread_1: "insert into "public"."table_trans_attribute" (table_transaction_id,attribute_type,value) values ('374740387','22008','4000');

If my maths is correct and the logs are honest, the vacuum would have
started at 14:01:00 CST (13:01:PDT), about 20 seconds after we first
encounter the problem. The clocks on the two machines, though in
different timezones, are currently synced.

Tom, I will create another tarball of the sl_log_1 table and indexes.
Should be quite a bit smaller than the previous one.

__
Marc

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.3 (GNU/Linux)

iD8DBQBEpDVQUBr6u+c2wkERAmTZAJoDw9Xed1/cJ+CouZu2lkeQh2hfVACgheDH
2HBbvWdAV7zxwv/MMsjzD1o=
=7kfS
-----END PGP SIGNATURE-----

marc@bloodnok.com (Marc Munro) writes:
> As you see, slony is attempting to enter one tuple
> ('374520943','22007','0') two times.
>
> Each previous time we have had this problem, rebuilding the indexes on
> slony log table (sl_log_1) has fixed the problem. I have not reindexed
> the table this time as I do not want to destroy any usable evidence.

We have seen this phenomenon on 7.4.8 several times; pulled dumps of
sl_log_1 and index files that Jan Wieck looked at, which alas hasn't
led to a fix.

He did, mind you, find some concurrency pattern that led, if memory
serves, to 7.4.12's release. We had experienced cases where there was
some worse corruption that required that we rebuild replicas from
scratch :-(.
--
output = reverse("gro.mca" "@" "enworbbc")
http://cbbrowne.com/info/advocacy.html
"There is no psychiatrist in the world like a puppy licking your
face." -- Ben Williams

Marc Munro <marc@bloodnok.com> writes:
> Tom,
> we have a newer and much smaller (35M) file showing the same thing:

Thanks. Looking into this, what I find is that *both* indexes have
duplicated entries for the same heap tuple:

idx1:

Item 190 -- Length: 24 Offset: 3616 (0x0e20) Flags: USED
Block Id: 27806 linp Index: 2 Size: 24
Has Nulls: 0 Has Varwidths: 0

0e20: 00009e6c 02001800 01000000 0057d123 ...l.........W.#
0e30: 1a781200 00000000 .x......

Item 191 -- Length: 24 Offset: 3592 (0x0e08) Flags: USED
Block Id: 27806 linp Index: 2 Size: 24
Has Nulls: 0 Has Varwidths: 0

0e08: 00009e6c 02001800 01000000 0057d123 ...l.........W.#
0e18: 2e781200 00000000 .x......

idx2:

Item 127 -- Length: 16 Offset: 6144 (0x1800) Flags: USED
Block Id: 27806 linp Index: 2 Size: 16
Has Nulls: 0 Has Varwidths: 0

1800: 00009e6c 02001000 0057d123 00000000 ...l.....W.#....

Item 128 -- Length: 16 Offset: 6128 (0x17f0) Flags: USED
Block Id: 27806 linp Index: 2 Size: 16
Has Nulls: 0 Has Varwidths: 0

17f0: 00009e6c 02001000 0057d123 00000000 ...l.....W.#....

However, the two entries in idx1 contain different data!!

What I speculate right at the moment is that we are not looking at index
corruption at all, but at heap corruption: somehow, the first insertion
into ctid (27806,2) got lost and the same ctid got re-used for the next
inserted row. We fixed one bug like this before ...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

Ühel kenal päeval, N, 2006-06-29 kell 16:42, kirjutas Chris Browne:
> marc@bloodnok.com (Marc Munro) writes:
> > As you see, slony is attempting to enter one tuple
> > ('374520943','22007','0') two times.
> >
> > Each previous time we have had this problem, rebuilding the indexes on
> > slony log table (sl_log_1) has fixed the problem. I have not reindexed
> > the table this time as I do not want to destroy any usable evidence.
>
> We have seen this phenomenon on 7.4.8 several times; pulled dumps of
> sl_log_1 and index files that Jan Wieck looked at, which alas hasn't
> led to a fix.
>
> He did, mind you, find some concurrency pattern that led, if memory
> serves, to 7.4.12's release. We had experienced cases where there was
> some worse corruption that required that we rebuild replicas from
> scratch :-(.

How well did you check the C-language triggers and special slony
functions for possibly corrupting some backend/shared-mem structures ?

--
----------------
Hannu Krosing
Database Architect
Skype Technologies OÜ
Akadeemia tee 21 F, Tallinn, 12618, Estonia

Skype me: callto:hkrosing
Get Skype for free: http://www.skype.com


---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

Ühel kenal päeval, N, 2006-06-29 kell 17:23, kirjutas Tom Lane:
> Marc Munro <marc@bloodnok.com> writes:
> > Tom,
> > we have a newer and much smaller (35M) file showing the same thing:
>
> Thanks. Looking into this, what I find is that *both* indexes have
> duplicated entries for the same heap tuple:
>
....
> However, the two entries in idx1 contain different data!!
>
> What I speculate right at the moment is that we are not looking at index
> corruption at all, but at heap corruption: somehow, the first insertion
> into ctid (27806,2) got lost and the same ctid got re-used for the next
> inserted row. We fixed one bug like this before ...

Marc: do you have triggers on some replicated tables ?

I remember having some corruption in a database with weird circular
trigger structures, some of them being slony log triggers.

The thing that seemed to mess up something inside there, was when change
on parent rownt fired a trigger that changes child table rows and there
rows fired another trigger that changed the same parent row again.

--
----------------
Hannu Krosing
Database Architect
Skype Technologies OÜ
Akadeemia tee 21 F, Tallinn, 12618, Estonia

Skype me: callto:hkrosing
Get Skype for free: http://www.skype.com



---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings