Strange problem with create table as select * from table;

On Thursday, November 03, 2011 1:25:58 am hubert depesz lubaczewski wrote:

Hi
We have pretty weird situation, which seems to be impossible, but perhaps
you'll notice something that will let me fix the problem.

System: SunOS 5.11 snv_130
Pg: PostgreSQL 8.4.7 on i386-pc-solaris2.11, compiled by cc: Sun C 5.10
SunOS_i386 2009/06/03, 64-bit

I also verified that there are no concurrent updates that would set
xobject_id to -1, so it's not a problem of isolation.

During the night I repeated the procedure and the rows that got duplicated
seem to be the same - at the very least - the same magic_id.

Does above seem sensible for anyone? Any suggestions on what could be
broken?

Do the xobject_id values have other negative numbers or is -1 just a special
case? The only thing I can think of is a corrupted index on xobject_id.

Best regards,

depesz

--
Adrian Klaver
adrian.klaver@gmail.com

On Thu, Nov 03, 2011 at 07:00:30AM -0700, Adrian Klaver wrote:

I also verified that there are no concurrent updates that would set
xobject_id to -1, so it's not a problem of isolation.

During the night I repeated the procedure and the rows that got duplicated
seem to be the same - at the very least - the same magic_id.

Does above seem sensible for anyone? Any suggestions on what could be
broken?

Do the xobject_id values have other negative numbers or is -1 just a special
case? The only thing I can think of is a corrupted index on xobject_id.

minimal xobject_id in source table is 1000.

index on xobject_id might be corrupted, but it doesn't explain that I
don't see duplicates with group_by/having query on xobjects, which uses
seqscan:

$ explain select xobject_id, count(*) from sssssss.xobjects group by 1 having count(*) > 1;
QUERY PLAN
---------------------------------------------------------------------------------
GroupAggregate (cost=11718280.34..12682724.26 rows=35070688 width=4)
Filter: (count(*) > 1)
-> Sort (cost=11718280.34..11805957.06 rows=35070688 width=4)
Sort Key: xobject_id
-> Seq Scan on xobjects (cost=0.00..5884815.88 rows=35070688 width=4)
(5 rows)

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/

On 3 November 2011 15:15, hubert depesz lubaczewski <depesz@depesz.com> wrote:

Do the xobject_id values have other negative numbers or is -1 just a special
case? The only thing I can think of is a corrupted index on xobject_id.

minimal xobject_id in source table is 1000.

index on xobject_id might be corrupted, but it doesn't explain that I
don't see duplicates with group_by/having query on xobjects, which uses
seqscan:

Actually, it does. A sequential scan doesn't use the index.

--
If you can't see the forest for the trees,
Cut the trees and you'll see there is no forest.

On Thu, Nov 03, 2011 at 03:19:36PM +0100, Alban Hertroys wrote:

On 3 November 2011 15:15, hubert depesz lubaczewski <depesz@depesz.com> wrote:

Do the xobject_id values have other negative numbers or is -1 just a special
case? The only thing I can think of is a corrupted index on xobject_id.

minimal xobject_id in source table is 1000.

index on xobject_id might be corrupted, but it doesn't explain that I
don't see duplicates with group_by/having query on xobjects, which uses
seqscan:

Actually, it does. A sequential scan doesn't use the index.

sure. but so isn't create table as.

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/

hubert depesz lubaczewski <depesz@depesz.com> writes:

index on xobject_id might be corrupted, but it doesn't explain that I
don't see duplicates with group_by/having query on xobjects, which uses
seqscan:

I was just going to ask you to check that. Weird as can be.

Does plain old "SELECT COUNT(*)" show a difference between the two
tables?

Do you get similar misbehavior if you break the CREATE TABLE AS into a
CREATE and an INSERT/SELECT? Also, please note the rowcount returned
by INSERT/SELECT and see how it matches up with the tables afterwards.

Does turning synchronize_seqscans off affect the behavior?

regards, tom lane

On Thu, Nov 03, 2011 at 10:55:20AM -0400, Tom Lane wrote:

index on xobject_id might be corrupted, but it doesn't explain that I
don't see duplicates with group_by/having query on xobjects, which uses
seqscan:

I was just going to ask you to check that. Weird as can be.
Does plain old "SELECT COUNT(*)" show a difference between the two
tables?

yes. the xobjects table is written to quite a lot and turning it off is
not an option.

Do you get similar misbehavior if you break the CREATE TABLE AS into a
CREATE and an INSERT/SELECT? Also, please note the rowcount returned
by INSERT/SELECT and see how it matches up with the tables afterwards.

Does turning synchronize_seqscans off affect the behavior?

interesting. will test and let you know. the test will take couple of
hours, though.

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/

On Thursday, November 03, 2011 7:15:22 am hubert depesz lubaczewski wrote:

On Thu, Nov 03, 2011 at 07:00:30AM -0700, Adrian Klaver wrote:

I also verified that there are no concurrent updates that would set
xobject_id to -1, so it's not a problem of isolation.

During the night I repeated the procedure and the rows that got
duplicated seem to be the same - at the very least - the same
magic_id.

Does above seem sensible for anyone? Any suggestions on what could be
broken?

Do the xobject_id values have other negative numbers or is -1 just a
special case? The only thing I can think of is a corrupted index on
xobject_id.

minimal xobject_id in source table is 1000.

So just to be clear there is and never has been a -1 value for xobject_id in the
source table?
So a select count(*) from sssssss.xobjects where xobject_id = -1 on the source
table yields 0?

depesz

--
Adrian Klaver
adrian.klaver@gmail.com

On Thu, Nov 03, 2011 at 08:04:19AM -0700, Adrian Klaver wrote:

So just to be clear there is and never has been a -1 value for xobject_id in the
source table?

yes. min value of xobject_id is 1000, and we had trigger in place on the
table which logged all inserts/updates/deletes and the value -1 never
showed up (At least in the last couple of days, during which i was
making the copies).

So a select count(*) from sssssss.xobjects where xobject_id = -1 on the source
table yields 0?

yes, that's correct. both using index, and usingf seq scan.

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/

On 3 November 2011 09:25, hubert depesz lubaczewski <depesz@depesz.com> wrote:

All looks good. pg_dump of the table also doesn't show any strange problems, and is duplicate free. But:

$ create table zzz as select * from sssssss.xobjects;
SELECT

$ select xobject_id, count(*) from zzz group by 1 having count(*) > 1 order by 2 desc;
 xobject_id | count
------------+-------
        -1 |    40
(1 row)

Can you verify that these queries both do actually use a sequential
scan, and not, for some reason, an index scan? Just to rule out the
index corruption scenario.
You (or someone near you) might have disabled seqscans, for example.

Another thought: Is it possible that xobject_id just happens to be
used internally as a hidden field by Postgres or by an extension? That
would be another explanation for seeing -1 or duplicates in that
column.

If that's the case, I would have expected an error on creation of that table.

And lastly, is this behaviour after copying a table into a new one
reproducible or did it happen just once?

--
If you can't see the forest for the trees,
Cut the trees and you'll see there is no forest.

On Thursday, November 03, 2011 8:05:38 am hubert depesz lubaczewski wrote:

On Thu, Nov 03, 2011 at 08:04:19AM -0700, Adrian Klaver wrote:

So just to be clear there is and never has been a -1 value for xobject_id
in the source table?

yes. min value of xobject_id is 1000, and we had trigger in place on the
table which logged all inserts/updates/deletes and the value -1 never
showed up (At least in the last couple of days, during which i was
making the copies).

So a select count(*) from sssssss.xobjects where xobject_id = -1 on the
source table yields 0?

yes, that's correct. both using index, and usingf seq scan.

Hmmm. Now we await the results of the tests Tom suggested. Just a thought, any
other strange behavior, hiccups in the database over the past couple of days?

Best regards,

depesz

--
Adrian Klaver
adrian.klaver@gmail.com

On Thu, Nov 03, 2011 at 04:21:37PM +0100, Alban Hertroys wrote:

On 3 November 2011 09:25, hubert depesz lubaczewski <depesz@depesz.com> wrote:

All looks good. pg_dump of the table also doesn't show any strange problems, and is duplicate free. But:

$ create table zzz as select * from sssssss.xobjects;
SELECT

$ select xobject_id, count(*) from zzz group by 1 having count(*) > 1 order by 2 desc;
 xobject_id | count
------------+-------
        -1 |    40
(1 row)

Can you verify that these queries both do actually use a sequential
scan, and not, for some reason, an index scan? Just to rule out the
index corruption scenario.
You (or someone near you) might have disabled seqscans, for example.

yes, i tested it with explain.

Another thought: Is it possible that xobject_id just happens to be
used internally as a hidden field by Postgres or by an extension? That
would be another explanation for seeing -1 or duplicates in that
column.

no. it's not a special field. just plain old "something_id", with
underscore, so it is not special in any way.

If that's the case, I would have expected an error on creation of that table.
And lastly, is this behaviour after copying a table into a new one
reproducible or did it happen just once?

fully reproductible, as i mentioned at the end of my original mail.

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/

