Re: Performance bug in prepared statement binding in 9.2?

On 08/01/2013 03:20 PM, Jeff Janes wrote:
> On Thu, Aug 1, 2013 at 10:58 AM, Josh Berkus <josh(at)agliodbs(dot)com> wrote:
>> Amit, All:
>>
>> So we just retested this on 9.3b2. The performance is the same as 9.1
>> and 9.2; that is, progressively worse as the test cycles go on, and
>> unacceptably slow compared to 8.4.
>>
>> Some issue introduced in 9.1 is causing BINDs to get progressively
>> slower as the PARSEs BINDs get run repeatedly. Per earlier on this
>> thread, that can bloat to 200X time required for a BIND, and it's
>> definitely PostgreSQL-side.
>>
>> I'm trying to produce a test case which doesn't involve the user's
>> application. However, hints on other things to analyze would be keen.
> Does it seem to be all CPU time (it is hard to imagine what else it
> would be, but...)
>
> Could you use oprofile or perf or gprof to get a profile of the
> backend during a run? That should quickly narrow it down to which C
> function has the problem.
>
> Did you test 9.0 as well?

This has been tested back to 9.0. What we have found is that the problem
disappears if the database has come in via dump/restore, but is present
if it is the result of pg_upgrade. There are some long-running
transactions also running alongside this - we are currently planning a
test where those are not present. We're also looking at constructing a
self-contained test case.

Here is some perf output from the bad case:

+ 14.67% postgres [.] heap_hot_search_buffer
+ 11.45% postgres [.] LWLockAcquire
+ 8.39% postgres [.] LWLockRelease
+ 6.60% postgres [.] _bt_checkkeys
+ 6.39% postgres [.] PinBuffer
+ 5.96% postgres [.] hash_search_with_hash_value
+ 5.43% postgres [.] hash_any
+ 5.14% postgres [.] UnpinBuffer
+ 3.43% postgres [.] ReadBuffer_common
+ 2.34% postgres [.] index_fetch_heap
+ 2.04% postgres [.] heap_page_prune_opt
+ 2.00% libc-2.15.so [.] 0x8041b
+ 1.94% postgres [.] _bt_next
+ 1.83% postgres [.] btgettuple
+ 1.76% postgres [.] index_getnext_tid
+ 1.70% postgres [.] LockBuffer
+ 1.54% postgres [.] ReadBufferExtended
+ 1.25% postgres [.] FunctionCall2Coll
+ 1.14% postgres [.] HeapTupleSatisfiesNow
+ 1.09% postgres [.] ReleaseAndReadBuffer
+ 0.94% postgres [.] ResourceOwnerForgetBuffer
+ 0.81% postgres [.] _bt_saveitem
+ 0.80% postgres [.] _bt_readpage
+ 0.79% [kernel.kallsyms] [k] 0xffffffff81170861
+ 0.64% postgres [.] CheckForSerializableConflictOut
+ 0.60% postgres [.] ResourceOwnerEnlargeBuffers
+ 0.59% postgres [.] BufTableLookup

and here is the good case:

+ 9.54% libc-2.15.so [.] 0x15eb1f
+ 7.31% [kernel.kallsyms] [k] 0xffffffff8117924b
+ 5.65% postgres [.] AllocSetAlloc
+ 3.57% postgres [.] SearchCatCache
+ 2.67% postgres [.] hash_search_with_hash_value
+ 1.69% postgres [.] base_yyparse
+ 1.49% libc-2.15.so [.] vfprintf
+ 1.34% postgres [.] MemoryContextAllocZeroAligned
+ 1.34% postgres [.] XLogInsert
+ 1.24% postgres [.] copyObject
+ 1.10% postgres [.] palloc
+ 1.09% postgres [.] _bt_compare
+ 1.04% postgres [.] core_yylex
+ 0.96% postgres [.] _bt_checkkeys
+ 0.95% postgres [.] expression_tree_walker
+ 0.88% postgres [.] ScanKeywordLookup
+ 0.87% postgres [.] pg_encoding_mbcliplen
+ 0.86% postgres [.] LWLockAcquire
+ 0.72% postgres [.] nocachegetattr
+ 0.67% postgres [.] FunctionCall2Coll
+ 0.63% postgres [.] fmgr_info_cxt_security
+ 0.62% postgres [.] hash_any
+ 0.62% postgres [.] ExecInitExpr
+ 0.58% postgres [.] hash_uint32
+ 0.55% postgres [.] PostgresMain
+ 0.55% postgres [.] LWLockRelease
+ 0.54% postgres [.] lappend
+ 0.52% postgres [.] slot_deform_tuple
+ 0.50% postgres [.] PinBuffer
+ 0.48% postgres [.] AllocSetFree
+ 0.46% postgres [.] check_stack_depth
+ 0.44% postgres [.] DirectFunctionCall1Coll
+ 0.43% postgres [.] ExecScanHashBucket
+ 0.36% postgres [.] deconstruct_array
+ 0.36% postgres [.] CatalogCacheComputeHashValue
+ 0.35% postgres [.] pfree
+ 0.33% libc-2.15.so [.] _IO_default_xsputn
+ 0.32% libc-2.15.so [.] malloc
+ 0.32% postgres [.] TupleDescInitEntry
+ 0.30% postgres [.] new_tail_cell.isra.2
+ 0.30% libm-2.15.so [.] 0x5898
+ 0.30% postgres [.] LockAcquireExtended
+ 0.30% postgres [.] _bt_first
+ 0.29% postgres [.] add_paths_to_joinrel
+ 0.28% postgres [.] MemoryContextCreate
+ 0.28% postgres [.] appendBinaryStringInfo
+ 0.28% postgres [.] MemoryContextStrdup
+ 0.27% postgres [.] heap_hot_search_buffer
+ 0.27% postgres [.] GetSnapshotData
+ 0.26% postgres [.] hash_search
+ 0.26% postgres [.] heap_getsysattr
+ 0.26% [vdso] [.] 0x7fff681ff70c
+ 0.25% postgres [.] compare_scalars
+ 0.25% postgres [.] pg_verify_mbstr_len

cheers

andrew