Re: Storing pg_stat_statements query texts externally, pg_stat_statements in core

Peter Geoghegan <pg(at)heroku(dot)com> writes:
> On Sat, Jan 25, 2014 at 2:20 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Well, it's fairly expensive to generate that text, in the case of a
>> large/complex statement. It's possible that continuing to hold the lock
>> is nonetheless the right thing to do because release+reacquire is also
>> expensive; but there is no proof of that AFAIK, and I believe that
>> release+reacquire is not likely to be expensive unless the lock is heavily
>> contended, which would be exactly the conditions under which keeping it
>> wouldn't be such a good idea anyway.

> My reason for only acquiring the shared lock once, and performing text
> normalization with it held was that in practice most query texts are
> not all that expensive to lex/normalize, and the cost of holding the
> lock for the vast majority of sessions (that won't experience
> contention) is nil.

Meh. This line of argument seems to reduce to "we don't need to worry
about performance of this code path because it won't be reached often".
I don't particularly buy that; it may be true in some usage patterns but
probably not all. And if you *do* buy it, it can be turned around to say
that we needn't worry about the costs of an extra locking cycle, anyway.

However, the only thing that is really going to settle this argument is
data, so here's a simple test case. I made a script that just consisted
of many repetitions of
\dd
SELECT pg_stat_statements_reset();
and ran it in psql while tracing the system with "perf". (\dd produces
a query that is middlingly complex, but certainly not a patch on those
I've seen produced by many real applications. The point of the reset
is to force us through the stats-entry-creation code path each time.)

The hits above 1%, in a non-assert-enabled backend:

13.92% 34576 postmaster [kernel.kallsyms] [k] 0xffffffff8103ed21
8.64% 21645 postmaster postgres [.] AllocSetAlloc
5.09% 12502 postmaster postgres [.] SearchCatCache
2.37% 6025 postmaster postgres [.] MemoryContextStrdup
2.22% 5624 postmaster libc-2.12.so [.] __strcmp_sse42
1.93% 4860 postmaster postgres [.] core_yylex
1.84% 4501 postmaster postgres [.] base_yyparse
1.83% 4601 postmaster postgres [.] ScanKeywordLookup
1.54% 3893 postmaster postgres [.] copyObject
1.54% 3849 postmaster postgres [.] MemoryContextAllocZeroAligned
1.30% 3237 postmaster postgres [.] expression_tree_walker
1.23% 3069 postmaster postgres [.] palloc
1.15% 2903 postmaster libc-2.12.so [.] memcpy
1.04% 2566 postmaster postgres [.] hash_uint32

So 3.76% of the entire runtime is going into core_yylex+ScanKeywordLookup,
and presumably half of that can be blamed on generate_normalized_query.
On the other hand, the earliest mention of lock-related functions in the
profile is

0.17% 411 postmaster postgres [.] LWLockAcquire

and LWLockRelease is down here:

0.11% 264 postmaster postgres [.] LWLockRelease

So on this example, the *total* cost of LWLocks, across the entire
backend, is something like 15% of the cost of generate_normalized_query.
This seems to me to be reasonably strong evidence that we should worry
about that cost, and that releasing/reacquiring the pgss LWLock is
trivial by comparison.

Of course, if the lock were contended then the locking cost would go
up substantially --- but that would also be a scenario in which it'd
be important not to hold the lock unnecessarily.

regards, tom lane