On Thu, Nov 03, 2011 at 08:23:01AM -0700, Adrian Klaver wrote:

On Thursday, November 03, 2011 8:05:38 am hubert depesz lubaczewski wrote:

On Thu, Nov 03, 2011 at 08:04:19AM -0700, Adrian Klaver wrote:

So just to be clear there is and never has been a -1 value for xobject_id
in the source table?

yes. min value of xobject_id is 1000, and we had trigger in place on the
table which logged all inserts/updates/deletes and the value -1 never
showed up (At least in the last couple of days, during which i was
making the copies).

So a select count(*) from sssssss.xobjects where xobject_id = -1 on the
source table yields 0?

yes, that's correct. both using index, and usingf seq scan.

Hmmm. Now we await the results of the tests Tom suggested. Just a thought, any
other strange behavior, hiccups in the database over the past couple of days?

no. it's doing it's job without problems.

other tests are running, but simple question - how to get number of rows
affected from psql?

create table xxx as select * from xobjects;
returns just:
SELECT

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/

hubert depesz lubaczewski <depesz@depesz.com> writes:

other tests are running, but simple question - how to get number of rows
affected from psql?

create table xxx as select * from xobjects;
returns just:
SELECT

We fixed that in 9.0, but 8.4 won't provide the count (unless you care to
patch it). That's why I suggested doing a separate insert/select.

regards, tom lane

On Thursday, November 03, 2011 8:30:34 am hubert depesz lubaczewski wrote:

On Thu, Nov 03, 2011 at 08:23:01AM -0700, Adrian Klaver wrote:

On Thursday, November 03, 2011 8:05:38 am hubert depesz lubaczewski wrote:

On Thu, Nov 03, 2011 at 08:04:19AM -0700, Adrian Klaver wrote:

So just to be clear there is and never has been a -1 value for
xobject_id in the source table?

yes. min value of xobject_id is 1000, and we had trigger in place on
the table which logged all inserts/updates/deletes and the value -1
never showed up (At least in the last couple of days, during which i
was making the copies).

So a select count(*) from sssssss.xobjects where xobject_id = -1 on
the source table yields 0?

yes, that's correct. both using index, and usingf seq scan.

Hmmm. Now we await the results of the tests Tom suggested. Just a
thought, any other strange behavior, hiccups in the database over the
past couple of days?

no. it's doing it's job without problems.

other tests are running, but simple question - how to get number of rows
affected from psql?

See Toms answer

create table xxx as select * from xobjects;
returns just:
SELECT

The thing that has me puzzled is shown below from you original post:

$ select xobject_id, magic_id from zzz where magic_id in ( 32440447, 32047231,
32505983);
xobject_id | magic_id
------------+----------
35858705 | 32505983
35793169 | 32440447
-1 | 32440447
-1 | 32047231
-1 | 32505983
-1 | 32505983
35399951 | 32047231
-1 | 32047231
(8 rows)

Looks like multiple tuples of the same row where magic_id(s) of 32505983 and
32047231 where touched three times and 32440447 twice. For some reason the
original table is seeing only the most recent version while the CREATE AS is
pulling it and past versions. Some sort of visibility problem, exactly what is
beyond me at this point.

Best regards,

depesz

--
Adrian Klaver
adrian.klaver@gmail.com

On Thu, Nov 03, 2011 at 10:55:20AM -0400, Tom Lane wrote:

hubert depesz lubaczewski <depesz@depesz.com> writes:

index on xobject_id might be corrupted, but it doesn't explain that I
don't see duplicates with group_by/having query on xobjects, which uses
seqscan:

I was just going to ask you to check that. Weird as can be.

Does plain old "SELECT COUNT(*)" show a difference between the two
tables?

Do you get similar misbehavior if you break the CREATE TABLE AS into a
CREATE and an INSERT/SELECT? Also, please note the rowcount returned
by INSERT/SELECT and see how it matches up with the tables afterwards.

Does turning synchronize_seqscans off affect the behavior?

So, did some tests:

$ select count(*) from sssssss.xobjects;
count
----------
35179058
(1 row)

$ create table qqq as select * from sssssss.xobjects;
SELECT

$ select count(*) from qqq;
count
----------
35179631
(1 row)

$ select count(*) from qqq where xobject_id = -1;
count
-------
40
(1 row)

$ drop table qqq;
DROP TABLE

$ select count(*) from sssssss.xobjects;
count
----------
35182687
(1 row)

$ create table qqq ( like sssssss.xobjects );
CREATE TABLE

$ insert into qqq select * from sssssss.xobjects;
INSERT 0 35182962

