I changed the number of shared buffers to 3000 and my database locks
on a simple query.  I must kill the database with pg_ctl stop -m i. 
Neither "smart" nor "fast" stops appear to succeed.  One CPU gets
pinned.

When I set the number of shared buffers to 64 everything is fine.  No
data appears to have been corrupted, but I haven't been able to do a
thorough check.  I really didn't have a chance to do much of a
postmortem.  I only have what I can get from my logs:
 - schema
 - query
 - query plan
 - vacuum results
 - postgres log

If anybody wants more data I can reproduce the problem.  It is very
repeatable.  Also, I prefer to discover what went wrong rather than
simply upgrade to 7.1.3 and hope for the best.  None of the
fixes/enhancements listed in 7.1.3 seem relevant to this problem.

I am running postgres 7.1.2 on Solaris 5.7 E450, 4 processors, 2 gig
ram.

I added the following lines to /etc/system:
  set shmsys:shminfo_shmmax=0x10000000
  set shmsys:shminfo_shmmin=1
  set shmsys:shminfo_shmmni=256
  set shmsys:shminfo_shmseg=256
  set semsys:seminfo_semmap=256
  set semsys:seminfo_semmni=512
  set semsys:seminfo_semmsl=32
  set semsys:seminfo_semmns=512
  set rlim_fd_max=65535
  set rlim_fd_cur=65535

Here is the query that locks the DB:
  select i8, i5, count(*), sum( float8mi(d2,d1) ), sum(i9)::int4 as
doll from
  calls_1001548800 group by i5, i8;
i8 has about 5 unique values.
i5 has two unique values (boolean) plus NULL.

The query was entered into psql by hand.


Here is the table def:
  CREATE TABLE calls_1001548800 (
  pk	int4 primary key,
  t1	text NOT NULL,
  t2	text NOT NULL,
  i1	int4 NOT NULL,
  i2	int4 NOT NULL,
  d1	double precision NOT NULL,
  d2	double precision NOT NULL,
  d3	double precision NOT NULL,
  d4	double precision NOT NULL,
  i3	int4 NOT NULL,
  d5	real NOT NULL,
  i4	int4 NOT NULL,
  t3	text,
  i5	boolean,
  i6	int4 NOT NULL,
  i7	int4 NOT NULL,
  i8	int2 NOT NULL,
  i9	int4,
  t4	text
  );
  CREATE INDEX calls_1001548800_d21 on calls_1001548800 (
float8mi(d2,d1) );
  CREATE INDEX calls_1001548800_i3 on calls_1001548800 ( i3 );
  CREATE INDEX calls_1001548800_i9 on calls_1001548800 ( i9 );


Vacuum of the table (before the query):

5681:DEBUG:  --Relation calls_1001548800--
5682:DEBUG:  Pages 915: Changed 54, reaped 559, Empty 0, New 0; Tup
33842: Vac 1077, Keep/VTL 0/0, Crash 0, UnUsed 0, MinLen 1
42, MaxLen 648; Re-using: Free/Avail. Space 279912/279912;
EndEmpty/Avail. Pages 0/559. CPU 0.00s/0.11u sec.
5683:DEBUG:  Index calls_1001548800_pkey: Pages 179; Tuples 33842:
Deleted 1077. CPU 0.00s/0.66u sec.
5684:DEBUG:  Index calls_1001548800_d21: Pages 95; Tuples 33842:
Deleted 1077. CPU 0.00s/0.70u sec.
5685:DEBUG:  XLogWrite: new log file created - consider increasing
WAL_FILES
5686:DEBUG:  Index calls_1001548800_i3: Pages 98; Tuples 33842:
Deleted 1077. CPU 0.39s/0.78u sec.
5687:DEBUG:  Index calls_1001548800_i9: Pages 100; Tuples 33842:
Deleted 1077. CPU 0.03s/0.66u sec.
5688:DEBUG:  Rel calls_1001548800: Pages: 915 --> 886; Tuple(s) moved:
1122. CPU 0.00s/1.16u sec.
5689:DEBUG:  Index calls_1001548800_pkey: Pages 179; Tuples 33842:
Deleted 1122. CPU 0.00s/0.38u sec.
5690:DEBUG:  Index calls_1001548800_d21: Pages 95; Tuples 33842:
Deleted 1122. CPU 0.00s/0.40u sec.
5691:DEBUG:  Index calls_1001548800_i3: Pages 102; Tuples 33842:
Deleted 1122. CPU 0.01s/0.39u sec.
5692:DEBUG:  Index calls_1001548800_i9: Pages 104; Tuples 33842:
Deleted 1122. CPU 0.00s/0.40u sec.


Here is a snippet of the log file showing the query plan and the
events after the query.

