Re: Prepared query parsing much slower in 9.0?

Hackers,

Followup to Josh's posts.

I'm getting Bricolage 2.0 ready to ship, and took some time to test it on PostgreSQL 9.0 today. I built PostgreSQL from Git/master with:

./configure --with-libs=/usr/local/lib --with-includes=/usr/local/include --prefix=$BASE --with-perl PERL=$PERL

This is simpler than how I build 8.4:

./configure --with-libedit-preferred --with-bonjour --with-perl PERL=$PERL \
--with-openssl --with-pam --with-krb5 --with-libxml --with-ldap \
--with-ossp-uuid --with-includes=/usr/local/include \
--enable-integer-datetimes --with-zlib \
--with-libs=/usr/local/lib --prefix=$BASE || exit $?

When I run the Bricolage test suite against 8.4 (12,700 assertions), it takes 45-50s on my MacBook Pro. When I run them against 9.0, it takes 530-540s!

Is there anything in the tree that has debugging turned on or something? I'm not at all sure that what Josh has found can account for this 10x difference, can it (I ran the tests several times).

Looking at the process table, postgresql never goes over 25% CPU on 8.4, but hovers at 90-95% on 9.0. To judge by the way test output is emitted, writes are particularly slow, but I can see some substantial delays on reads, too.

I thought at first the difference might be because I hand't tweaked postgresql.conf at all, but then I updated it to match 8.4's and restarted, and things were still slow. Important settings I have:

max_connections = 100
shared_buffers = 100MB
work_mem = 8MB
maintenance_work_mem = 64MB
wal_buffers = 2MB
effective_cache_size = 750MB
log_destination = 'csvlog'
logging_collector = on
standard_conforming_strings = on

But as I said, things were slow when these had their default values, too.

This is on Mac OS X 10.6.3 "Snow Leopard".

Best,

David

On Apr 5, 2010, at 10:32 PM, Josh Berkus wrote:

> All,
>
> Wheeler has been doing some head-to-head performance testing of
> Bricolage performance on 8.4 vs. 9.0. So far, 9.0 has been slower, and
> I've been trying to track down the particular areas where it is.
>
> One appears to be prepared query parsing. One test of the Bricolage
> test suite creates 89 new prepared queries.
>
> 9.0's median parse time is 30% slower than 8.4 ( .2ms vs. .134ms). More
> seriously, the top 3 slowest parses take 900% as much time as they do on
> 8.4, and account for 50% of overall prepared query parsing time. Those
> appear to be these queries, although the pg_log makes it hard to relate
> a parse to what query is being prepared:
>
> execute dbdpg_p81932_1: SELECT u.id, u.login, u.password,
> u.active, p.prefix, p.fname, p.mname, p.lname, p.suffix, p.active,
> m.grp__id, 1 FROM person p, usr u, member m, user_member c
> WHERE p.id = u.id AND u.id = c.object_id AND c.member__id = m.id
> AND m.active = '1' AND u.id = $1 ORDER BY LOWER(p.lname),
> LOWER(p.fname), LOWER(p.mname), u.id
>
> execute dbdpg_p81932_2: SELECT DISTINCT a.id FROM
> site a, member m, site_member c WHERE a.id = c.object_id AND
> c.member__id = m.id AND m.active = '1' AND LOWER(a.name) LIKE LOWER($1)
> ORDER BY a.id
>
> execute dbdpg_p81932_27: DELETE FROM org WHERE id > 1
>
> --
> -- Josh Berkus
> PostgreSQL Experts Inc.
> http://www.pgexperts.com