From: Andrew Dunstan <andrew@dunslane.net>
To: Jeff Janes <jeff.janes@gmail.com>
Cc: Josh Berkus <josh@agliodbs.com>
Cc: Amit Kapila <amit.kapila@huawei.com>
Cc: pgsql-performance@postgresql.org <pgsql-performance@postgresql.org>
Subject: Re: Performance bug in prepared statement binding in 9.2?
Date: Mon, 09 Sep 2013 20:38:09 -0400
Message-ID: <522E69F1.8070203@dunslane.net> (raw)
In-Reply-To: <CAMkU=1wn3npjTjEkC8rYMgmoKXYoAgfxosT_Q3v_=wTfriPKdA@mail.gmail.com>
References: <51A699E6.3000008@agliodbs.com>
<WM!f3d412a8ff9fb2a52f4cfd0f48c225b6122ba5bf1e1523173b5dbc63db143b9cab09ac3f5518a12a19d2507538472d98!@asav-1.01.com>
<51A79512.4020200@agliodbs.com>
<WM!c84cb8479a8b2ec21d1061c951095da00bc52608e9822124f1438b9de432ec7ebedaf25085801b67d581eed6d368c344!@asav-2.01.com>
<51FAA1B8.6040809@agliodbs.com>
<CAMkU=1wn3npjTjEkC8rYMgmoKXYoAgfxosT_Q3v_=wTfriPKdA@mail.gmail.com>
List-Unsubscribe: <mailto:majordomo@postgresql.org?body=unsub%20pgsql-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
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: andrew@dunslane.net, jeff.janes@gmail.com, josh@agliodbs.com, amit.kapila@huawei.com
Subject: Re: Performance bug in prepared statement binding in 9.2?
In-Reply-To: <522E69F1.8070203@dunslane.net>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox