Received: from makus.postgresql.org (makus.postgresql.org [98.129.198.125]) by mail.postgresql.org (Postfix) with ESMTP id 62ADE9ED581 for ; Wed, 7 Dec 2011 08:14:38 -0400 (AST) Received: from [87.84.168.242] (helo=mail.anatec.com) by makus.postgresql.org with smtp (Exim 4.72) (envelope-from ) id 1RYGOS-00032B-8k for pgsql-novice@postgresql.org; Wed, 07 Dec 2011 12:14:37 +0000 Received: from [192.168.10.57] ([192.168.10.57]) by mail.anatec.com over TLS secured channel with Microsoft SMTPSVC(6.0.3790.4675); Wed, 7 Dec 2011 12:14:21 +0000 Message-ID: <4EDF589D.7060003@anatec.com> Date: Wed, 07 Dec 2011 12:14:21 +0000 From: Ioannis Anagnostopoulos User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:8.0) Gecko/20111105 Thunderbird/8.0 MIME-Version: 1.0 To: Pandu Poluan CC: Tom Lane , ahodgson@simkin.ca, pgsql-novice@postgresql.org, Merlin Moncure Subject: Re: Linux server connection process consumes all memory References: <11644.1322973927@sss.pgh.pa.us><23418.1323016204@sss.pgh.pa.us><4EDC9FE0.8030506@anatec.com><4EDDDCEF.5080903@anatec.com><22700.1323191446@sss.pgh.pa.us><4EDF30D6.20705@anatec.com> In-Reply-To: Content-Type: multipart/alternative; boundary="------------050208040709080905020209" X-OriginalArrivalTime: 07 Dec 2011 12:14:21.0722 (UTC) FILETIME=[C07CF7A0:01CCB4D9] X-Host-Lookup-Failed: Reverse DNS lookup failed for 87.84.168.242 (failed) X-Pg-Spam-Score: -1.1 (-) X-Archive-Number: 201112/38 X-Sequence-Number: 25804 This is a multi-part message in MIME format. --------------050208040709080905020209 Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit On 07/12/2011 11:23, Pandu Poluan wrote: > > > On Dec 7, 2011 4:26 PM, "Ioannis Anagnostopoulos" > wrote: > > > > On 06/12/2011 17:10, Tom Lane wrote: > >> > >> Merlin Moncure> writes: > >>> > >>> *) You may want to consider changing your vm over commit settings > >>> and/or reducing swap in order to get your server to more aggressively > >>> return OOM to postgres memory allocation. The specific error returned > >>> to postgres for an OOM of course would be very helpful. > >> > >> Yeah. I would try starting the postmaster under smaller ulimit > settings > >> so that the kernel gives it ENOMEM before you start getting swapped. > >> When that happens, the backend will dump a memory map into the > >> postmaster log that would be very useful for seeing what is actually > >> happening here. > >> > >> regards, tom lane > >> > > Hello all, > > > > I think I have solved the problem. Many thanks for the support and > the time you spend. The solution/bug/problem is as follows: > > > > 1. There was one connection that as I described was used IN A LOOP > 22million times. This connection was assigned a PID x (on the linux > server) > > 2. Nested within this LOOP there was another connection that had > been forgotten from past code and the linux server was assigning to it > a PID y > > 3. PID y was of course called also 22million times (since it was in > the loop). However it had a nasty bug and it was creating constantly > prepared commands! (opps my mistake). So PID y was creating 22million > prepared commands! > > 4. As I had no clue that that there was at all PID y, monitoring the > TOP on the server I was presented with the misbehaving PID y but I was > of the impression that it was PID x. In fact PID x was below in the > list happy doing its own job. > > > > So the healthy PID X had a top signature as follows (please note the > difference between RES and SHR as well as the magnitude in Mb as > Merlin suggested): > > > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > > 30475 postgres 20 0 2187m 746m 741m S 31 9.5 0:41.48 postgres > > > > While the unhealthy PID Y had a TOP signature (please note that RES > memory is at 12.9g! and SHR 1.4g as well as the magnitude in Gb!): > > > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > > 15965 postgres 20 0 12.9g 6.4g 1.4g S 11 83.4 13:59.15 postgres > > > > As I said I had no clue about the existence of PID Y and since it > was coming top at the TOP list I had wrongfully assumed that it was > the PID X. It gets more complicated by the fact that the test code I > sent you, which should have been working fine as it had no nested > buggy loop, was mainly running from home over the DSL line thus I > never let it conclude its 22million iterations (it would have been > still running!) instead I was monitoring the TOP and since the memory > was going UP I was wrongfully assuming that I had the same issue (if I > had let it run for 2 -3 hours I would have noticed what Merlin > suggested about RES/SHR ratio). So it was a misdiagnosis after all :) > > > > I hope this explains everything. > > Kind Regards and sorry for the misunderstanding. > > All's well that ends well. > > May I ask how you finally found the culprit? Through profiling or code > review? > > That said, I can't help admiring that PostgreSQL still survives 22 > million prepared commands without committing suicide. Yes, it's > severely impacted, but still survives. > > Rgds, > When I compared the "demo program" (the one I though it was not working as I was not letting it run for long enough) and the actual code base I realised that the actual code base was running much slower than the demo even though they were, to my mind doing the same things. It took me then a few "step into" to find somewhere deep the nasty .prepare() which was placed in a function that once was declared static and now it was called for every object created (22million of them). In fact it is a little bit more complicated as I was in the middle of a major re factoring reducing the 22million iteration to 55000 by grouping and creating a few prepared instead of executing 22million times a command. So what I am not sure still is what will happen if I execute 22million times non-prepared statements, will it crash or will it survive since I removed the buggy "prepared" that were nested. Regards --------------050208040709080905020209 Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: 8bit On 07/12/2011 11:23, Pandu Poluan wrote:


On Dec 7, 2011 4:26 PM, "Ioannis Anagnostopoulos" <ioannis@anatec.com> wrote:
>
> On 06/12/2011 17:10, Tom Lane wrote:
>>
>> Merlin Moncure<mmoncure@gmail.com>  writes:
>>>
>>> *) You may want to consider changing your vm over commit settings
>>> and/or reducing swap in order to get your server to more aggressively
>>> return OOM to postgres memory allocation.  The specific error returned
>>> to postgres for an OOM of course would be very helpful.
>>
>> Yeah.  I would try starting the postmaster under smaller ulimit settings
>> so that the kernel gives it ENOMEM before you start getting swapped.
>> When that happens, the backend will dump a memory map into the
>> postmaster log that would be very useful for seeing what is actually
>> happening here.
>>
>>                        regards, tom lane
>>
> Hello all,
>
> I think I have solved the problem. Many thanks for the support and the time you spend. The solution/bug/problem is as follows:
>
> 1. There was one connection that as I described was used IN A LOOP 22million times. This connection was assigned a PID x (on the linux server)
> 2. Nested within this LOOP there was another connection that had been forgotten from past code and the linux server was assigning to it a PID y
> 3. PID y was of course called also 22million times (since it was in the loop). However it had a nasty bug and it was creating constantly prepared commands! (opps my mistake). So PID y was creating 22million prepared commands!
> 4. As I had no clue that that there was at all PID y, monitoring the TOP on the server I was presented with the misbehaving PID y but I was of the impression that it was PID x. In fact PID x was below in the list happy doing its own job.
>
> So the healthy PID X had a top signature as follows (please note the difference between RES and SHR as well as the magnitude in Mb as Merlin suggested):
>
> PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+ COMMAND
> 30475 postgres  20   0 2187m 746m 741m S   31  9.5   0:41.48 postgres
>
> While the unhealthy PID Y had a TOP signature (please note that RES memory is at 12.9g! and SHR 1.4g as well as the magnitude in Gb!):
>
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> 15965 postgres 20 0 12.9g 6.4g 1.4g S 11 83.4 13:59.15 postgres
>
> As I said I had no clue about the existence of PID Y and since it was coming top at the TOP list I had wrongfully assumed that it was the PID X. It gets more complicated by the fact that the test code I sent you, which should have been working fine as it had no nested buggy loop, was mainly running from home over the DSL line thus I never let it conclude its 22million iterations (it would have been still running!) instead I was monitoring the TOP and since the memory was going UP I was wrongfully assuming that I had the same issue (if I had let it run for 2 -3 hours I would have noticed what Merlin suggested about RES/SHR ratio). So it was a misdiagnosis after all :)
>
> I hope this explains everything.
> Kind Regards and sorry for the misunderstanding.

All's well that ends well.

May I ask how you finally found the culprit? Through profiling or code review?

That said, I can't help admiring that PostgreSQL still survives 22 million prepared commands without committing suicide. Yes, it's severely impacted, but still survives.

Rgds,


When I compared the "demo program" (the one I though it was not working as I was not letting it run for long enough) and the actual code base I realised that the actual code base was running much slower than the demo even though they were, to my mind doing the same things. It took me then a few "step into" to find somewhere deep the nasty .prepare() which was placed in a function that once was declared static and now it was called for every object created (22million of them). In fact it is a little bit more complicated as I was in the middle of a major re factoring reducing the 22million iteration to 55000 by grouping and creating a few prepared instead of executing 22million times a command. So what I am not sure still is what will happen if I execute 22million times non-prepared statements, will it crash or will it survive since I removed the buggy "prepared" that were nested.

Regards
--------------050208040709080905020209--