7553:NOTICE:  QUERY PLAN:
7554:
7555:Aggregate  (cost=3770.44..4108.86 rows=3384 width=19)
7556:  ->  Group  (cost=3770.44..3939.65 rows=33842 width=19)
7557:        ->  Sort  (cost=3770.44..3770.44 rows=33842 width=19)
7558:              ->  Seq Scan on calls_1001548800 
(cost=0.00..1224.42 rows=33
842 width=19)
7559:
7560:Smart Shutdown request at Tue Oct  2 18:34:08 2001
7561:Fast Shutdown request at Tue Oct  2 18:35:03 2001
7562:Aborting any active transaction...
7563:FATAL 1:  This connection has been terminated by the
administrator.
7564:Immediate Shutdown request at Tue Oct  2 18:39:47 2001
7565:NOTICE:  Message from PostgreSQL backend:
7566:   The Postmaster has informed me that some other backend  died
abnormally
and possibly corrupted shared memory.
7567:   I have rolled back the current transaction and am       going
to termina
te your database system connection and exit.
7568:   Please reconnect to the database system and repeat your query.
7569:DEBUG:  database system was interrupted at 2001-10-02 18:11:06
PDT
7570:DEBUG:  CheckPoint record at (39, 1811142680)
7571:DEBUG:  Redo record at (39, 1811142680); Undo record at (0, 0);
Shutdown FA
LSE
7572:DEBUG:  NextTransactionId: 2086582; NextOid: 134710037
7573:DEBUG:  database system was not properly shut down; automatic
recovery in p
rogress...
7574:DEBUG:  ReadRecord: record with zero len at (39, 1811142744)
7575:DEBUG:  redo is not required
7576:DEBUG:  database system is in production state


Ryan

8 Oct 2001 12:28:20 -0700
ryan_rs@c4.com (Ryan)
Postgres server locks up
Tom, Bruce, any suggestions?

