Thread: BUG #8757: Dublicate rows, broken primary key.

The following bug has been logged on the website:

Bug reference:      8757
Logged by:          Dmitry Sarafannikov
Email address:      dimon99901@mail.ru
PostgreSQL version: 9.3.2
Operating system:   Debian 7.3
Description:

Hi. We have newly migrated from 9.1.10 to 9.3.2 version with pg_upgrade and
find where strange behaviour.
We have table with 70 rows:
=# \d blog.blogs
                                               Table "blog.blogs"
      Column       |            Type             |
Modifiers
-------------------+-----------------------------+--------------------------------------------------------------
 id_blog           | bigint                      | not null default
nextval('blog.blogs_id_blog_seq'::regclass)
 blog_url          | character varying(50)       | not null
......
......
Indexes:
    "pk_blog_blogs" PRIMARY KEY, btree (id_blog)
Referenced by:
    TABLE "blog.blog_contest" CONSTRAINT "fk_blog_blog_contest_blog" FOREIGN
KEY (id_blog) REFERENCES blog.blogs(id_blog)
    TABLE "blog.post_votes" CONSTRAINT "fk_blog_post_votes_blog" FOREIGN KEY
(id_blog) REFERENCES blog.blogs(id_blog)
    TABLE "blog.post_visits" CONSTRAINT "fk_post_last_visits_blog" FOREIGN
KEY (id_blog) REFERENCES blog.blogs(id_blog)






Strange behaviour observed with row id_blog = 26, blog_url = 'orders'.
We have no deletes or insertes, but have intensive updates on this table.
And we have intensive inserts in tables blog.post_votes and
blog.post_visits.


In the random time. We get this error:
ERROR: insert or update on table "post_visits" violates foreign key
constraint "fk_post_last_visits_blog"
Detail: Key (id_blog)=(26) is not present in table "blogs".
Context: SQL statement "insert into blog.post_visits (...)


and this:
ERROR: insert or update on table "post_votes" violates foreign key
constraint "fk_blog_post_votes_blog"
Detail: Key (id_blog)=(26) is not present in table "blogs".
Context: SQL statement "insert into blog.post_votes (...)


And we look on the table blog.blogs;


select * from blog.blogs where id_blog = 26;
no rows.


select * from blog.blogs where blog_url = 'orders';
We have 2 same rows (but sometimes 3 rows) with id_blog = 26!!!


explain analyze select * from blog.blogs where id_blog = 26;
                                                      QUERY PLAN

-----------------------------------------------------------------------------------------------------------------------
 Index Scan using pk_blog_blogs on blogs  (cost=0.14..8.17 rows=1 width=781)
(actual time=0.028..0.042 rows=1 loops=1)
   Index Cond: (id_blog = 26)
 Total runtime: 0.093 ms



So, primary key have dublicate rows and is broken.
Then we drop 3 references from tables blog.blog_contest, blog.post_votes,
blog.post_visits.
delete from blog.blogs where blog_url = 'orders';
insert into blog.blogs (id_blog, blog_url, ...) values (26, 'orders', ...);
Create foreign keys and this ok.
Through the several hours this situation repeated. Then repeated again, and
again.


And then we just drop the 2 of 3 referenses to this tables (in table
blog.blog_contes we have no rows, updates, inserts with id_blog = 26). We
drop references from tables blog.post_votes and blog.post_visits. And this
situation don't repeated along more then 24 hours.


This is bug?

Can you please share the output of pg_controldata?

--
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

pg_control version number: 937
Catalog version number: 201306121
Database system identifier: 5965523135297743807
Database cluster state: in production
pg_control last modified: Thu 09 Jan 2014 04:23:43 PM UTC
Latest checkpoint location: 263C/A2B28550
Prior checkpoint location: 263C/9AC7F608
Latest checkpoint's REDO location: 263C/9EC81058
Latest checkpoint's REDO WAL file: 000000010000263C0000009E
Latest checkpoint's TimeLineID: 1
Latest checkpoint's PrevTimeLineID: 1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID: 0/3917877569
Latest checkpoint's NextOID: 148656505
Latest checkpoint's NextMultiXactId: 3400755
Latest checkpoint's NextMultiOffset: 505332
Latest checkpoint's oldestXID: 3718614222
Latest checkpoint's oldestXID's DB: 16435
Latest checkpoint's oldestActiveXID: 3917877507
Latest checkpoint's oldestMultiXid: 3188075
Latest checkpoint's oldestMulti's DB: 0
Time of latest checkpoint: Thu 09 Jan 2014 04:21:13 PM UTC
Fake LSN counter for unlogged rels: 0/1
Minimum recovery ending location: 0/0
Min recovery ending loc's timeline: 0
Backup start location: 0/0
Backup end location: 0/0
End-of-backup record required: no
Current wal_level setting: hot_standby
Current max_connections setting: 200
Current max_prepared_xacts setting: 0
Current max_locks_per_xact setting: 64
Maximum data alignment: 8
Database block size: 8192
Blocks per segment of large relation: 131072
WAL block size: 8192
Bytes per WAL segment: 16777216
Maximum length of identifiers: 64
Maximum columns in an index: 32
Maximum size of a TOAST chunk: 1996
Date/time type storage: 64-bit integers
Float4 argument passing: by value
Float8 argument passing: by value
Data page checksum version: 0


