8.3devel slower than 8.2 under read-only load

On Wed, 2007-11-21 at 20:04 +0100, Guillaume Smet wrote:

number of clients: 1
number of transactions per client: 1000
number of transactions actually processed: 1000/1000
tps = 784.819087 (including connections establishing)
tps = 786.884214 (excluding connections establishing)

All the queries are index scans (SELECT a couple of fields FROM a
table WHERE one or two conditions). I checked the plans on both 8.2
and 8.3 and they are identical. I made several runs and numbers are
consistent.

Please do tests of at least 2 minutes duration. A 1.25 second test isn't
enough. Please confirm you have VACUUM ANALYZED each db beforehand.

Have you checked that the EXPLAIN ANALYZEs are essentially identical
also? Is the data identical on both systems?

How do the postgresql.conf files differ?

Please find out any differences you can, so we can rule things out.

Also, do a run with SELECT 1 FROM table where col = constant; so we can
assess differences in path without cache or data being relevant.

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com

FWIW,

Please do tests of at least 2 minutes duration. A 1.25 second test isn't
enough. Please confirm you have VACUUM ANALYZED each db beforehand.

Have you checked that the EXPLAIN ANALYZEs are essentially identical
also? Is the data identical on both systems?

I've been running some fairly heavy read-only tests (5 minutes duration) against 8.3beta2 and 8.2.5 and 8.1.10 and are getting slightly faster numbers for 8.2.5 over 8.1 and 8.3beta2 looks consistently faster by a few percent. This is heavily oriented to postGIS queries so your mileage may vary. But so far I haven't seen any red flags or show stoppers from my (limited) perspective. There are some changes to the config files but I don't have details at hand.

Initial tests are always faster; we usually throw them out and run for real numbers starting with 3rd tests to make sure we don't jump at cache issues. For the most part we only care about performance with as much of the database in cache as we can so those initial tests aren;t of much use.

(Sorry for the poor posting -- challenged mail client)

HTH,

Greg Williamson
Senior DBA
GlobeXplorer LLC, a DigitalGlobe company

Confidentiality Notice: This e-mail message, including any attachments, is for the sole use of the intended recipient(s) and may contain confidential and privileged information and must be protected in accordance with those provisions. Any unauthorized review, use, disclosure or distribution is prohibited. If you are not the intended recipient, please contact the sender by reply e-mail and destroy all copies of the original message.

(My corporate masters made me say this.)

On Nov 21, 2007 10:09 PM, Simon Riggs <simon@2ndquadrant.com> wrote:

Please do tests of at least 2 minutes duration. A 1.25 second test isn't
enough.

I already run far longer tests. It's not a matter of running a test
for long, it's just that each unique query is a little bit slower.

