Received: from magus.postgresql.org (magus.postgresql.org [87.238.57.229]) by mail.postgresql.org (Postfix) with ESMTP id 657782F33B3 for ; Thu, 9 Aug 2012 22:31:18 -0300 (ADT) Received: from nm11-vm2.bullet.mail.ne1.yahoo.com ([98.138.90.159]) by magus.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1Sze4J-0007Ne-LK for pgsql-admin@postgresql.org; Fri, 10 Aug 2012 01:31:17 +0000 Received: from [98.138.90.57] by nm11.bullet.mail.ne1.yahoo.com with NNFMP; 10 Aug 2012 01:31:01 -0000 Received: from [98.138.226.160] by tm10.bullet.mail.ne1.yahoo.com with NNFMP; 10 Aug 2012 01:31:01 -0000 Received: from [127.0.0.1] by omp1061.mail.ne1.yahoo.com with NNFMP; 10 Aug 2012 01:31:01 -0000 X-Yahoo-Newman-Property: ymail-3 X-Yahoo-Newman-Id: 14276.7916.bm@omp1061.mail.ne1.yahoo.com Received: (qmail 1555 invoked by uid 60001); 10 Aug 2012 01:31:00 -0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s1024; t=1344562260; bh=tqSCiXtzlTBw+fz9ub4NRkxGPfSCjCYKPJuN2rQQvxk=; h=X-YMail-OSG:Received:X-Mailer:References:Message-ID:Date:From:Reply-To:Subject:To:In-Reply-To:MIME-Version:Content-Type; b=yLFN2947j7FYNC7Dv2BM4SdeKcx7Dy0ggipA+wZ45oNkDhYtBqyzSjd4ZK9MEElLz9vlYywVLeJosx9AMceZFbaXv8fUTWnAo+r5ioIEgHLu98DxZO2A6HjTGwm69Znu8UO4l/GAbVBH10HBR4B2ERpoWrS38iflHeX39yMd2vc= DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=s1024; d=yahoo.com; h=X-YMail-OSG:Received:X-Mailer:References:Message-ID:Date:From:Reply-To:Subject:To:In-Reply-To:MIME-Version:Content-Type; b=UfDj3cVh40eub6hcVquTmTwHPAr1CZ6FYbmTfhHWSVfaDSnD7xYPTOm6P7pGbais2aVFL8/JmUNEdCBDfKl8B6Fxj5kznjVCWWrHRU3n5feIsWRbH+GlFK5wH3wJGgS5+JZ1Y3FPyueZL/mIkTAxyBi/GoV1TUMnhDS5l2mK8pU=; X-YMail-OSG: nu5ob44VM1lTTACfl.wOWI1uCJuNrIxLQfeTKwXphSt0E0L UutRi_AI9YypFN2ZLRw8B2sqnnZ6ZV85MEqlmrdz103N6tY53cRmNdLXmPbf DbXV7_ydmo4SzlowehItI4n6Bea0vVPWVmpc4tlwkl5G8ZnpewI5oWGjg5Kf f5UEONT7BwJbVy5ilSHKVpVuzal6cVJ4H2AAB6gVyvDeN2zjh3hYb2tOWipQ zKHyiSt0iqIhX_wjASh82rX3BtHOtyMMUo3xAZHFZKdhG1iwfgZbB8Boj15u 3Uo_IchDY_Ijo5gQ3eBv5eoxG90IkxRag86PKUuvKyGEHzSHsSEw8HxMe9dT xZ_zObzkV4_UN1nYLVIKL4aJi8RVWlgyEUxI.sXqgPWwtGtLqgRx5Puwp4Oo VdaBSDpg.PhjeRjAeze3qvolcYus.Hb.6ELDFPFCe5CQWTeegTdojRC0sUQD jjB.a3XJ.pBlxfImTMA-- Received: from [199.9.251.45] by web125901.mail.ne1.yahoo.com via HTTP; Thu, 09 Aug 2012 18:31:00 PDT X-Mailer: YahooMailWebService/0.8.120.356233 References: <1344557082.43876.YahooMailNeo@web125906.mail.ne1.yahoo.com> <8579.1344557984@sss.pgh.pa.us> <1344558910.70207.YahooMailNeo@web125906.mail.ne1.yahoo.com> Message-ID: <1344562260.90632.YahooMailNeo@web125901.mail.ne1.yahoo.com> Date: Thu, 9 Aug 2012 18:31:00 -0700 (PDT) From: Greg Williamson Reply-To: Greg Williamson Subject: Re: Question about ALTER TABLE DROP CONSTRAINT on 9.1 -- psql crashes To: "pgsql-admin@postgresql.org" In-Reply-To: <1344558910.70207.YahooMailNeo@web125906.mail.ne1.yahoo.com> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="1155904834-115190056-1344562260=:90632" X-Pg-Spam-Score: -1.5 (-) X-Archive-Number: 201208/70 X-Sequence-Number: 39891 --1155904834-115190056-1344562260=:90632 Content-Type: text/plain; charset=iso-8859-1 Content-Transfer-Encoding: quoted-printable Tom, et. al., >________________________________ > From: Greg Williamson >To: Tom Lane =20 >Cc: "pgsql-admin@postgresql.org" =20 >Sent: Thursday, August 9, 2012 5:35 PM >Subject: Re: [ADMIN] Question about ALTER TABLE DROP CONSTRAINT on 9.1 -- = psql crashes >=20 > >Tom -- > > > >>________________________________ >>><...>>>=A0 >>>> WTF?=A0 That should certainly not happen.=A0 Have you perhaps got a sc= ript >>>> that runs around sending SIGTERM to backends that it thinks are blocki= ng >>>> something?=A0 Does anything show up in the postmaster log when this >>>> happens? >>> >>> No, we have processes that kill IDLE IN TRANSACTIONs ruthlessly, but no= thing that kills any other processes. There is an outside chance that this = ran at just the >>> same time that a cronjob ran the REINDEX command for the table (unlikel= y but I am going to shut off the cronjob and try this again). >>>=A0 >>> It does not log an ERROR to the log file; I can wade intio the log and = see what else it says but it will take a little while (about 800 megs per h= our) to answer that. >>>=A0 >>> Thanks, and I'll report back soon. >> >> >> >> >>This was as all run as user postgres, unlike everything else so here is e= veryhting in the logsw: >>2012-08-09 16:50:25.398 PDT,"postgres","gusher",13873,"[local]",50244cc1.= 3631,2,"authentication",2012-08-09 16:50:25 PDT,19/61906190,0,LOG,00000,"co= nnection authorized: user=3Dpostgres database=3Dgusher",,,,,,,,,"" >>2012-08-09 16:50:41.206 PDT,"postgres","gusher",13873,"[local]",50244cc1.= 3631,3,"SELECT",2012-08-09 16:50:25 PDT,19/0,0,LOG,00000,"duration: 3.437 m= s =A0statement: SELECT c.oid, >>2012-08-09 16:50:41.212 PDT,"postgres","gusher",13873,"[local]",50244cc1.= 3631,4,"SELECT",2012-08-09 16:50:25 PDT,19/0,0,LOG,00000,"duration: 4.461 m= s =A0statement: SELECT a.attname, >>2012-08-09 16:50:59.238 PDT,"postgres","gusher",13873,"[local]",50244cc1.= 3631,5,"ALTER TABLE",2012-08-09 16:50:25 PDT,19/61906197,1518480799,LOG,000= 00,"duration: 4.612 ms =A0statement: ALTER TABLE ourcodes ADD CONSTRAINT ou= rcodes_pkey PRIMARY KEY (id);",,,,,,,,,"psql" >>2012-08-09 16:51:01.808 PDT,"postgres","gusher",13873,"[local]",50244cc1.= 3631,6,"idle in transaction",2012-08-09 16:50:25 PDT,19/61906197,1518480799= ,FATAL,57P01,"terminating connection due to administrator command",,,,,,,,,= "psql" >>2012-08-09 16:51:01.859 PDT,"postgres","gusher",13873,"[local]",50244cc1.= 3631,7,"idle in transaction",2012-08-09 16:50:25 PDT,,0,LOG,00000,"disconne= ction: session time: 0:00:36.458 user=3Dpostgres database=3Dgusher host=3D[= local]",,,,,,,,,"psql" >>2012-08-09 16:51:02.309 PDT,"postgres","gusher",14000,"[local]",50244ce6.= 36b0,2,"authentication",2012-08-09 16:51:02 PDT,19/61906206,0,LOG,00000,"co= nnection authorized: user=3Dpostgres database=3Dgusher",,,,,,,,,"" >>2012-08-09 16:51:18.551 PDT,"postgres","gusher",14000,"[local]",50244ce6.= 36b0,3,"SELECT",2012-08-09 16:51:02 PDT,19/0,0,LOG,00000,"duration: 3.979 m= s =A0statement: SELECT a.attname, >>2012-08-09 16:51:18.556 PDT,"postgres","gusher",14000,"[local]",50244ce6.= 36b0,4,"SELECT",2012-08-09 16:51:02 PDT,19/0,0,LOG,00000,"duration: 5.255 m= s =A0statement: SELECT c2.relname, i.indisprimary, i.indisunique, i.indiscl= ustered, i.indisvalid, pg_catalog.pg_get_indexdef(i.indexrelid, 0, true), >>2012-08-09 16:59:34.443 PDT,"postgres","gusher",14000,"[local]",50244ce6.= 36b0,5,"idle",2012-08-09 16:51:02 PDT,,0,LOG,00000,"disconnection: session = time: 0:08:32.135 user=3Dpostgres database=3Dgusher host=3D[local]",,,,,,,,= ,"psql" >> >> >>Every minute on the minute there is a cronjob that kills IDLE IN CONNECTI= ON procs older than 3 seconds ... possibly that process killed the process = I was running, but to me the user it seemed as if the COMMIT came before th= e disconnect. >> >> >>We have had some issues on this box so I probably won't test this much mo= re today; I'll post more if I can get a reproducible case. >> >> >>Thanks, >> >> >>Greg= --1155904834-115190056-1344562260=:90632 Content-Type: text/html; charset=iso-8859-1 Content-Transfer-Encoding: quoted-printable
Tom, et. al.,