And, we noticed, that updates on rows where id_blog = 26 executes more longer then updates on other rows of this table.
Четверг, 9 января 2014, 12:38 -03:00 от Alvaro Herrera <alvherre@2ndquadrant.com>:

Дмитрий Сарафанников wrote:
>  Hey ? I need the answer or some information.

The first thing I would check is whether the values are present in the
table and not the index, or are they missing altogether.  Please try
searching for them with enable_indexscan and enable_bitmapscan both set
to OFF.  This should force a sequential scan and will tell you if the
values are completely missing from the table, or just missing in the
index.

If missing from the table, I would suspect a tqual.c problem, perhaps
related to multixacts, as you see to have some use of them.

>
> Четверг,  9 января 2014, 20:27 +04:00 от Дмитрий Сарафанников <dimon99901@mail.ru>:
> >pg_control version number: 937
> >Catalog version number: 201306121
> >Database system identifier: 5965523135297743807
> >Database cluster state: in production
> >pg_control last modified: Thu 09 Jan 2014 04:23:43 PM UTC
> >Latest checkpoint location: 263C/A2B28550
> >Prior checkpoint location: 263C/9AC7F608
> >Latest checkpoint's REDO location: 263C/9EC81058
> >Latest checkpoint's REDO WAL file: 000000010000263C0000009E
> >Latest checkpoint's TimeLineID: 1
> >Latest checkpoint's PrevTimeLineID: 1
> >Latest checkpoint's full_page_writes: on
> >Latest checkpoint's NextXID: 0/3917877569
> >Latest checkpoint's NextOID: 148656505
> >Latest checkpoint's NextMultiXactId: 3400755
> >Latest checkpoint's NextMultiOffset: 505332
> >Latest checkpoint's oldestXID: 3718614222
> >Latest checkpoint's oldestXID's DB: 16435
> >Latest checkpoint's oldestActiveXID: 3917877507
> >Latest checkpoint's oldestMultiXid: 3188075
> >Latest checkpoint's oldestMulti's DB: 0
> >Time of latest checkpoint: Thu 09 Jan 2014 04:21:13 PM UTC
> >Fake LSN counter for unlogged rels: 0/1
> >Minimum recovery ending location: 0/0
> >Min recovery ending loc's timeline: 0
> >Backup start location: 0/0
> >Backup end location: 0/0
> >End-of-backup record required: no
> >Current wal_level setting: hot_standby
> >Current max_connections setting: 200
> >Current max_prepared_xacts setting: 0
> >Current max_locks_per_xact setting: 64
> >Maximum data alignment: 8
> >Database block size: 8192
> >Blocks per segment of large relation: 131072
> >WAL block size: 8192
> >Bytes per WAL segment: 16777216
> >Maximum length of identifiers: 64
> >Maximum columns in an index: 32
> >Maximum size of a TOAST chunk: 1996
> >Date/time type storage: 64-bit integers
> >Float4 argument passing: by value
> >Float8 argument passing: by value
> >Data page checksum version: 0
> >
> >
> >And, we noticed, that updates on rows where id_blog = 26 executes more longer then updates on other rows of this
table.
> >Четверг,  9 января 2014, 12:38 -03:00 от Alvaro Herrera <alvherre@2ndquadrant.com>:
> >>
> >>
> >>Can you please share the output of pg_controldata?
> >>
> >>--
> >>Álvaro Herrera  http://www.2ndQuadrant.com/
> >>PostgreSQL Development, 24x7 Support, Training & Services
> >
> >
> >--
> >Дмитрий Сарафанников
>
>
> --
> Дмитрий Сарафанников


--
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services