does this look more like a possible bug or more like a possible hardware problem...? (long) - Mailing list pgsql-general

Hi,

I'm using a 9500 line script to create an initial database. After applying a
number of changes, I was repeatedly executing this script while hunting for
typos. The script itself takes care of dropping the various objects and every
now and then (when delta t << autovacuum t) a manual vacuum full was
performed to clean the system tables.

At one point, I arrived at the following situation:

db=# select version();
                                version
------------------------------------------------------------------------
 PostgreSQL 7.4.1 on i586-pc-linux-gnu, compiled by GCC gcc (GCC) 3.2.3


Message in psql terminal:

psql:/home/data/megadump.sql:5169: NOTICE:  CREATE TABLE / PRIMARY KEY will
create implicit index "remainder_type_pkey" for table "remainder_type"
psql:/home/data/megadump.sql:5169: NOTICE:  CREATE TABLE / UNIQUE will create
implicit index "remainder_type_abbreviation_key" for table "remainder_type"
psql:/home/data/megadump.sql:5169: WARNING:  specified item offset is too
large
psql:/home/data/megadump.sql:5169: PANIC:  failed to add item to the page for
"pg_attribute_relid_attnum_index"
server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
psql:/home/data/megadump.sql:5169: connection to server was lost
vugtf@katrien:~>

(so psql did indeed quit)



The specific part in the script contains nothing strange:

CREATE TABLE "remainder_type" (
    "id" integer primary key check ("id" > 0),
    "abbreviation" varchar(20) not null unique,
    "descr" varchar(30) not null
);
GRANT SELECT on remainder_type to PUBLIC;
GRANT ALL on remainder_type to "postgres";



The server logs are mentioning this:

2004-03-09 23:11:34 [6516] LOG:  statement: CREATE TABLE "remainder_type" (
                "id" integer primary key check ("id" > 0),
                "abbreviation" varchar(20) not null unique,
                "descr" varchar(30) not null
        );
2004-03-09 23:11:34 [6516] NOTICE:  CREATE TABLE / PRIMARY KEY will create
implicit index "remainder_type_pkey" for table "remainder_type"
2004-03-09 23:11:34 [6516] NOTICE:  CREATE TABLE / UNIQUE will create implicit
index "remainder_type_abbreviation_key" for table "remainder_type"
2004-03-09 23:11:34 [6516] WARNING:  specified item offset is too large
2004-03-09 23:11:34 [6516] PANIC:  failed to add item to the page for
"pg_attribute_relid_attnum_index"
STATEMENT:  CREATE TABLE "remainder_type" (
                "id" integer primary key check ("id" > 0),
                "abbreviation" varchar(20) not null unique,
                "descr" varchar(30) not null
        );
2004-03-09 23:11:34 [833] LOG:  server process (PID 6516) was terminated by
signal 6
2004-03-09 23:11:34 [833] LOG:  terminating any other active server processes
2004-03-09 23:11:34 [8074] WARNING:  terminating connection because of crash
of another server process
DETAIL:  The postmaster has commanded this server process to roll back the
current transaction and exit, because another server process exited
abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat
your command.
2004-03-09 23:11:34 [833] LOG:  all server processes terminated;
reinitializing
2004-03-09 23:11:34 [8075] LOG:  database system was interrupted at 2004-03-09
23:11:31 CET
2004-03-09 23:11:35 [8075] LOG:  checkpoint record is at 1/9FAAB5C
2004-03-09 23:11:35 [8075] LOG:  redo record is at 1/9E803DC; undo record is
at 0/0; shutdown FALSE
2004-03-09 23:11:35 [8075] LOG:  next transaction ID: 354187; next OID:
8355508
2004-03-09 23:11:35 [8075] LOG:  database system was not properly shut down;
automatic recovery in progress
2004-03-09 23:11:35 [8075] LOG:  redo starts at 1/9E803DC
2004-03-09 23:11:46 [8075] LOG:  record with zero length at 1/B27335C
2004-03-09 23:11:46 [8075] LOG:  redo done at 1/B273338
2004-03-09 23:11:55 [8075] LOG:  database system is ready


After this, a vacuum full verbose analyse seems to end prematurely with:

INFO:  vacuuming "public.stock_delivery"
INFO:  "stock_delivery": found 0 removable, 0 nonremovable row versions in 0
pages
DETAIL:  0 dead row versions cannot be removed yet.
Nonremovable row versions range from 0 to 0 bytes long.
There were 0 unused item pointers.
Total free space (including removable row versions) is 0 bytes.
0 pages are or will become empty, including 0 at the end of the table.
0 pages containing 0 free bytes are potential move destinations.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  index "stock_delivery_pkey" now contains 0 row versions in 1 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.02 sec.
INFO:  index "stock_delivery_delivery_id_key" now contains 0 row versions in 1
pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  index "stock_delivery_idx1" now contains 0 row versions in 1 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  analyzing "public.stock_delivery"
INFO:  "stock_delivery": 0 pages, 0 rows sampled, 0 estimated total rows
ERROR:  catalog is missing 6 attribute(s) for relid 8349771




Looking at the pg_autovacuum log (see timestamps) it seems this could have
clashed with the script :

[2004-03-09 11:11:08 PM] Performing: VACUUM ANALYZE "pg_catalog"."pg_depend"
[2004-03-09 11:11:29 PM]   table name:
megafox_trial."pg_catalog"."pg_depend"
[2004-03-09 11:11:29 PM]      relid: 16599;   relisshared: 0
[2004-03-09 11:11:29 PM]      reltuples: 6124;  relpages: 153
[2004-03-09 11:11:29 PM]      curr_analyze_count:  668446; cur_delete_count:
332899
[2004-03-09 11:11:29 PM]      ins_at_last_analyze: 668446; del_at_last_vacuum:
332899
[2004-03-09 11:11:29 PM]      insert_threshold:    6624; delete_threshold
13248
[2004-03-09 11:11:29 PM] Performing: VACUUM ANALYZE
"pg_catalog"."pg_attribute"
[2004-03-09 11:11:35 PM] Can not refresh statistics information from the
database megafox_trial.
[2004-03-09 11:11:35 PM] The error is [server closed the connection
unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
]
[2004-03-09 11:11:35 PM] Fatal error occured while sending query (select
oid,reltuples,relpages from pg_class where oid=1249) to database
megafox_trial
[2004-03-09 11:11:35 PM] The error is []
[2004-03-09 11:11:35 PM]   table name:
megafox_trial."pg_catalog"."pg_attribute"
[2004-03-09 11:11:35 PM]      relid: 1249;   relisshared: 0
[2004-03-09 11:11:35 PM]      reltuples: 3595;  relpages: 214
[2004-03-09 11:11:35 PM]      curr_analyze_count:  721978; cur_delete_count:
361920
[2004-03-09 11:11:35 PM]      ins_at_last_analyze: 707819; del_at_last_vacuum:
346312
[2004-03-09 11:11:35 PM]      insert_threshold:    4095; delete_threshold
11400
[2004-03-09 11:11:35 PM] Performing: VACUUM ANALYZE "pg_catalog"."pg_class"
[2004-03-09 11:11:35 PM] Fatal error occured while sending query (VACUUM
ANALYZE "pg_catalog"."pg_class") to database megafox_trial
[2004-03-09 11:11:35 PM] The error is []
[2004-03-09 11:11:35 PM] Fatal error occured while sending query (select
oid,reltuples,relpages from pg_class where oid=1259) to database
megafox_trial
[2004-03-09 11:11:35 PM] The error is []
[2004-03-09 11:11:35 PM]   table name:
megafox_trial."pg_catalog"."pg_class"
[2004-03-09 11:11:35 PM]      relid: 1259;   relisshared: 0
[2004-03-09 11:11:35 PM]      reltuples: 885;  relpages: 117
[2004-03-09 11:11:35 PM]      curr_analyze_count:  439206; cur_delete_count:
373969
[2004-03-09 11:11:35 PM]      ins_at_last_analyze: 430423; del_at_last_vacuum:
366316
[2004-03-09 11:11:35 PM]      insert_threshold:    1385; delete_threshold
2770
[2004-03-09 11:11:35 PM] Performing: VACUUM ANALYZE "pg_catalog"."pg_attrdef"
[2004-03-09 11:11:35 PM] Fatal error occured while sending query (VACUUM
ANALYZE "pg_catalog"."pg_attrdef") to database megafox_trial
[2004-03-09 11:11:35 PM] The error is []
[2004-03-09 11:11:35 PM] Fatal error occured while sending query (select
oid,reltuples,relpages from pg_class where oid=16384) to database
megafox_trial
[2004-03-09 11:11:35 PM] The error is []





There's nothing critical here and I expect a drop/create database to solve it,
but I'll wait for a reply just in case.



--
Best,




Frank.