ryan_rs@c4.com (Ryan) wrote in message news:<7299ab58.0110081128.50cf8fba@posting.google.com>...
> I changed the number of shared buffers to 3000 and my database locks
> on a simple query.  I must kill the database with pg_ctl stop -m i. 
> Neither "smart" nor "fast" stops appear to succeed.  One CPU gets
> pinned.
> 
> When I set the number of shared buffers to 64 everything is fine.  No
> data appears to have been corrupted, but I haven't been able to do a
> thorough check.  I really didn't have a chance to do much of a
> postmortem.  I only have what I can get from my logs:
>  - schema
>  - query
>  - query plan
>  - vacuum results
>  - postgres log
> 
> If anybody wants more data I can reproduce the problem.  It is very
> repeatable.  Also, I prefer to discover what went wrong rather than
> simply upgrade to 7.1.3 and hope for the best.  None of the
> fixes/enhancements listed in 7.1.3 seem relevant to this problem.
> 
> I am running postgres 7.1.2 on Solaris 5.7 E450, 4 processors, 2 gig
> ram.
> 
> I added the following lines to /etc/system:
>   set shmsys:shminfo_shmmax=0x10000000
>   set shmsys:shminfo_shmmin=1
>   set shmsys:shminfo_shmmni=256
>   set shmsys:shminfo_shmseg=256
>   set semsys:seminfo_semmap=256
>   set semsys:seminfo_semmni=512
>   set semsys:seminfo_semmsl=32
>   set semsys:seminfo_semmns=512
>   set rlim_fd_max=65535
>   set rlim_fd_cur=65535
> 
> Here is the query that locks the DB:
>   select i8, i5, count(*), sum( float8mi(d2,d1) ), sum(i9)::int4 as
> doll from
>   calls_1001548800 group by i5, i8;
> i8 has about 5 unique values.
> i5 has two unique values (boolean) plus NULL.
> 
> The query was entered into psql by hand.
> 
> 
> Here is the table def:
>   CREATE TABLE calls_1001548800 (
>   pk	int4 primary key,
>   t1	text NOT NULL,
>   t2	text NOT NULL,
>   i1	int4 NOT NULL,
>   i2	int4 NOT NULL,
>   d1	double precision NOT NULL,
>   d2	double precision NOT NULL,
>   d3	double precision NOT NULL,
>   d4	double precision NOT NULL,
>   i3	int4 NOT NULL,
>   d5	real NOT NULL,
>   i4	int4 NOT NULL,
>   t3	text,
>   i5	boolean,
>   i6	int4 NOT NULL,
>   i7	int4 NOT NULL,
>   i8	int2 NOT NULL,
>   i9	int4,
>   t4	text
>   );
>   CREATE INDEX calls_1001548800_d21 on calls_1001548800 (
> float8mi(d2,d1) );
>   CREATE INDEX calls_1001548800_i3 on calls_1001548800 ( i3 );
>   CREATE INDEX calls_1001548800_i9 on calls_1001548800 ( i9 );
> 
> 
> Vacuum of the table (before the query):
> 
> 5681:DEBUG:  --Relation calls_1001548800--
> 5682:DEBUG:  Pages 915: Changed 54, reaped 559, Empty 0, New 0; Tup
> 33842: Vac 1077, Keep/VTL 0/0, Crash 0, UnUsed 0, MinLen 1
> 42, MaxLen 648; Re-using: Free/Avail. Space 279912/279912;
> EndEmpty/Avail. Pages 0/559. CPU 0.00s/0.11u sec.
> 5683:DEBUG:  Index calls_1001548800_pkey: Pages 179; Tuples 33842:
> Deleted 1077. CPU 0.00s/0.66u sec.
> 5684:DEBUG:  Index calls_1001548800_d21: Pages 95; Tuples 33842:
> Deleted 1077. CPU 0.00s/0.70u sec.
> 5685:DEBUG:  XLogWrite: new log file created - consider increasing
> WAL_FILES
> 5686:DEBUG:  Index calls_1001548800_i3: Pages 98; Tuples 33842:
> Deleted 1077. CPU 0.39s/0.78u sec.
> 5687:DEBUG:  Index calls_1001548800_i9: Pages 100; Tuples 33842:
> Deleted 1077. CPU 0.03s/0.66u sec.
> 5688:DEBUG:  Rel calls_1001548800: Pages: 915 --> 886; Tuple(s) moved:
> 1122. CPU 0.00s/1.16u sec.
> 5689:DEBUG:  Index calls_1001548800_pkey: Pages 179; Tuples 33842:
> Deleted 1122. CPU 0.00s/0.38u sec.
> 5690:DEBUG:  Index calls_1001548800_d21: Pages 95; Tuples 33842:
> Deleted 1122. CPU 0.00s/0.40u sec.
> 5691:DEBUG:  Index calls_1001548800_i3: Pages 102; Tuples 33842:
> Deleted 1122. CPU 0.01s/0.39u sec.
> 5692:DEBUG:  Index calls_1001548800_i9: Pages 104; Tuples 33842:
> Deleted 1122. CPU 0.00s/0.40u sec.
> 
> 
> Here is a snippet of the log file showing the query plan and the
> events after the query.
> 
> 7553:NOTICE:  QUERY PLAN:
> 7554:
> 7555:Aggregate  (cost=3770.44..4108.86 rows=3384 width=19)
> 7556:  ->  Group  (cost=3770.44..3939.65 rows=33842 width=19)
> 7557:        ->  Sort  (cost=3770.44..3770.44 rows=33842 width=19)
> 7558:              ->  Seq Scan on calls_1001548800 
> (cost=0.00..1224.42 rows=33
> 842 width=19)
> 7559:
> 7560:Smart Shutdown request at Tue Oct  2 18:34:08 2001
> 7561:Fast Shutdown request at Tue Oct  2 18:35:03 2001
> 7562:Aborting any active transaction...
> 7563:FATAL 1:  This connection has been terminated by the
> administrator.
> 7564:Immediate Shutdown request at Tue Oct  2 18:39:47 2001
> 7565:NOTICE:  Message from PostgreSQL backend:
> 7566:   The Postmaster has informed me that some other backend  died
> abnormally
> and possibly corrupted shared memory.
> 7567:   I have rolled back the current transaction and am       going
> to termina
> te your database system connection and exit.
> 7568:   Please reconnect to the database system and repeat your query.
> 7569:DEBUG:  database system was interrupted at 2001-10-02 18:11:06
> PDT
> 7570:DEBUG:  CheckPoint record at (39, 1811142680)
> 7571:DEBUG:  Redo record at (39, 1811142680); Undo record at (0, 0);
> Shutdown FA
> LSE
> 7572:DEBUG:  NextTransactionId: 2086582; NextOid: 134710037
> 7573:DEBUG:  database system was not properly shut down; automatic
> recovery in p
> rogress...
> 7574:DEBUG:  ReadRecord: record with zero len at (39, 1811142744)
> 7575:DEBUG:  redo is not required
> 7576:DEBUG:  database system is in production state
> 
> 
> Ryan

10 Oct 2001 11:07:35 -0700
ryan_rs@c4.com (Ryan)
Re: Postgres server locks up, HELP!
ryan_rs@c4.com (Ryan) writes:
> I changed the number of shared buffers to 3000 and my database locks
> on a simple query.  I must kill the database with pg_ctl stop -m i. 
> If anybody wants more data I can reproduce the problem.  It is very
> repeatable.

Please attach to the stuck process with a debugger and see where
it's stuck.   Or, if you're not handy with gdb or local equivalent,
maybe you could give access to your system to someone who is.

> Also, I prefer to discover what went wrong rather than
> simply upgrade to 7.1.3 and hope for the best. 

I agree; this does not strike me as a symptom of any known problem.

			regards, tom lane

Thu, 11 Oct 2001 01:21:25 -0400
Tom Lane <tgl@sss.pgh.pa.us>
Re: Postgres server locks up 