Moreover it's not a pgbench artifact, I have the same results inside
the real application (it's a PHP app).

Please confirm you have VACUUM ANALYZED each db beforehand.

Yes of course. The dump was just loaded in both databases. Both
databases are identical (the 8.3 db is smaller in size on the disk as
expected).
They are both analyzed.
FYI, I also have the very same database running on a 8.1.x branch
(just loaded and analyzed) and the results are more like the 8.2 ones
than like the 8.3 ones.

Have you checked that the EXPLAIN ANALYZEs are essentially identical
also?

I did the test before. Every plan of every query involved in the test
is identical. I removed from the test the one where a different index
was chosen (8.2 chooses a larger index and 8.3 chooses the good one -
Tom fixed something about that not so long ago and it works fine for
us too).

Is the data identical on both systems?

Freshly loaded from a dump.

How do the postgresql.conf files differ?

They don't differ at all, except for the new parameters introduced in
8.3 (I let them the default).

Also, do a run with SELECT 1 FROM table where col = constant; so we can
assess differences in path without cache or data being relevant.

I don't think the cache is relevant as they are all index scans and
queries don't return a lot of rows. The indexes fit in RAM and I run
each pgbench test several times.

And to answer a question Joshua asked on IRC, pgbench is the same in
both tests. I use the system wide one (8.1.9 from the RH package).

To be sure, here are more information:
** 8.2 **
cityvox=# show shared_buffers;
shared_buffers
----------------
128MB
(1 row)

cityvox=# show work_mem;
work_mem
----------
32MB
(1 row)

cityvox=# show lc_collate;
lc_collate
-------------
fr_FR.UTF-8
(1 row)

cityvox=# select version();
version
----------------------------------------------------------------------------------------------------
PostgreSQL 8.2.5 on i686-pc-linux-gnu, compiled by GCC gcc (GCC)
4.1.1 20070105 (Red Hat 4.1.1-52)
(1 row)

** 8.3 **
cityvox=# ANALYZE;
ANALYZE
cityvox=# show shared_buffers;
shared_buffers
----------------
128MB
(1 row)

cityvox=# show work_mem;
work_mem
----------
32MB
(1 row)

cityvox=# show lc_collate;
lc_collate
-------------
fr_FR.UTF-8
(1 row)

cityvox=# select version();
version
-------------------------------------------------------------------------------------------------------
PostgreSQL 8.3beta2 on i686-pc-linux-gnu, compiled by GCC gcc (GCC)
4.1.1 20070105 (Red Hat 4.1.1-52)
(1 row)

Then I run the test longer (I run it with 1000 transactions before to
have the data in cache):
** 8.2 **
[ip-dyn151 postgresql]# pgbench -h localhost -p 5482 -U cityvox -f
bench.cityvox.simple.sql -t 100000 -c 1 cityvox
starting vacuum...end.
transaction type: Custom query
scaling factor: 1
number of clients: 1
number of transactions per client: 100000
number of transactions actually processed: 100000/100000
tps = 853.100511 (including connections establishing)
tps = 853.124776 (excluding connections establishing)

** 8.3 **
[ip-dyn151 postgresql]# pgbench -h localhost -p 5483 -U cityvox -f
bench.cityvox.simple.sql -t 100000 -c 1 cityvox
starting vacuum...end.
transaction type: Custom query
scaling factor: 1
number of clients: 1
number of transactions per client: 100000
number of transactions actually processed: 100000/100000
tps = 791.244011 (including connections establishing)
tps = 791.268316 (excluding connections establishing)

Then let's simplify the test a bit with only one query:

[root@ip-dyn151 postgresql]# cat bench.cityvox.really.simple.sql
select libvil from vilsitelang where codelang='FRA' and codevil='LYO'

** 8.2 **
cityvox=> EXPLAIN ANALYZE select libvil from vilsitelang where
codelang='FRA' and codevil='LYO';
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------
Index Scan using pk_vilsitelang on vilsitelang (cost=0.00..4.27
rows=1 width=12) (actual time=0.028..0.031 rows=1 loops=1)
Index Cond: (((codevil)::text = 'LYO'::text) AND ((codelang)::text
= 'FRA'::text))
Total runtime: 0.071 ms
(3 rows)

[ip-dyn151 postgresql]# pgbench -h localhost -p 5482 -U cityvox -f
bench.cityvox.really.simple.sql -t 100000 -c 1 cityvox
starting vacuum...end.
transaction type: Custom query
scaling factor: 1
number of clients: 1
number of transactions per client: 100000
number of transactions actually processed: 100000/100000
tps = 3468.220041 (including connections establishing)
tps = 3468.630504 (excluding connections establishing)

** 8.3 **
cityvox=> EXPLAIN ANALYZE select libvil from vilsitelang where
codelang='FRA' and codevil='LYO';
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------
Index Scan using pk_vilsitelang on vilsitelang (cost=0.00..4.27
rows=1 width=9) (actual time=0.029..0.031 rows=1 loops=1)
Index Cond: (((codevil)::text = 'LYO'::text) AND ((codelang)::text
= 'FRA'::text))
Total runtime: 0.057 ms
(3 rows)

[ip-dyn151 postgresql]# pgbench -h localhost -p 5483 -U cityvox -f
bench.cityvox.really.simple.sql -t 100000 -c 1 cityvox
starting vacuum...end.
transaction type: Custom query
scaling factor: 1
number of clients: 1
number of transactions per client: 100000
number of transactions actually processed: 100000/100000
tps = 3272.416750 (including connections establishing)
tps = 3272.820625 (excluding connections establishing)

Except for the prefix, I didn't give any options to configure. The CVS
tip doesn't have any particular options compared to 8.2?

--
Guillaume

On Nov 22, 2007 12:07 AM, Gregory Williamson
<Gregory.Williamson@digitalglobe.com> wrote:

I've been running some fairly heavy read-only tests (5 minutes duration)
against 8.3beta2 and 8.2.5 and 8.1.10 and are getting slightly faster
numbers for 8.2.5 over 8.1 and 8.3beta2 looks consistently faster by a few
percent. This is heavily oriented to postGIS queries so your mileage may
vary. But so far I haven't seen any red flags or show stoppers from my
(limited) perspective. There are some changes to the config files but I
don't have details at hand.

Thanks for your input. That's what I expected and that's why I'm a bit
surprised...

--
Guillaume

On Wed, 21 Nov 2007, Guillaume Smet wrote:

*** 8.2 ***
tps = 853.360277 (including connections establishing)

*** 8.3 ***
tps = 784.819087 (including connections establishing)

This is an 8% drop. I've seen a larger difference than that between two
identical installations of the same version when the database is many GB
large. Hard drives deliver a higher transfer rate at their inner
portions, typically the start of the disk from the operating system's
perspective. It's not unusual for the slow parts of the disk to be 30-40%
slower than the fast ones. I've been known to mkfs all the database
paritions before each test run just to remove this bias, so that the data
was on exactly the same portion of the drive each time.

Not saying this is responsible for your results, just that benchmarking is
hard and there may be somthing other than what you think responsible for a
difference of this size. I'd suggest running "select count(*) from x" on
a couple of the big tables as one way to get a feel for whether the
underlying disk is delivering at the same speed in both installations.

--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD

"Guillaume Smet" <guillaume.smet@gmail.com> writes:

I took a couple of very simple read only queries executed in the pages
to create a pgbench script and I have the following results:

Hmm ... I can reproduce a consistent difference of about three percent
between 8.2 and HEAD. Using pgbench's built-in SELECT-only transaction
after "pgbench -i -s 10 bench", I get

HEAD:

$ time pgbench -n -S -c 10 -t 100000 bench
transaction type: SELECT only
scaling factor: 10
number of clients: 10
number of transactions per client: 100000
number of transactions actually processed: 1000000/1000000
tps = 9399.185809 (including connections establishing)
tps = 9402.305058 (excluding connections establishing)

real 1m46.402s
user 0m19.889s
sys 0m23.497s

8.2:

$ time pgbench -n -S -c 10 -t 100000 bench82
transaction type: SELECT only
scaling factor: 10
number of clients: 10
number of transactions per client: 100000
number of transactions actually processed: 1000000/1000000
tps = 9729.892729 (including connections establishing)
tps = 9732.769774 (excluding connections establishing)

real 1m42.785s
user 0m19.250s
sys 0m23.646s

Vanilla build (--enable-debug but not much else), C locale, SQL_ASCII
encoding, dual Xeon/EMT on Fedora Core 6. Configuration parameters
are all defaults in both cases, except I had fsync off, which shouldn't
matter anyway in a read-only test.

The weird thing is that after a couple of hours of poking at it with
oprofile and other sharp objects, I have no idea *why* it's slower.
oprofile shows just about the same relative percentages for all the
hot-spot functions in the backend. strace shows that there's no
particular increase in kernel calls (indeed, HEAD seems to use
significantly fewer semops/selects, indicating that we had some
success in reducing contention). It's not that autovacuum is now
on by default --- turning it off made no particular difference.
It's not that stats collection is now on by default --- ditto.
Slowing down the walwriter and bgwriter doesn't help either.
It's not pgbench itself --- I get about the same results if I use
8.2 pgbench with HEAD or vice versa.

The best theory I can come up with is that all the new stuff added
to the backend (the executable is about 12% larger than in 8.2)
has resulted in some generalized slowdown just because the code is
larger. But most of the added code isn't getting exercised by this
test, so in theory the code bloat shouldn't be hurting us either.

Weird. Given that it's only a couple percent I'm not gonna panic
about it, but I would like to know where the time is going ...

regards, tom lane

Greg Smith <gsmith@gregsmith.com> writes:

On Wed, 21 Nov 2007, Guillaume Smet wrote:

*** 8.2 ***
tps = 853.360277 (including connections establishing)

*** 8.3 ***
tps = 784.819087 (including connections establishing)

This is an 8% drop. I've seen a larger difference than that between two
identical installations of the same version when the database is many GB
large. Hard drives deliver a higher transfer rate at their inner
portions, typically the start of the disk from the operating system's
perspective. It's not unusual for the slow parts of the disk to be 30-40%
slower than the fast ones.

FWIW, the test cases I was just comparing are entirely CPU-bound ---
vmstat says there are no disk reads happening at all. Now I only got a
3% drop, so that may not be the same effect Guillaume is seeing. But
the whole thing is a bit upsetting seeing that we thought we'd reduced
the overhead for short read-only transactions ...

regards, tom lane

On Nov 22, 2007 12:59 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

It's not that autovacuum is now
on by default --- turning it off made no particular difference.

Tested that also a few hours ago. No difference.

It's not that stats collection is now on by default --- ditto.

Same here. My 8.2 has stats collection enabled in the same way that 8.3 does.

--
Guillaume

On Nov 22, 2007 12:49 AM, Greg Smith <gsmith@gregsmith.com> wrote:

Hard drives deliver a higher transfer rate at their inner
portions, typically the start of the disk from the operating system's
perspective.

It could have been a good point if it was seq scans of large tables.
It's only index scans on small tables which return only a couple of
rows. They all fit in cache without any problem.

For the last test I exposed in a previous email, the table is just
5480 rows and here are the sizes of the table and the index used:
cityvox=> select pg_size_pretty(pg_relation_size('vilsitelang'));
pg_size_pretty
----------------
232 kB
(1 row)

cityvox=> select pg_size_pretty(pg_relation_size('pk_vilsitelang'));
pg_size_pretty
----------------
120 kB
(1 row)

Not saying this is responsible for your results, just that benchmarking is
hard and there may be somthing other than what you think responsible for a
difference of this size.

Sure. That's why I wanted other people advice :).

I'm not saying my benchmark is perfectly relevant: I made it
excessively simple on purpose. I just see a general slow down which is
quite consistent accross all the tests I did (with pgbench or the
application) and I'd really like to know if it's just my case on this
particular box or something more general.
Let's call it a call to share benchmark results for 8.3 :). We're not
that far from the release and I didn't see a lot of benchmarks results
around.

I just wanted to add that I know that there is a lot of other things
which may be faster with 8.3. What bothers me is that I don't think
the other improvements will help that much this database in particular
and this is by far the most critical database we're hosting here.

--
Guillaume

I wrote:

The weird thing is that after a couple of hours of poking at it with
oprofile and other sharp objects, I have no idea *why* it's slower.
oprofile shows just about the same relative percentages for all the
hot-spot functions in the backend.

However, some comparisons with gprof show that the planner is calling
the hot-spot functions more than it used to, which might be enough to
account for a couple percent on trivial queries like the ones being
issued by pg_bench ("SELECT abalance FROM accounts WHERE aid = :aid;").

After the holiday I'll look into refactoring to try to avoid the
extra calls.

Another issue is that on read-only transactions there's an extra
gettimeofday() call caused by pgstat_report_tabstats, which could be a
problem on machines with slow gettimeofday(). However that shouldn't
happen if you've got track_counts turned off, so if you don't see any
difference with or without stats then it's not the problem for you.

regards, tom lane

On Nov 21, 2007 7:22 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

FWIW, the test cases I was just comparing are entirely CPU-bound ---
vmstat says there are no disk reads happening at all. Now I only got a
3% drop, so that may not be the same effect Guillaume is seeing. But
the whole thing is a bit upsetting seeing that we thought we'd reduced
the overhead for short read-only transactions ...

A month or so ago I mentioned to Bruce that we were seeing this
behavior (accidentally) but hadn't had time to focus on it or
determine whether it was a tuning issue.

Basically we're performing the same select-only pgbench test, but with
a varying scale from 1 to 1000. In almost all cases, 8.2.5 is faster
than 8.3 by about 2-5 percent.

The script given to us by a customer was as follows:

for scale in 1 2 5 10 20 30 40 50 75 100 200 400 800 1000; do
echo "------------------------------------------------------------"
echo "SCALE $scale"
dropdb pgbench
createdb pgbench
pgbench -p 5432 -i -s $scale pgbench
psql pgbench -c 'CHECKPOINT'
pgbench -p 5432 -c 8 -t 2500 -S pgbench
pgbench -p 5432 -c 8 -t 2500 -S pgbench
pgbench -p 5432 -c 8 -t 2500 -S pgbench
done

--
Jonah H. Harris, Sr. Software Architect | phone: 732.331.1324
EnterpriseDB Corporation | fax: 732.331.1301
499 Thornall Street, 2nd Floor | jonah.harris@enterprisedb.com
Edison, NJ 08837 | http://www.enterprisedb.com/

"Guillaume Smet" <guillaume.smet@gmail.com> writes:

I'm not saying my benchmark is perfectly relevant: I made it
excessively simple on purpose. I just see a general slow down which is
quite consistent accross all the tests I did (with pgbench or the
application) and I'd really like to know if it's just my case on this
particular box or something more general.

Are you examining only "trivial" queries? I've been able to identify a
couple of new planner hotspots that could explain some slowdown if the
planning time is material compared to the execution time. If you're
seeing a slowdown on queries that run for awhile, that would be
something else ...

regards, tom lane

On Nov 22, 2007 2:17 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Another issue is that on read-only transactions there's an extra
gettimeofday() call caused by pgstat_report_tabstats, which could be a
problem on machines with slow gettimeofday(). However that shouldn't
happen if you've got track_counts turned off, so if you don't see any
difference with or without stats then it's not the problem for you.

The box is a Core2 duo box so I don't think it's the case.

track_counts on/off doesn't change anything to the results.

--
Guillaume

On Nov 22, 2007 6:44 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Are you examining only "trivial" queries? I've been able to identify a
couple of new planner hotspots that could explain some slowdown if the
planning time is material compared to the execution time. If you're
seeing a slowdown on queries that run for awhile, that would be
something else ...

Yes, I kept only queries with no join and a couple of where
conditions. As I explained previously, I can reproduce the behavior
with a single index scan on only one table (plan posted previously).
If anyone is interested I can post the content of this table (there's
nothing confidential in it so I should have the customer permission)
and a couple of instructions to reproduce the test case.

The case in which I used a few differents queries executes the
following ones directly extracted from the application (all are index
scans - and they use the exact same index on 8.2 and 8.3):
select libvil from vilsitelang where codelang='FRA' and codevil='LYO'
select TL.motsclesmetatags, TL.descriptifmeta, TL.motcleoverture_l,
TL.motcleoverture_c, TL.baselinetheme from themelang TL where
TL.codeth = 'ASS' and TL.codelang = 'FRA'
SELECT libvilpubwoo, codelang, codepays, petiteville FROM vilsite
WHERE codevil = 'LYO'
select libvil from vilsitelang where codelang='FRA' and codevil='LYO'

So as you can see, queries can't be simpler.

--
Guillaume

On Thu, 2007-11-22 at 00:30 +0100, Guillaume Smet wrote:

Is the data identical on both systems?

Guillaume,

Sounds comprehensive, thanks for double checking.

Would it be possible to do these tests?

1. Compare SELECT 1;
This will allow us to remove planner and indexscan overheads from
results, though will still include protocol and tcop stuff.

2. Compare SELECT ... WHERE values are constants
This will cause the clients to reuse the plan already made, so should
effectively remove planner, but not indexscan overheads from the test.

3. Change the test to look at Integers columns only for the WHERE
clause, so we can remove any thought it has anything to do with text
data, collation etc..

From those tests we should be able to narrow things down to planner,

executor or indexscan related.

Thanks,

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com

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

The weird thing is that after a couple of hours of poking at it with
oprofile and other sharp objects, I have no idea *why* it's slower.
oprofile shows just about the same relative percentages for all the
hot-spot functions in the backend.

Out of curiosity have you recompiled 8.2.5 recently? That is, are they
compiled with the same version of gcc?

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

"Guillaume Smet" <guillaume.smet@gmail.com> writes:

On Nov 22, 2007 6:44 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Are you examining only "trivial" queries? I've been able to identify a
couple of new planner hotspots that could explain some slowdown if the
planning time is material compared to the execution time. If you're
seeing a slowdown on queries that run for awhile, that would be
something else ...

Yes, I kept only queries with no join and a couple of where
conditions. As I explained previously, I can reproduce the behavior
with a single index scan on only one table (plan posted previously).
If anyone is interested I can post the content of this table (there's
nothing confidential in it so I should have the customer permission)
and a couple of instructions to reproduce the test case.

I don't think you need to --- the "read-only transaction" case built
into pgbench is probably an equivalent test. What it looks like to
me is that the EquivalenceClass mechanism has added a little bit of
overhead, which isn't actually buying much of anything in these
trivial cases. I'll look at whether it can be short-circuited.

regards, tom lane

Gregory Stark <stark@enterprisedb.com> writes:

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

The weird thing is that after a couple of hours of poking at it with
oprofile and other sharp objects, I have no idea *why* it's slower.
oprofile shows just about the same relative percentages for all the
hot-spot functions in the backend.

Out of curiosity have you recompiled 8.2.5 recently? That is, are they
compiled with the same version of gcc?

CVS tip of both branches, freshly compiled for this test.

regards, tom lane

On Nov 22, 2007 5:00 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Gregory Stark <stark@enterprisedb.com> writes:

Out of curiosity have you recompiled 8.2.5 recently? That is, are they
compiled with the same version of gcc?

CVS tip of both branches, freshly compiled for this test.

And in my case, a vanilla 8.2.5 compiled on the same box with the same compiler.

--
Guillaume