SELECT constant; takes 15x longer on 9.0?

Josh Berkus <josh@agliodbs.com> wrote:

SELECT 'DBD::Pg ping test';

In our test, which does 5801 of these pings during the test, they take
an average of 15x longer to execute on 9.0 as 8.4 ( 0.77ms vs. 0.05ms ).

Any clue why this would be?

Did you use the same configure options between them?
For example, --enable-debug or --enable-cassert.

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

On Tue, Apr 6, 2010 at 1:47 AM, Josh Berkus <josh@agliodbs.com> wrote:

Hackers,

Continuing the performance test:

DBD, like a number of monitoring systems, does "pings" on the database
which look like this:

SELECT 'DBD::Pg ping test';

In our test, which does 5801 of these pings during the test, they take
an average of 15x longer to execute on 9.0 as 8.4 ( 0.77ms vs. 0.05ms ).

did your pings change? on my machine the query ';' completes in about
0.05ms but any select takes 0.19 - 0.25ms.

0.77 is awfully high -- there has to be an explanation.

merlin

Josh Berkus <josh@agliodbs.com> writes:

Continuing the performance test:

DBD, like a number of monitoring systems, does "pings" on the database
which look like this:

SELECT 'DBD::Pg ping test';

In our test, which does 5801 of these pings during the test, they take
an average of 15x longer to execute on 9.0 as 8.4 ( 0.77ms vs. 0.05ms ).

There's something wrong with your test setup. Or, if you'd like me to
think that there isn't, provide a self-contained test case. I ran a
small program that does

for (i = 0; i < 10000; i++)
{
res = PQexec(conn, "SELECT 'DBD::Pg ping test'");
PQclear(res);
}

and I only see a few percent difference between HEAD and 8.4.3,
on two different machines. (It does appear that HEAD is a bit slower
for this, which might or might not be something to worry about.)

regards, tom lane

On Apr 6, 2010, at 2:32 AM, Takahiro Itagaki wrote:

In our test, which does 5801 of these pings during the test, they take
an average of 15x longer to execute on 9.0 as 8.4 ( 0.77ms vs. 0.05ms ).

Any clue why this would be?

Did you use the same configure options between them?

Yes.

For example, --enable-debug or --enable-cassert.

No.

David

On Apr 6, 2010, at 6:07 AM, Merlin Moncure wrote:

In our test, which does 5801 of these pings during the test, they take
an average of 15x longer to execute on 9.0 as 8.4 ( 0.77ms vs. 0.05ms ).

did your pings change?

No.

David

On Apr 6, 2010, at 7:28 AM, Tom Lane wrote:

There's something wrong with your test setup. Or, if you'd like me to
think that there isn't, provide a self-contained test case. I ran a
small program that does

for (i = 0; i < 10000; i++)
{
res = PQexec(conn, "SELECT 'DBD::Pg ping test'");
PQclear(res);
}

and I only see a few percent difference between HEAD and 8.4.3,
on two different machines. (It does appear that HEAD is a bit slower
for this, which might or might not be something to worry about.)

I'm going to see if I can replicate it on a second box today.

Best,

David

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

Josh Berkus <josh@agliodbs.com> writes:

Continuing the performance test:

DBD, like a number of monitoring systems, does "pings" on the database
which look like this:

SELECT 'DBD::Pg ping test';

In our test, which does 5801 of these pings during the test, they take
an average of 15x longer to execute on 9.0 as 8.4 ( 0.77ms vs. 0.05ms ).

There's something wrong with your test setup. Or, if you'd like me to
think that there isn't, provide a self-contained test case.

I did some comparisons and oprofile work against this test case:

for (i = 0; i < [lots]; i++)
{
res = PQexec(conn, "SELECT 'DBD::Pg ping test'");
PQclear(res);
}

In assert-enabled builds, HEAD seems about 10% slower than 8.4 branch
tip, but as far as I can tell this is all debug overhead associated with
a slightly larger number of catcache entries that are present
immediately after startup. In non-assert-enabled builds there's a
difference of a percent or so, which appears to be due to increased
lexer overhead; oprofile shows these top routines in HEAD:

