Обсуждение: BUG #6601: Inconsistent behavior of ALTER TABLE ADD COLUMN

Поиск
Список
Период
Сортировка

BUG #6601: Inconsistent behavior of ALTER TABLE ADD COLUMN

От
jon.plotky@gmail.com
Дата:
The following bug has been logged on the website:

Bug reference:      6601
Logged by:          jon
Email address:      jon.plotky@gmail.com
PostgreSQL version: 8.4.7
Operating system:   RedHat Enterprise Linux 6.2 (Linux version 2.6.32)
Description:=20=20=20=20=20=20=20=20

Not sure if this is a bug or not.  Would like to know what (if any) behavior
is guaranteed about updates to the pg_attribute catalog table.

Issue: After adding one new column to each of two different tables, querying
pg_attribute shows the new column in one table but not the other.  This is a
problem for ActiveRecord, which tries to  maintain its table model based on
querying pg_attribute.

Facts:
- Behavior is repeatable on different servers/databases
- After a commit the pg_attribute table shows the new column in both tables
- Postgresql log shows difference after the two ALTER TABLE statements (see
below), with a "forked new backend" message always following the ALTER TABLE
that does not update pg_attribute. Don't know if this has anything to do
with anything, but the log messages are always the same
- No difference after adding "nop" ALTER TABLE to cause a "table rewrite" as
mentioned at http://www.postgresql.org/docs/8.4/static/sql-altertable.html


Postgresql log of ALTER TABLE that immediately updates pg_attribute:
2012-04-18 00:06:27.449 EDT|postgres|mcp_production|DEBUG:=20
StartTransactionCommand
2012-04-18 00:06:27.449 EDT|postgres|mcp_production|STATEMENT:  ALTER TABLE
"users" ADD COLUMN "fo_mapping_id" integer
2012-04-18 00:06:27.450 EDT|postgres|mcp_production|LOG:  statement: ALTER
TABLE "users" ADD COLUMN "fo_mapping_id" integer
2012-04-18 00:06:27.450 EDT|postgres|mcp_production|DEBUG:  ProcessUtility
2012-04-18 00:06:27.450 EDT|postgres|mcp_production|STATEMENT:  ALTER TABLE
"users" ADD COLUMN "fo_mapping_id" integer
2012-04-18 00:06:27.450 EDT|postgres|mcp_production|DEBUG:=20
CommitTransactionCommand
2012-04-18 00:06:27.450 EDT|postgres|mcp_production|STATEMENT:  ALTER TABLE
"users" ADD COLUMN "fo_mapping_id" integer
2012-04-18 00:06:27.452 EDT|postgres|mcp_production|DEBUG:=20
StartTransactionCommand
2012-04-18 00:06:27.452 EDT|postgres|mcp_production|STATEMENT:  SELECT id
FROM greetings WHERE user_id=3D284 limit 1


Postgresql log of ALTER TABLE that does not update pg_attribute:
2012-04-18 00:06:27.558 EDT|postgres|mcp_production|DEBUG:=20
StartTransactionCommand
2012-04-18 00:06:27.558 EDT|postgres|mcp_production|STATEMENT:  ALTER TABLE
"organizations" ADD COLUMN "default_foid" integer
2012-04-18 00:06:27.558 EDT|postgres|mcp_production|LOG:  statement: ALTER
TABLE "organizations" ADD COLUMN "default_foid" integer
2012-04-18 00:06:27.558 EDT|postgres|mcp_production|DEBUG:  ProcessUtility
2012-04-18 00:06:27.558 EDT|postgres|mcp_production|STATEMENT:  ALTER TABLE
"organizations" ADD COLUMN "default_foid" integer
2012-04-18 00:06:27.558 EDT|postgres|mcp_production|DEBUG:=20
CommitTransactionCommand
2012-04-18 00:06:27.558 EDT|postgres|mcp_production|STATEMENT:  ALTER TABLE
"organizations" ADD COLUMN "default_foid" integer
2012-04-18 00:06:27.580 EDT|||DEBUG:  forked new backend, pid=3D4626 socket=
=3D8
2012-04-18 00:06:27.580 EDT|postgres|mcp_production|DEBUG:  postgres
child[4626]: starting with (
2012-04-18 00:06:27.580 EDT|postgres|mcp_production|DEBUG:      postgres
2012-04-18 00:06:27.580 EDT|postgres|mcp_production|DEBUG:      -v196608
2012-04-18 00:06:27.580 EDT|postgres|mcp_production|DEBUG:      -y
2012-04-18 00:06:27.580 EDT|postgres|mcp_production|DEBUG:=20=20=20=20=20
mcp_production
2012-04-18 00:06:27.580 EDT|postgres|mcp_production|DEBUG:  )
2012-04-18 00:06:27.580 EDT|postgres|mcp_production|DEBUG:  InitPostgres
2012-04-18 00:06:27.580 EDT|postgres|mcp_production|DEBUG:  my backend id is
49
2012-04-18 00:06:27.581 EDT|postgres|mcp_production|DEBUG:=20
StartTransaction
2012-04-18 00:06:27.581 EDT|postgres|mcp_production|DEBUG:  name: unnamed;
blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1,
children:
2012-04-18 00:06:27.582 EDT|postgres|mcp_production|DEBUG:=20
CommitTransaction
2012-04-18 00:06:27.582 EDT|postgres|mcp_production|DEBUG:  name: unnamed;
blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1,
children:

Re: BUG #6601: Inconsistent behavior of ALTER TABLE ADD COLUMN

От
Tom Lane
Дата:
jon.plotky@gmail.com writes:
> Issue: After adding one new column to each of two different tables, querying
> pg_attribute shows the new column in one table but not the other.

This is a bit hard to believe, and your log extract certainly doesn't
provide any evidence to support the statement.  Could we see a complete
self-contained test case?

> - Postgresql log shows difference after the two ALTER TABLE statements (see
> below), with a "forked new backend" message always following the ALTER TABLE
> that does not update pg_attribute. Don't know if this has anything to do
> with anything, but the log messages are always the same

That only suggests a new incoming connection, which seems probably
unrelated.  However, if that new connection is what's going to examine
pg_attribute, maybe the issue is that it's looking before the ALTER has
committed?

            regards, tom lane

Re: BUG #6601: Inconsistent behavior of ALTER TABLE ADD COLUMN

От
Jon Plotky
Дата:
On Wed, Apr 18, 2012 at 7:44 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> jon.plotky@gmail.com writes:
> > Issue: After adding one new column to each of two different tables, que=
rying
> > pg_attribute shows the new column in one table but not the other.
>
> This is a bit hard to believe, and your log extract certainly doesn't
> provide any evidence to support the statement. =A0Could we see a complete
> self-contained test case?
>
> > - Postgresql log shows difference after the two ALTER TABLE statements =
(see
> > below), with a "forked new backend" message always following the ALTER =
TABLE
> > that does not update pg_attribute. Don't know if this has anything to do
> > with anything, but the log messages are always the same
>
> That only suggests a new incoming connection, which seems probably
> unrelated. =A0However, if that new connection is what's going to examine
> pg_attribute, maybe the issue is that it's looking before the ALTER has
> committed?

This is what's happening.  The stack is Rails, ActiveRecord,
connection pooler pgbouncer, and Postgresql.  The ActiveRecord class
that doesn't see the column update uses a specific connection pool.
Unfortunately ActiveRecord uses the default pool connection to alter
the table associated with that class, then tries to update the class
attributes by querying pg_attribute using the class specific
connection pool (generating the new connection in the log).

>
> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0regards, tom lane

Thanks for the response and insight!