Memory use in 8.3 plpgsql with heavy use of xpath()

"Matt Magoffin" <postgresql.org@msqr.us> writes:

Later, I added a large set of plpgsql trigger functions that operate on
that new xml column data, using the xpath() function to extract bits of
XML and populate them into normal tables. The server has been running in
this fashion for many months now, and there is a noticeable difference in
how Postgres is using memory now, in that over time it's non-shared memory
use is climbing higher and higher. Right now I'm tracking this from data
captured by Munin on the system. The memory creep is very slight, but over
many months is easy to discern.

Ugh. Sounds like "small memory leak inside libxml2" --- probably not
going to be easy to find. Can you put together a self-contained test
case?

regards, tom lane

Ugh. Sounds like "small memory leak inside libxml2" --- probably not
going to be easy to find. Can you put together a self-contained test
case?

OK, I'll try to come up with something. Do you have a recommended way of
capturing the amount memory being used by Postgres related to this? I was
thinking I would have a plpgsql function that loops a large number of
times, calling a few xpath() calls, and could take a memory snapshot
before/after the function completes. Is there a call within Postgres I can
make, or should I just rely on OS-level tools for this?

-- m@

"Matt Magoffin" <postgresql.org@msqr.us> writes:

Ugh. Sounds like "small memory leak inside libxml2" --- probably not
going to be easy to find. Can you put together a self-contained test
case?

OK, I'll try to come up with something. Do you have a recommended way of
capturing the amount memory being used by Postgres related to this? I was
thinking I would have a plpgsql function that loops a large number of
times, calling a few xpath() calls,

Yeah, that's what I'd try first.

regards, tom lane

OK, I'll try to come up with something. Do you have a recommended way of
capturing the amount memory being used by Postgres related to this? I
was
thinking I would have a plpgsql function that loops a large number of
times, calling a few xpath() calls,

Yeah, that's what I'd try first.

regards, tom lane

Below is a test case that simulates the use of xpath() within a plpgsql
function in my application. I'm not sure of a good way to measure the
retained memory before/after the script runs, however. I ran this several
times and the postgres process that ran it does have more memory allocated
afterwards than before, but I don't know what is expected and what isn't.

You can adjust the number of loops that run at

num_loops int8 := 1000000;

-- m@

-----
DROP TABLE IF EXISTS tmp_xml_test CASCADE;
DROP TABLE IF EXISTS tmp_xml_addr CASCADE;
CREATE TEMPORARY TABLE tmp_xml_test(
id int4, x xml, primary key (id));
CREATE TEMPORARY TABLE tmp_xml_addr(
id int4, xmlpos int4, street text, city text, state text, zip text,
primary key (id, xmlpos));