$ select count(*) from qqq;
count
----------
35182962
(1 row)

$ select count(*) from qqq where xobject_id = -1;
count
-------
40
(1 row)

$ drop table qqq;
DROP TABLE

$ set synchronize_seqscans = off;
SET

$ create table qqq as select * from sssssss.xobjects;

SELECT
$ select count(*) from qqq;
count
----------
35185653
(1 row)

$ select count(*) from qqq where xobject_id = -1;
count
-------
40
(1 row)

$ drop table qqq;
DROP TABLE

$ create table qqq ( like sssssss.xobjects );
CREATE TABLE

$ insert into qqq select * from sssssss.xobjects;
INSERT 0 35188896

$ select count(*) from qqq;
count
----------
35188896
(1 row)

$ select count(*) from qqq where xobject_id = -1;
count
-------
40
(1 row)

$ drop table qqq;
DROP TABLE

as you can see counts of rows in created table are more or less
sensible, but whatever method I used - create table as, insert into,
using sychronized_scans (initially) or not (later) - copy of the table,
as long as it's in database, has 40 those "-1" rows.

one note - maybe it wasn't clear from my original mail - when I did
pg_dump of the xobjects table, it didn't have -1 rows.

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/

On Thursday, November 03, 2011 1:03:12 pm hubert depesz lubaczewski wrote:

On Thu, Nov 03, 2011 at 10:55:20AM -0400, Tom Lane wrote:

So, did some tests:

as you can see counts of rows in created table are more or less
sensible, but whatever method I used - create table as, insert into,
using sychronized_scans (initially) or not (later) - copy of the table,
as long as it's in database, has 40 those "-1" rows.

At least it is consistent:)
Characteristics of those forty rows.
1) creation_tsz clustered?
2) magic_id in a range?
3) Non -1 xobject_id in a range?
4) Any other field show a similarity?

one note - maybe it wasn't clear from my original mail - when I did
pg_dump of the xobjects table, it didn't have -1 rows.

--
Adrian Klaver
adrian.klaver@gmail.com

Adrian Klaver <adrian.klaver@gmail.com> writes:

On Thursday, November 03, 2011 1:03:12 pm hubert depesz lubaczewski wrote:

as you can see counts of rows in created table are more or less
sensible, but whatever method I used - create table as, insert into,
using sychronized_scans (initially) or not (later) - copy of the table,
as long as it's in database, has 40 those "-1" rows.

At least it is consistent:)

Yeah, it wasn't clear before, but it looks like there are specific
rows that there's something wrong with.

Characteristics of those forty rows.
1) creation_tsz clustered?
2) magic_id in a range?
3) Non -1 xobject_id in a range?
4) Any other field show a similarity?

I would like to know the ctid's of the -1 rows in the copied table,
along with the ctid's of the rows they share magic_ids with, and
the ctid's of the rows with those same magic_ids in the original.
I'm wondering whether the affected rows are physically clustered ...

regards, tom lane

I would like to know the ctid's of the -1 rows in the copied table,
along with the ctid's of the rows they share magic_ids with, and
the ctid's of the rows with those same magic_ids in the original.
I'm wondering whether the affected rows are physically clustered ...

i tried:
create table qqq as select cmax as o_cmax, xmax as o_xmax, cmin as
o_cmin, xmin as o_xmin, ctid as o_ctid, * from sssssss.xobjects;

but the resulting table didn't have -1 values:
$ select xobject_id, count(*) from qqq group by 1 having count(*) > 1;
xobject_id | count
------------+-------
(0 rows)

$ select o_cmax,o_xmax,o_cmin,o_xmin,o_ctid, xobject_id, order_id from qqq where xobject_id = -1;
o_cmax | o_xmax | o_cmin | o_xmin | o_ctid | xobject_id | order_id
--------+--------+--------+--------+--------+------------+----------
(0 rows)

i'm checking now something else, but later will try to get better grasp on those bad rows.

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/

hubert depesz lubaczewski <depesz@depesz.com> writes:

i tried:
create table qqq as select cmax as o_cmax, xmax as o_xmax, cmin as
o_cmin, xmin as o_xmin, ctid as o_ctid, * from sssssss.xobjects;

but the resulting table didn't have -1 values:

Oh, that's pretty interesting ... suggests that the targetlist has to be
exactly "select *". We have some minor optimizations for that case,
though nothing that could result in extra rows AFAICS.

Are there any dropped columns in the original table? Try

select * from pg_attribute where attrelid = 'sssssss.xobjects'::regclass
and attisdropped;

regards, tom lane