Re: SELECT constant; takes 15x longer on 9.0?

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> writes:
> Josh Berkus <josh(at)agliodbs(dot)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