Received: from maia.hub.org (unknown [200.46.208.211]) by mail.postgresql.org (Postfix) with ESMTP id B7FC5632559 for ; Sun, 21 Mar 2010 11:33:48 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.208.211]) (amavisd-maia, port 10024) with ESMTP id 78882-09 for ; Sun, 21 Mar 2010 14:33:28 +0000 (UTC) X-Greylist: domain auto-whitelisted by SQLgrey-1.7.6 Received: from mail-bw0-f221.google.com (mail-bw0-f221.google.com [209.85.218.221]) by mail.postgresql.org (Postfix) with ESMTP id 989F76321B2 for ; Sun, 21 Mar 2010 11:33:37 -0300 (ADT) Received: by bwz21 with SMTP id 21so4511471bwz.35 for ; Sun, 21 Mar 2010 07:33:35 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:mime-version:received:in-reply-to:references :date:message-id:subject:from:to:cc:content-type; bh=tfMgrJBkWObKXl5GORo6zO0P8jvfGb0amkavJrbQeV0=; b=Etdp714JMkkf6/BykQjSwD1eEvfBF5rfnel+2T7ZGP4IKi88hh2SpnjKDTu6QiiAQJ sZRss/LE7NmUNl6IEIbMD11kBig03YIEu1MyhqzRbW+9J6mzH+OiALcEVRwIUSjBvkok dHNajg30i+LiKwYnYJ+VqFBOewc9YH+gz2bLU= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :cc:content-type; b=njAbjnrAjQxaI0X9JTCF0n243vo/pbgnMpkJI+1nNHY2Op/UDNZx6uk8OPsX7NDv4X wMbqoLnumhZndsfC0YoHeMu9YzrX/T9tuQ5jzNbLRHFPDmO6sH6/V9bYLCiVejMLIV+s ZWgF2+1CdJEMbA/XaCvX8284fytHbHDh5LZeQ= MIME-Version: 1.0 Received: by 10.204.85.73 with SMTP id n9mr2248335bkl.71.1269182015095; Sun, 21 Mar 2010 07:33:35 -0700 (PDT) In-Reply-To: <4BA61C74.70506@davidnewall.com> References: <4B9C97E1.40509@davidnewall.com> <24696.1268598111@sss.pgh.pa.us> <4BA61C74.70506@davidnewall.com> Date: Sun, 21 Mar 2010 09:33:35 -0500 Message-ID: Subject: Re: pg_dump far too slow From: Dave Crooke To: David Newall Cc: Tom Lane , pgsql-performance@postgresql.org, robertmhaas@gmail.com Content-Type: multipart/alternative; boundary=0016e6d9728a2a46c104825077b5 X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-2.431 tagged_above=-10 required=5 tests=AWL=0.167, BAYES_00=-2.599, HTML_MESSAGE=0.001 X-Spam-Level: X-Archive-Number: 201003/257 X-Sequence-Number: 38082 --0016e6d9728a2a46c104825077b5 Content-Type: text/plain; charset=ISO-8859-1 One more from me .... If you think that the pipe to GZIP may be causing pg_dump to stall, try putting something like buffer(1) in the pipeline ... it doesn't generally come with Linux, but you can download source or create your own very easily ... all it needs to do is asynchronously poll stdin and write stdout. I wrote one in Perl when I used to do a lot of digital video hacking, and it helped with chaining together tools like mplayer and mpeg. However, my money says that Tom's point about it being (disk) I/O bound is correct :-) Cheers Dave On Sun, Mar 21, 2010 at 8:17 AM, David Newall wrote: > Thanks for all of the suggestions, guys, which gave me some pointers on new > directions to look, and I learned some interesting things. > > The first interesting thing was that piping (uncompressed) pg_dump into > gzip, instead of using pg_dump's internal compressor, does bring a lot of > extra parallelism into play. (Thank you, Matthew Wakeling.) I observed > gzip using 100% CPU, as expected, and also two, count them, two postgres > processes collecting data, each consuming a further 80% CPU. It seemed to > me that Postgres was starting and stopping these to match the capacity of > the consumer (i.e. pg_dump and gzip.) Very nice. Unfortunately one of > these processes dropped eventually, and, according to top, the only non-idle > process running was gzip (100%.) Obviously there were postgress and pg_dump > processes, too, but they were throttled by gzip's rate of output and > effectively idle (less than 1% CPU). That is also interesting. The final > output from gzip was being produced at the rate of about 0.5MB/second, which > seems almost unbelievably slow. > > I next tried Tom Lane's suggestion, COPY WITH BINARY, which produced the > complete 34GB file in 30 minutes (a good result.) I then compressed that > with gzip, which took an hour and reduced the file to 32GB (hardly worth the > effort) for a total run time of 90 minutes. In that instance, gzip produced > output at the rate of 10MB/second, so I tried pg_dump -Z0 to see how quickly > that would dump the file. I had the idea that I'd go on to see how quickly > gzip would compress it, but unfortunately it filled my disk before finishing > (87GB at that point), so there's something worth knowing: pg_dump's output > for binary data is very much less compact than COPY WITH BINARY; all those > backslashes, as Tom pointed out. For the aforementioned reason, I didn't > get to see how gzip would perform. For the record, pg_dump with no > compression produced output at the rate of 26MB/second; a rather meaningless > number given the 200%+ expansion of final output. > > I am now confident the performance problem is from gzip, not Postgres and > wonder if I should read up on gzip to find why it would work so slowly on a > pure text stream, albeit a representation of PDF which intrinsically is > fairly compressed. Given the spectacular job that postgres did in adjusting > it's rate of output to match the consumer process, I did wonder if there > might have been a tragic interaction between postgres and gzip; perhaps > postgres limits its rate of output to match gzip; and gzip tries to compress > what's available, that being only a few bytes; and perhaps that might be so > inefficient that it hogs the CPU; but it don't think that likely. I had a > peek at gzip's source (surprisingly readable) and on first blush it does > seem that unfortunate input could result in only a few bytes being written > each time through the loop, meaning only a few more bytes could be read in. > > Just to complete the report, I created a child table to hold the PDF's, > which are static, and took a dump of just that table, and adjusted my backup > command to exclude it. Total size of compressed back sans PDFs circa 7MB > taking around 30 seconds. > --0016e6d9728a2a46c104825077b5 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable One more from me ....