CREATE OR REPLACE FUNCTION tmp_extract_address(data_row tmp_xml_test)
RETURNS void AS
$BODY$
DECLARE
addr_row tmp_xml_addr%ROWTYPE;
tmp_txt text;
tmp_array xml[];
BEGIN
addr_row.id := data_row.id;
DELETE FROM tmp_xml_addr WHERE id = data_row.id;
tmp_array := xpath(
'/po:purchaseOrder/*[name(.) = "shipTo" or name(.) = "billTo"]',
data_row.x, ARRAY[ARRAY['po', 'http://www.example.com/PO1&#39;]]);
IF array_upper(tmp_array, 1) > 0 THEN
FOR idx IN 1..array_upper(tmp_array, 1) LOOP
addr_row.xmlpos := idx;
addr_row.street := upper(XMLSERIALIZE(CONTENT(xpath(
'/po:purchaseOrder/*[name(.) = "shipTo" or name(.) = "billTo"]['
||idx|| ']/po:street[1]/text()',
data_row.x, ARRAY[ARRAY['po', 'http://www.example.com/PO1&#39;]]))[1] as
text));
addr_row.city := upper(XMLSERIALIZE(CONTENT(xpath(
'/po:purchaseOrder/*[name(.) = "shipTo" or name(.) = "billTo"]['
||idx|| ']/po:city[1]/text()',
data_row.x, ARRAY[ARRAY['po', 'http://www.example.com/PO1&#39;]]))[1] as
text));
addr_row.state := upper(XMLSERIALIZE(CONTENT(xpath(
'/po:purchaseOrder/*[name(.) = "shipTo" or name(.) = "billTo"]['
||idx|| ']/po:state[1]/text()',
data_row.x, ARRAY[ARRAY['po', 'http://www.example.com/PO1&#39;]]))[1] as
text));
addr_row.zip := upper(XMLSERIALIZE(CONTENT(xpath(
'/po:purchaseOrder/*[name(.) = "shipTo" or name(.) = "billTo"]['
||idx|| ']/po:zip[1]/text()',
data_row.x, ARRAY[ARRAY['po', 'http://www.example.com/PO1&#39;]]))[1] as
text));
INSERT INTO tmp_xml_addr (id, xmlpos, street, city, state, zip) VALUES
(addr_row.id, addr_row.xmlpos, addr_row.street, addr_row.city,
addr_row.state, addr_row.zip);
END LOOP;
END IF;
RETURN;
END;
$BODY$
LANGUAGE 'plpgsql';

CREATE OR REPLACE FUNCTION tmp_populate_addr() RETURNS trigger AS
$BODY$
BEGIN
PERFORM tmp_extract_address(NEW);
RETURN NEW;
END;
$BODY$
LANGUAGE 'plpgsql';

CREATE TRIGGER tmp_populate_addr_trigger AFTER INSERT OR UPDATE ON
tmp_xml_test
FOR EACH ROW EXECUTE PROCEDURE tmp_populate_addr();

DROP FUNCTION IF EXISTS tmp_test_loop();
CREATE OR REPLACE FUNCTION tmp_test_loop() RETURNS SETOF tmp_xml_addr AS
$BODY$
DECLARE
num_loops int8 := 1000000;
BEGIN
FOR idx IN 1..num_loops LOOP
INSERT INTO tmp_xml_test VALUES (idx,
$$<purchaseOrder xmlns="http://www.example.com/PO1&quot; orderDate="1999-10-20">
<shipTo country="US">
<name>Alice Smith</name>
<street>123 Maple Street</street>
<city>Mill Valley</city>
<state>CA</state>
<zip>90952</zip>
</shipTo>
<billTo country="US">
<name>Robert Smith</name>
<street>8 Oak Avenue</street>
<city>Old Town</city>
<state>PA</state>
<zip>95819</zip>
</billTo>
<comment>Hurry, my lawn is going wild!</comment>
<items>
<item partNum="872-AA">
<productName>Lawnmower</productName>
<quantity>1</quantity>
<USPrice>148.95</USPrice>
<comment>Confirm this is electric</comment>
</item>
<item partNum="926-AA">
<productName>Baby Monitor</productName>
<quantity>1</quantity>
<USPrice>39.98</USPrice>
<shipDate>1999-05-21</shipDate>
</item>
</items>
</purchaseOrder>$$);
END LOOP;
FOR idx IN 1..num_loops LOOP
UPDATE tmp_xml_test SET id = idx WHERE id = idx;
END LOOP;
RETURN QUERY SELECT * FROM tmp_xml_addr ORDER BY id, xmlpos;
END;
$BODY$
LANGUAGE 'plpgsql';

SELECT * FROM tmp_test_loop();

"Matt Magoffin" <postgresql.org@msqr.us> writes:

Below is a test case that simulates the use of xpath() within a plpgsql
function in my application.

I'm able to duplicate the memory leak in this function with the current
Fedora 8 libxml2 (2.6.32). The leak is definitely inside libxml2
itself, because the bloat shows up here:

LibxmlContext: 150986752 total in 27 blocks; 6025448 free (204 chunks); 144961304 used

and that context is only used for allocations requested by libxml2.
(We reset that context at every transaction end, so the only way for
the problem to become really noticeable in Postgres is to do a whole
lot of xpath() calls in a single transaction.)

Some idle looking through the context suggests that the leakage consists
of short individually palloc'd null-terminated strings that seem to be
words from your test data. I tried dumping the context stats at
successive entries to xpath():

LibxmlContext: 260038656 total in 40 blocks; 3934120 free (204 chunks); 256104536 used
LibxmlContext: 260038656 total in 40 blocks; 3934088 free (204 chunks); 256104568 used
LibxmlContext: 260038656 total in 40 blocks; 3934056 free (204 chunks); 256104600 used
LibxmlContext: 260038656 total in 40 blocks; 3934056 free (205 chunks); 256104600 used
LibxmlContext: 260038656 total in 40 blocks; 3934000 free (205 chunks); 256104656 used
LibxmlContext: 260038656 total in 40 blocks; 3933960 free (204 chunks); 256104696 used
LibxmlContext: 260038656 total in 40 blocks; 3933928 free (204 chunks); 256104728 used
LibxmlContext: 260038656 total in 40 blocks; 3933896 free (204 chunks); 256104760 used
LibxmlContext: 260038656 total in 40 blocks; 3933856 free (204 chunks); 256104800 used
LibxmlContext: 260038656 total in 40 blocks; 3933816 free (204 chunks); 256104840 used
LibxmlContext: 260038656 total in 40 blocks; 3933784 free (204 chunks); 256104872 used
LibxmlContext: 260038656 total in 40 blocks; 3933752 free (204 chunks); 256104904 used
LibxmlContext: 260038656 total in 40 blocks; 3933752 free (205 chunks); 256104904 used
LibxmlContext: 260038656 total in 40 blocks; 3933696 free (205 chunks); 256104960 used
LibxmlContext: 260038656 total in 40 blocks; 3933656 free (204 chunks); 256105000 used
LibxmlContext: 260038656 total in 40 blocks; 3933624 free (204 chunks); 256105032 used

which shows that not every call in this test case leaks memory, but the
majority do, and that the leakage runs between 32 and 56 bytes per call.
This is on a 64-bit machine with cassert enabled, which means that the
palloc overhead is 24 bytes per chunk. So I think we can fairly
confidently assert that libxml is leaking exactly one short string per
xpath() call --- the leak is too small for it to be more than one palloc
chunk at a time.

I looked through the libxml2 sources a little bit but couldn't
immediately find the problem. I'm fairly confident though that
this could be reproduced outside Postgres, by replicating the sequence
of libxml2 calls we make in xpath(). The next step should probably be
to build a reproducer program and submit it to the libxml authors,
or maybe run it under a debugging malloc package that could help
identify where the leak is. Anyone want to do that?

regards, tom lane

I looked through the libxml2 sources a little bit but couldn't
immediately find the problem. I'm fairly confident though that
this could be reproduced outside Postgres, by replicating the sequence
of libxml2 calls we make in xpath(). The next step should probably be
to build a reproducer program and submit it to the libxml authors,
or maybe run it under a debugging malloc package that could help
identify where the leak is. Anyone want to do that?

Ugh, I'd love to give that a shot but that is a bit outside my comfort zone.

-- m@

On Wed, 2 Jul 2008, Tom Lane wrote:

"Matt Magoffin" <postgresql.org@msqr.us> writes:

Below is a test case that simulates the use of xpath() within a plpgsql
function in my application.

I'm able to duplicate the memory leak in this function with the current
Fedora 8 libxml2 (2.6.32). The leak is definitely inside libxml2
itself, because the bloat shows up here:

I think this should fix it.

Kris Jurka

I'm able to duplicate the memory leak in this function with the current
Fedora 8 libxml2 (2.6.32). The leak is definitely inside libxml2
itself, because the bloat shows up here:

I think this should fix it.

Kris Jurka

It looks like xml.c source has changed considerably since 8.3 (looking at
revision 1.68.2.2 from the 8.3.3. release). Do you know where/if this
patch would apply to the 8.3 branch?

-- m@

"Matt Magoffin" <postgresql.org@msqr.us> writes:

It looks like xml.c source has changed considerably since 8.3

No, hardly at all actually, but this patch happens to be right next door
to one of the lines that did change. cstring_to_text() replaces some
grottier stuff that used to be used for the same purpose.

In a few minutes I'm going to verify whether Kris' fix makes the leak go
away for me, and commit to CVS if so.

regards, tom lane

I think this should fix it.

Kris Jurka

It looks like xml.c source has changed considerably since 8.3 (looking at
revision 1.68.2.2 from the 8.3.3. release). Do you know where/if this
patch would apply to the 8.3 branch?

I diff'ed 1.74 and 1.68.2.2, and I'm guessing this new line could be added
after line 3203 in 1.68.2.2? I'll give that a try...

-- m@

"Matt Magoffin" <postgresql.org@msqr.us> writes:

I think this should fix it.
Kris Jurka

Confirmed, that makes it go away nicely here:

LibxmlContext: 57344 total in 3 blocks; 55720 free (202 chunks); 1624 used

It looks like xml.c source has changed considerably since 8.3 (looking at
revision 1.68.2.2 from the 8.3.3. release). Do you know where/if this
patch would apply to the 8.3 branch?

Here's what I just committed to the 8.3 branch:

Index: xml.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/adt/xml.c,v
retrieving revision 1.68.2.2
diff -c -r1.68.2.2 xml.c
*** xml.c	24 Mar 2008 19:12:58 -0000	1.68.2.2
--- xml.c	2 Jul 2008 23:57:20 -0000
***************
*** 3201,3206 ****
--- 3201,3207 ----
  		result = (text *) palloc(len + VARHDRSZ);
  		SET_VARSIZE(result, len + VARHDRSZ);
  		memcpy(VARDATA(result), str, len);
+ 		xmlFree(str);
  	}

return result;

regards, tom lane

"Matt Magoffin" <postgresql.org@msqr.us> writes:

Later, I added a large set of plpgsql trigger functions that operate on
that new xml column data, using the xpath() function to extract bits of
XML and populate them into normal tables. The server has been running in
this fashion for many months now, and there is a noticeable difference in
how Postgres is using memory now, in that over time it's non-shared memory
use is climbing higher and higher. Right now I'm tracking this from data
captured by Munin on the system. The memory creep is very slight, but over
many months is easy to discern.

Looking back, I'm not sure that what we just found explains that part
of your original report.

If I run some of these plpgsql functions using a lot of xpath() calls on
large sets of data, huge amounts of memory are consumed (gigabytes) and
the memory seems to accumulate until the transaction the functions are
running in completes.

This part seems to match the bug though --- the leak is approximately
the same size as all the text returned by xpath() within the current
transaction.

So there may be a second issue remaining to be found. Can you put
together a test case for the long-term small leak?

regards, tom lane

This part seems to match the bug though --- the leak is approximately
the same size as all the text returned by xpath() within the current
transaction.

So there may be a second issue remaining to be found. Can you put
together a test case for the long-term small leak?

regards, tom lane

Hmm, I'm not sure what else to add to this test case. This test case was a
good example of what our database is doing with xpath(); it is using quite
a number of them, that's all. Is there something else in particular you'd
be looking for in another test case?

-- m@

"Matt Magoffin" <postgresql.org@msqr.us> writes:

So there may be a second issue remaining to be found. Can you put
together a test case for the long-term small leak?

Hmm, I'm not sure what else to add to this test case. This test case was a
good example of what our database is doing with xpath(); it is using quite
a number of them, that's all. Is there something else in particular you'd
be looking for in another test case?

Well, you tell me --- *you* reported a behavior that isn't obviously
explained by the bug we found.

It's possible that what you were seeing was an indirect effect of the
now-known bug: if the xpath leak were to occur repeatedly on a large
scale in a long-lived session, I think it's possible that memory
allocation behavior might suffer due to fragmentation effects.
I feel that that's a pretty hand-wavy explanation though.

Probably the right thing for you to do now is just to install the known
fix, and keep an eye on your server for awhile to see if you still see
any indication of the long-term leak behavior.

regards, tom lane

Probably the right thing for you to do now is just to install the known
fix, and keep an eye on your server for awhile to see if you still see
any indication of the long-term leak behavior.

Certainly, that is my plan. Once I can get the patch rolled out to these
systems, I should be able to see if the memory-creep trend is resolved
after a couple of weeks or so.

-- m@

"Tom Lane" <tgl@sss.pgh.pa.us> writes:

Well, you tell me --- *you* reported a behavior that isn't obviously
explained by the bug we found.

In case it wasn't clear, the bug found was a intra-transaction memory leak.
When the transaction ended the memory would be reclaimed. That doesn't seem to
match the description of long term memory growth.

It's possible that what you were seeing was an indirect effect of the
now-known bug: if the xpath leak were to occur repeatedly on a large
scale in a long-lived session, I think it's possible that memory
allocation behavior might suffer due to fragmentation effects.
I feel that that's a pretty hand-wavy explanation though.

Another explanation is that there wasn't a inter-transaction memory leak, it
was just that the high water mark would grow whenever a transaction processed
more data than previous transactions. If the data set size varies a lot most
common distributions would have the majority of data sets be about the same
size with a long tail of larger sets. That might like a slow creep as the
increases get rarer and rarer but do continue to happen.

That's just a special case of what would be expected to happen with memory
allocation anyways though. Few allocators return memory to the OS anyways. It
might just be exaggerated in this case since probably a significant part of
Postgres's footprint here was the per-transaction memory being used by this
leak.

--
Gregory Stark
EnterpriseDB http://www.enterprisedb.com
Get trained by Bruce Momjian - ask me about EnterpriseDB's PostgreSQL training!

Gregory Stark <stark@enterprisedb.com> writes:

That's just a special case of what would be expected to happen with memory
allocation anyways though. Few allocators return memory to the OS anyways.

Well, that does happen on Linux for instance. Since Matt knew in his
original report that the xpath leak was intra-transaction, I assumed
he must be using a platform where malloc/free can release memory back
to the OS --- else he couldn't have seen that behavior from outside
the backend.

Still, it's entirely possible that some sort of high-water-mark is
involved somewhere, perhaps in malloc's internal data structures.

regards, tom lane

Gregory Stark <stark@enterprisedb.com> writes:

That's just a special case of what would be expected to happen with
memory
allocation anyways though. Few allocators return memory to the OS
anyways.

Well, that does happen on Linux for instance. Since Matt knew in his
original report that the xpath leak was intra-transaction, I assumed
he must be using a platform where malloc/free can release memory back
to the OS --- else he couldn't have seen that behavior from outside
the backend.

Still, it's entirely possible that some sort of high-water-mark is
involved somewhere, perhaps in malloc's internal data structures.

I was really going on a hunch, as I noticed a definite trend of postgres
processes using more and more memory over time, and it only started after
switching to 8.3 and starting to use xpath() quite heavily. Most of the
memory data I have comes from Linux x64 systems with Postgres compiled as
64-bit. But I did also notice what appeared to be a similar trend on an OS
X PPC system.

In any event, I'm sorry I can't provide any more helpful tests, but I'll
report back how the system changes after I've patched these systems.

-- m@

Gregory Stark <stark@enterprisedb.com> writes:

That's just a special case of what would be expected to happen with
memory
allocation anyways though. Few allocators return memory to the OS
anyways.

Well, that does happen on Linux for instance. Since Matt knew in his
original report that the xpath leak was intra-transaction, I assumed
he must be using a platform where malloc/free can release memory back
to the OS --- else he couldn't have seen that behavior from outside
the backend.

Still, it's entirely possible that some sort of high-water-mark is
involved somewhere, perhaps in malloc's internal data structures.

I was really going on a hunch, as I noticed a definite trend of postgres
processes using more and more memory over time, and it only started after
switching to 8.3 and starting to use xpath() quite heavily. Most of the
memory data I have comes from Linux x64 systems with Postgres compiled as
64-bit. But I did also notice what appeared to be a similar trend on an OS
X PPC system.

In any event, I'm sorry I can't provide any more helpful tests, but I'll
report back how the system changes after I've patched these systems.

I'm following up on this thread from a month ago on PG 8.3 memory use. I'm
afraid even after updating to 8.3.3 + this patch, I still see the same
overall memory trend. You can see what I'm looking at here with a couple
of memory graphs.

The first comes from our old primary database server, which started on 8.1
and then we switched to 8.3. I've added a callout on the chart to when we
switched to 8.3. Before the switch, the application memory use (bright
green) was pretty consistent, around 250MB. After the switch, you can see
the application memory trends upwards over time.

http://msqr.us/pg83-mem/pg83-memlead-1.png

Around June, we then switched to some new hardware. It was on this machine
about a month ago I updated to 8.3.3 + the xml.c patch referred to in this
thread. I've pointed this out on this chart:

http://msqr.us/pg83-mem/pg83-memlead-2.png

Here the application memory continues to trend upwards over time since the
8.3.3 server was started, up to 1.2GB as of now.

Am I right in my understanding that in general I should not see this
every-increasing use of app memory by PostgreSQL? Or will PostgreSQL
slowly work towards consuming all the shared memory we've allocated (4GB
in this case) and retain that? The only apps running on this box are
PostgreSQL and Slony for replication.

-- m@