On 08/01/2013 03:20 PM, Jeff Janes wrote:
On Thu, Aug 1, 2013 at 10:58 AM, Josh Berkus <josh@xxxxxxxxxxxx> 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
--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