samples % image name symbol name
49787 7.0533 postgres base_yyparse
35510 5.0307 postgres AllocSetAlloc
29135 4.1275 postgres hash_search_with_hash_value
24541 3.4767 postgres core_yylex
15231 2.1578 postgres PostgresMain
14710 2.0840 postgres hash_seq_search
14340 2.0315 postgres LockReleaseAll
13878 1.9661 postgres MemoryContextAllocZeroAligned
10047 1.4234 postgres ScanKeywordLookup
9866 1.3977 postgres LWLockAcquire
9434 1.3365 postgres LockAcquireExtended
8347 1.1825 postgres hash_any
7954 1.1268 postgres ExecInitExpr
7326 1.0379 postgres MemoryContextAlloc
7243 1.0261 postgres AllocSetFree
6787 0.9615 postgres MemoryContextAllocZero
6501 0.9210 postgres internal_flush
5956 0.8438 postgres LWLockRelease

versus these in 8.4:

samples % image name symbol name
51795 7.2589 postgres AllocSetAlloc
37742 5.2894 postgres base_yyparse
32558 4.5629 postgres hash_search_with_hash_value
17250 2.4175 postgres hash_seq_search
14933 2.0928 postgres AllocSetFree
14902 2.0885 postgres MemoryContextAllocZeroAligned
13219 1.8526 postgres LockReleaseAll
12974 1.8183 postgres SearchCatCache
10885 1.5255 postgres PostgresMain
10592 1.4844 postgres ResourceOwnerReleaseInternal
10462 1.4662 postgres base_yylex
10007 1.4025 postgres hash_any
9553 1.3388 postgres MemoryContextAllocZero
8758 1.2274 postgres LWLockAcquire
8237 1.1544 postgres exec_simple_query
7410 1.0385 postgres LockAcquire
7315 1.0252 postgres MemoryContextCreate
7262 1.0177 postgres MemoryContextAlloc
7220 1.0119 postgres LWLockRelease

The only thing that seems to have changed by more than the noise level
is that core_yylex (formerly base_yylex) got slower. I suppose this is
due to changing over to a re-entrant scanner. The flex manual claims
that %option reentrant doesn't cost any performance --- so I suspect
that what we are seeing here is additional per-call overhead and not a
slowdown that would be important for lexing long queries. I don't think
there's anything to worry about there for nontrivial queries.

I also tried reconnecting to the server for each query. In that
situation HEAD seems to be about 10% slower than 8.4 even without
asserts, which might be an artifact of the changes to eliminate the
"flat" authentication files. I'm not particularly concerned about that
either, since if you're looking for performance, reconnecting to issue a
trivial query is not what you should be doing.

So I'm not sure where your 15x is coming from, but I don't see it.

regards, tom lane

On Tue, Apr 6, 2010 at 12:08 PM, David E. Wheeler <david@kineticode.com> wrote:

On Apr 6, 2010, at 2:32 AM, Takahiro Itagaki wrote:

In our test, which does 5801 of these pings during the test, they take
an average of 15x longer to execute on 9.0 as 8.4 ( 0.77ms vs. 0.05ms ).

Any clue why this would be?

Did you use the same configure options between them?

Yes.

For example, --enable-debug or --enable-cassert.

hmm. ssl? (I don't see any interesting difference in time either
btw). can you log in w/psql and confirm the difference there w/timing
switch?

merlin

On Apr 6, 2010, at 9:08 AM, David E. Wheeler wrote:

For example, --enable-debug or --enable-cassert.

No.

Oh FFS! I was looking at the wrong build script. It was indeed built with --enable-cassert --enable-debug. Grrr.

Well, that's likely the culprit right there. I'm rebuilding without those now and hopefully my tests will be back down to 45s.

Many apologies for the noise and wasted time.

Best,

David

On Apr 6, 2010, at 10:17 AM, Tom Lane wrote:

So I'm not sure where your 15x is coming from, but I don't see it.

By stupidly having configured with --enable-cassert --enable-debug without realizing it. I've just rebuilt without them and run the tests again using the default postgresql.conf and I'm back down to 57s and 46s over two runs.

Sorry for the wasted time. I knew there had to a be a simple answer.

Best,

David

On Apr 6, 2010, at 10:52 AM, David E. Wheeler wrote:

Oh FFS! I was looking at the wrong build script. It was indeed built with --enable-cassert --enable-debug. Grrr.

Well, that's likely the culprit right there. I'm rebuilding without those now and hopefully my tests will be back down to 45s.

Many apologies for the noise and wasted time.

And just to close out this thread, I rebuilt without `--enable-cassert --enable-debug` and now the tests pass in 57s and 46s over two runs, just like on 8.4 (though with just the default postgresql.conf, unlike my 8.4 install).