If you think that the pipe to GZIP may be caus= ing pg_dump to stall, try putting something like buffer(1) in the pipeline = ... it doesn't generally come with Linux, but you can download source o= r create your own very easily ... all it needs to do is asynchronously poll= stdin and write stdout. I wrote one in Perl when I used to do a lot of dig= ital video hacking, and it helped with chaining together tools like mplayer= and mpeg.

However, my money says that Tom's point about it being (disk) I/O b= ound is correct :-)

Cheers
Dave

On Sun, Mar 21, 2010 at 8:17 AM, David Newall <postgresql@davidnewall.com><= /span> wrote:
Thanks for all of= the suggestions, guys, which gave me some pointers on new directions to lo= ok, and I learned some interesting things.

The first interesting thing was that piping (uncompressed) pg_dump into gzi= p, instead of using pg_dump's internal compressor, does bring a lot of = extra parallelism into play. =A0(Thank you, Matthew Wakeling.) =A0I observe= d gzip using 100% CPU, as expected, and also two, count them, two postgres = processes collecting data, each consuming a further 80% CPU. =A0It seemed t= o me that Postgres was starting and stopping these to match the capacity of= the consumer (i.e. pg_dump and gzip.) =A0Very nice. =A0Unfortunately one o= f these processes dropped eventually, and, according to top, the only non-i= dle process running was gzip (100%.) =A0Obviously there were postgress and = pg_dump processes, too, but they were throttled by gzip's rate of outpu= t and effectively idle (less than 1% CPU). =A0That is also interesting. =A0= The final output from gzip was being produced at the rate of about 0.5MB/se= cond, which seems almost unbelievably slow.

I next tried Tom Lane's suggestion, COPY WITH BINARY, which produced th= e complete 34GB file in 30 minutes (a good result.) =A0I then compressed th= at with gzip, which took an hour and reduced the file to 32GB (hardly worth= the effort) for a total run time of 90 minutes. =A0In that instance, gzip = produced output at the rate of 10MB/second, so I tried pg_dump -Z0 to see h= ow quickly that would dump the file. =A0I had the idea that I'd go on t= o see how quickly gzip would compress it, but unfortunately it filled my di= sk before finishing (87GB at that point), so there's something worth kn= owing: pg_dump's output for binary data is very much less compact than = COPY WITH BINARY; all those backslashes, as Tom pointed out. =A0For the afo= rementioned reason, I didn't get to see how gzip would perform. =A0For = the record, pg_dump with no compression produced output at the rate of 26MB= /second; a rather meaningless number given the 200%+ expansion of final out= put.

I am now confident the performance problem is from gzip, not Postgres and w= onder if I should read up on gzip to find why it would work so slowly on a = pure text stream, albeit a representation of PDF which intrinsically is fai= rly compressed. =A0Given the spectacular job that postgres did in adjusting= it's rate of output to match the consumer process, I did wonder if the= re might have been a tragic interaction between postgres and gzip; perhaps = postgres limits its rate of output to match gzip; and gzip tries to compres= s what's available, that being only a few bytes; and perhaps that might= be so inefficient that it hogs the CPU; but it don't think that likely= . =A0I had a peek at gzip's source (surprisingly readable) and on first= blush it does seem that unfortunate input could result in only a few bytes= being written each time through the loop, meaning only a few more bytes co= uld be read in.

Just to complete the report, I created a child table to hold the PDF's,= which are static, and took a dump of just that table, and adjusted my back= up command to exclude it. =A0Total size of compressed back sans PDFs circa = 7MB taking around 30 seconds.

--0016e6d9728a2a46c104825077b5--