= From: Greg Williamson <= ;gwilliamson39@yahoo.com>
To:<= /span> Tom Lane <tgl@sss.pgh.pa.us>
Cc: "pgsql-admin@postgresql.org" <pgsql-admin@po= stgresql.org>
Sent: Thursday, Augu= st 9, 2012 5:35 PM
Subject: Re: [ADMIN] Question about ALTER TABLE DROP CONSTRAINT on 9.1 -- psql= crashes

= Tom --

><...>
>> = ;
>> WTF?  That should certainly not happen.  Have you p= erhaps got a script
>> that runs around sending SIGTERM to backend= s that it thinks are blocking
>> something?  Does anything sh= ow up in the postmaster log when this
>> happens?
>
> = No, we have processes that kill IDLE IN TRANSACTIONs ruthlessly, but nothing that kill= s any other processes. There is an outside chance that this ran at just the
> same time that = a cronjob ran the REINDEX command for the table (unlikely but I am going to= shut off the cronjob and try this again).
> 
> It does not log an ERROR to the log file; I can wade in= tio the log and see what else it says but it will take a little while (abou= t 800 megs per hour) to answer that.
> 
> Thanks, and I'll= report back soon.

=
This was as all run as = user postgres, unlike everything else so here is everyhting in the logsw:
2012-08-09 16:50:25.398 PDT,"postgres","gusher",13873,"[local= ]",50244cc1.3631,2,"authentication",2012-08-09 16:50:25 PDT,19/61906190,0,L= OG,00000,"connection authorized: user=3Dpostgres database=3Dgusher",,,,,,,,= ,""
2012-08-09 16:50:41.206 PDT,"postgres","gusher",13873,"[local]",50244cc1.3631,3,"SELECT",2012-08-0= 9 16:50:25 PDT,19/0,0,LOG,00000,"duration: 3.437 ms  statement: SELECT= c.oid,
2012-08-09 16:50:41.212 PDT,"postgres","gusher",1387= 3,"[local]",50244cc1.3631,4,"SELECT",2012-08-09 16:50:25 PDT,19/0,0,LOG,000= 00,"duration: 4.461 ms  statement: SELECT a.attname,
= 2012-08-09 16:50:59.238 PDT,"postgres","gusher",13873,"[local]",50244cc1.36= 31,5,"ALTER TABLE",2012-08-09 16:50:25 PDT,19/61906197,1518480799,LOG,00000= ,"duration: 4.612 ms  statement: ALTER TABLE ourcodes ADD CONSTRAINT o= urcodes_pkey PRIMARY KEY (id);",,,,,,,,,"psql"
2012-08-09 16= :51:01.808 PDT,"postgres","gusher",13873,"[local]",50244cc1.3631,6,"idle in transaction",2012-08-09 16:50:25 PDT,19/61906197,1518480799,FATAL,57P01,"t= erminating connection due to administrator command",,,,,,,,,"psql"
2012-08-09 16:51:01.859 PDT,"postgres","gusher",13873,"[local]",5024= 4cc1.3631,7,"idle in transaction",2012-08-09 16:50:25 PDT,,0,LOG,00000,"dis= connection: session time: 0:00:36.458 user=3Dpostgres database=3Dgusher hos= t=3D[local]",,,,,,,,,"psql"
2012-08-09 16:51:02.309 PDT,"pos= tgres","gusher",14000,"[local]",50244ce6.36b0,2,"authentication",2012-08-09= 16:51:02 PDT,19/61906206,0,LOG,00000,"connection authorized: user=3Dpostgr= es database=3Dgusher",,,,,,,,,""
2012-08-09 16:51:18.551 PDT= ,"postgres","gusher",14000,"[local]",50244ce6.36b0,3,"SELECT",2012-08-09 16= :51:02 PDT,19/0,0,LOG,00000,"duration: 3.979 ms  statement: SELECT a.attname= ,
2012-08-09 16:51:18.556 PDT,"postgres","gusher",14000,"[lo= cal]",50244ce6.36b0,4,"SELECT",2012-08-09 16:51:02 PDT,19/0,0,LOG,00000,"du= ration: 5.255 ms  statement: SELECT c2.relname, i.indisprimary, i.indi= sunique, i.indisclustered, i.indisvalid, pg_catalog.pg_get_indexdef(i.index= relid, 0, true),
2012-08-09 16:59:34.443 PDT,"postgres","gus= her",14000,"[local]",50244ce6.36b0,5,"idle",2012-08-09 16:51:02 PDT,,0,LOG,= 00000,"disconnection: session time: 0:08:32.135 user=3Dpostgres database=3D= gusher host=3D[local]",,,,,,,,,"psql"

<= /font>
Every minute on the minute = there is a cronjob that kills IDLE IN CONNECTION procs older than 3 seconds= ... possibly that process killed the process I was running, but to me the = user it seemed as if the COMMIT came before the disconnect.

We have= had some issues on this box so I probably won't test this much more today;= I'll post more if I can get a reproducible case.

Thanks,

= Greg
= --1155904834-115190056-1344562260=:90632--