Re: Performance bug in prepared statement binding in 9.2? - Mailing list pgsql-performance

On 08/01/2013 03:20 PM, Jeff Janes wrote:
> On Thu, Aug 1, 2013 at 10:58 AM, Josh Berkus <josh@agliodbs.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