Phew! Knew it had to be somehting stup^H^H^Himple.

Best,

David

"David E. Wheeler" <david@kineticode.com> writes:

On Apr 6, 2010, at 10:17 AM, Tom Lane wrote:

So I'm not sure where your 15x is coming from, but I don't see it.

By stupidly having configured with --enable-cassert --enable-debug without realizing it. I've just rebuilt without them and run the tests again using the default postgresql.conf and I'm back down to 57s and 46s over two runs.

Huh. I'm still curious, because in my test the overhead of those
options seemed to be about 3x. So there's still something considerably
different between what you did and what I did.

Are you testing a separate connection per ping query? I think I
neglected to compare that case with and without assert overhead.

regards, tom lane

David E. Wheeler wrote:

By stupidly having configured with --enable-cassert --enable-debug without realizing it. I've just rebuilt without them and run the tests again using the default postgresql.conf and I'm back down to 57s and 46s over two runs.

Every performance test I run, regardless of where the binaries come from
or how I thought they were built, starts like this:

postgres=# show debug_assertions;
debug_assertions
------------------
off
(1 row)

It's a really good habit to get into, or even enforce in your testing
script if practical.

--
Greg Smith 2ndQuadrant US Baltimore, MD
PostgreSQL Training, Services and Support
greg@2ndQuadrant.com www.2ndQuadrant.us

On Apr 6, 2010, at 11:15 AM, Tom Lane wrote:

By stupidly having configured with --enable-cassert --enable-debug without realizing it. I've just rebuilt without them and run the tests again using the default postgresql.conf and I'm back down to 57s and 46s over two runs.

Huh. I'm still curious, because in my test the overhead of those
options seemed to be about 3x. So there's still something considerably
different between what you did and what I did.

Are you doing this on a Mac?

Are you testing a separate connection per ping query? I think I
neglected to compare that case with and without assert overhead.

No, should be one connection for the entire test suite.

Best,

David

"David E. Wheeler" <david@kineticode.com> writes:

On Apr 6, 2010, at 11:15 AM, Tom Lane wrote:

Huh. I'm still curious, because in my test the overhead of those
options seemed to be about 3x. So there's still something considerably
different between what you did and what I did.

Are you doing this on a Mac?

I hadn't, but since you mention it: 100000 iterations take about 7.5sec
with non-assert CVS HEAD and 15sec with asserts, on a 2008 Macbook Pro.
Color me still confused.

regards, tom lane

On Apr 6, 2010, at 12:50 PM, Tom Lane wrote:

I hadn't, but since you mention it: 100000 iterations take about 7.5sec
with non-assert CVS HEAD and 15sec with asserts, on a 2008 Macbook Pro.
Color me still confused.

Well it's not just pings that the bricolage tests were running, of course.

Josh, might you have got the numbers wrong when trying to match up query runtimes to their queries in the CSVLOG output? That might explain it. Most of the queries were BINDs.

Best,

David

2010/4/6 Tom Lane <tgl@sss.pgh.pa.us>:

"David E. Wheeler" <david@kineticode.com> writes:

On Apr 6, 2010, at 11:15 AM, Tom Lane wrote:

Huh.  I'm still curious, because in my test the overhead of those
options seemed to be about 3x.  So there's still something considerably
different between what you did and what I did.

Are you doing this on a Mac?

I hadn't, but since you mention it: 100000 iterations take about 7.5sec
with non-assert CVS HEAD and 15sec with asserts, on a 2008 Macbook Pro.
Color me still confused.

it is little bit offtopic. Can we add info about assertation to
version() output?

like

postgres=# select version();
version

────────────────────────────────────────────────────────────────────────────────
───────────────────────────────
PostgreSQL 9.0alpha4 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 4.4.3 2010
0127 (Red Hat 4.4.3-4), 32-bit >>> with enabled assertation <<<<
(1 row)

Regards
Pavel Stehule

Pavel Stehule <pavel.stehule@gmail.com> writes:

it is little bit offtopic. Can we add info about assertation to
version() output?

Greg has the right idea: show debug_assertions.

regards, tom lane

Josh, might you have got the numbers wrong when trying to match up query runtimes to their queries in the CSVLOG output? That might explain it. Most of the queries were BINDs.

I swept up some DEALLOCATEs by acccident, but those don't appreciably
affect the final numbers.

--
-- Josh Berkus
PostgreSQL Experts Inc.
http://www.pgexperts.com