BUG #13984: Multiple rows with the same primary key value exist.

The following bug has been logged on the website:

Bug reference: 13984
Logged by: Takayuki Tsunakawa
Email address: tsunakawa(dot)takay(at)jp(dot)fujitsu(dot)com
PostgreSQL version: 9.1.14
Operating system: Linux (RHEL 6.6) for Intel64
Description:

Hello,

Our customer have found multiple rows with the same primary key value in a
table during their test. I asked them to reproduce the problem with the
latest 9.1.20, but there doesn't seem to be a relevant bug fix through
9.1.15 to 9.1.20.

They are running some custom application. The transaction isolation level
is read committed. They insist that multiple concurrent transactions don't
modify the same row in the problematic table simultaneously.

They don't use advanced features like streaming replication or WAL
archiving. But they performed crash recovery testing.

The table definition is as follows. Here, I renamed the table and showed
just relevant columns.

... three columns of timestamp with timezone type
id | integer | not null default
nextval('my_table_id_seq'::regclass)
service_id | integer | not null
...
stats | text |
Indexes:
"my_table_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"my_table_service_id_fkey" FOREIGN KEY (service_id) REFERENCES
services(id)

For example, there are four rows with id = 1:

SELECT ctid, xmin, xmax, * FROM my_table;
--------------------------------------------------
-[ RECORD 1
]--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
ctid | (7,7)
xmin | 29036962
xmax | 0
...
id | 1
service_id | 5
...
-[ RECORD 2
]--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
ctid | (18,1)
xmin | 26677514
xmax | 0
...
id | 1
service_id | 5
...
-[ RECORD 3
]--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
ctid | (23,2)
xmin | 26677687
xmax | 0
...
id | 1
service_id | 5
...
-[ RECORD 4
]--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
ctid | (25,3)
xmin | 26677757
xmax | 0
...
id | 1
service_id | 5
...
--------------------------------------------------

On the other hand, the index scan (SELECT ctid, xmin, xmax FROM my_table
WHERE id = 1) only returns the first row shown above.

pageinspect against the four rows shows the following:

--------------------------------------------------
-[ RECORD 1
]-------------------------------------------------------------------------
lp | 7
lp_off | 3432
lp_flags | 1
lp_len | 678
t_xmin | 29036962
t_xmax | 0
t_field3 | 0
t_ctid | (7,7)
t_infomask2 | 32795
t_infomask | 10499
t_hoff | 32
t_bits |
110111111111111111111111101000000000000000000000000000000000000000000000
t_oid |

-[ RECORD 1
]-------------------------------------------------------------------------
lp | 1
lp_off | 6256
lp_flags | 1
lp_len | 1935
t_xmin | 26677514
t_xmax | 0
t_field3 | 0
t_ctid | (18,1)
t_infomask2 | 27
t_infomask | 10499
t_hoff | 32
t_bits |
110111111111111111111111101000000000000000000000000000000000000000000000
t_oid |

-[ RECORD 1
]-------------------------------------------------------------------------
lp | 2
lp_off | 4400
lp_flags | 1
lp_len | 1935
t_xmin | 26677687
t_xmax | 0
t_field3 | 0
t_ctid | (23,2)
t_infomask2 | 27
t_infomask | 10499
t_hoff | 32
t_bits |
110111111111111111111111101000000000000000000000000000000000000000000000
t_oid |

-[ RECORD 1
]-------------------------------------------------------------------------
lp | 3
lp_off | 4400
lp_flags | 1
lp_len | 1935
t_xmin | 26677757
t_xmax | 0
t_field3 | 0
t_ctid | (25,3)
t_infomask2 | 27
t_infomask | 10499
t_hoff | 32
t_bits |
110111111111111111111111101000000000000000000000000000000000000000000000
t_oid |
--------------------------------------------------

Here:

* The t_infomask of four tuples are all 0x2903 (HEAP_UPDATED |
HEAP_XMAX_INVALID | HEAP_XMIN_COMMITTED | HEAP_HASVARWIDTH | HEAP_HASNULL).

* The t_infomask2 of the first tuple is 27 (=0x1b), which matches the number
of columns in the table.

* The t_infomask2 of the remaining three tuples are 0x801b. HEAP_ONLY_TUPLE
is set.

The size of the data file for the primary key index is only 16KB.
pageinspect shows the following:

SELECT * FROM bt_metap('my_table_pkey');
--------------------------------------------------
-[ RECORD 1 ]-----
magic | 340322
version | 2
root | 1
level | 0
fastroot | 1
fastlevel | 0
--------------------------------------------------

SELECT * FROM bt_page_stats('my_table_pkey', 1);
--------------------------------------------------
-[ RECORD 1 ]-+-----
blkno | 1
type | l
live_items | 6
dead_items | 0
avg_item_size | 16
page_size | 8192
free_size | 8028
btpo_prev | 0
btpo_next | 0
btpo | 0
btpo_flags | 3
--------------------------------------------------

SELECT * FROM bt_page_items('my_table_pkey', 1);
--------------------------------------------------
-[ RECORD 1 ]-----------------------
itemoffset | 1
ctid | (7,1)
itemlen | 16
nulls | f
vars | f
data | 01 00 00 00 00 00 00 00
-[ RECORD 2 ]-----------------------
itemoffset | 2
ctid | (0,2)
itemlen | 16
nulls | f
vars | f
data | 02 00 00 00 00 00 00 00
-[ RECORD 3 ]-----------------------
itemoffset | 3
ctid | (16,2)
itemlen | 16
nulls | f
vars | f
data | 03 00 00 00 00 00 00 00
-[ RECORD 4 ]-----------------------
itemoffset | 4
ctid | (8,1)
itemlen | 16
nulls | f
vars | f
data | 04 00 00 00 00 00 00 00
-[ RECORD 5 ]-----------------------
itemoffset | 5
ctid | (3,2)
itemlen | 16
nulls | f
vars | f
data | 05 00 00 00 00 00 00 00
-[ RECORD 6 ]-----------------------
itemoffset | 6
ctid | (5,4)
itemlen | 16
nulls | f
vars | f
data | 06 00 00 00 00 00 00 00
--------------------------------------------------

Finally, I picked up some suspicious messages from the server log.

WARNING: AbortTransaction while in COMMIT state
WARNING: autovacuum worker started without a worker entry
WARNING: worker took too long to start; canceled
WARNING: pgstat wait timeout
WARNING: relation "my_table" page 15 is uninitialized --- fixing

ERROR: could not extend file "base/16384/17299": No space left on device
ERROR: could not read block 10 in file "base/16386/18153": read only 0 of
8192 bytes

FATAL: semop(id=557071) failed: Identifier removed
FATAL: terminating connection due to administrator command
FATAL: unsupported frontend protocol 27265.28208: server supports 1.0 to
3.0

PANIC: semop(id=589840) failed: Identifier removed

Regards
Takayuki Tsunakawa