Received: from localhost (maia-1.hub.org [200.46.204.191]) by postgresql.org (Postfix) with ESMTP id 8BA769FC0A6 for ; Fri, 20 Jul 2007 16:46:38 -0300 (ADT) Received: from postgresql.org ([200.46.204.71]) by localhost (mx1.hub.org [200.46.204.191]) (amavisd-maia, port 10024) with ESMTP id 52714-02 for ; Fri, 20 Jul 2007 16:46:34 -0300 (ADT) X-Greylist: from auto-whitelisted by SQLgrey-1.7.5 Received: from brmea-mail-1.sun.com (brmea-mail-1.Sun.COM [192.18.98.31]) by postgresql.org (Postfix) with ESMTP id EADB49FC132 for ; Fri, 20 Jul 2007 16:46:33 -0300 (ADT) Received: from fe-amer-03.sun.com ([192.18.108.177]) by brmea-mail-1.sun.com (8.13.6+Sun/8.12.9) with ESMTP id l6KJkWVe013876 for ; Fri, 20 Jul 2007 19:46:32 GMT Received: from conversion-daemon.mail-amer.sun.com by mail-amer.sun.com (Sun Java System Messaging Server 6.2-6.01 (built Apr 3 2006)) id <0JLH00801TG29A00@mail-amer.sun.com> (original mail from J.K.Shah@Sun.COM) for pgsql-performance@postgresql.org; Fri, 20 Jul 2007 13:46:32 -0600 (MDT) Received: from [129.148.9.17] by mail-amer.sun.com (Sun Java System Messaging Server 6.2-6.01 (built Apr 3 2006)) with ESMTPSA id <0JLH00I37TLIC6Y0@mail-amer.sun.com>; Fri, 20 Jul 2007 13:46:32 -0600 (MDT) Date: Fri, 20 Jul 2007 15:46:30 -0400 From: "Jignesh K. Shah" Subject: Re: User concurrency thresholding: where do I look? In-reply-to: <12445.1184958793@sss.pgh.pa.us> To: Tom Lane Cc: Josh Berkus , pgsql-performance@postgresql.org, Alvaro Herrera Message-id: <46A11116.5030905@sun.com> Organization: Sun Microsystems MIME-version: 1.0 Content-type: text/plain; format=flowed; charset=ISO-8859-1 Content-transfer-encoding: 7BIT References: <200707190828.59088.josh@agliodbs.com> <200707191819.13899.josh@agliodbs.com> <15685.1184895926@sss.pgh.pa.us> <200707192138.39679.josh@agliodbs.com> <46A0FA31.2080208@sun.com> <12002.1184955831@sss.pgh.pa.us> <46A1055F.9010304@sun.com> <12445.1184958793@sss.pgh.pa.us> User-Agent: Thunderbird 1.5.0.8 (X11/20061110) X-Virus-Scanned: Maia Mailguard 1.0.1 X-Archive-Number: 200707/273 X-Sequence-Number: 25957 Tom Lane wrote: > "Jignesh K. Shah" writes: >> Yes I did see increase in context switches and CPU migrations at that >> point using mpstat. > > So follow that up --- try to determine which lock is being contended > for. There's some very crude code in the sources that you can enable > with -DLWLOCK_STATS, but probably DTrace would be a better tool. > > regards, tom lane Using plockstat -A -s 5 -p $pid on bgwriter: doesnt report anything On one of the many connections: This one is hard to read easily By default, plockstat monitors all lock con- tention events, gathers frequency and timing data about those events, and displays the data in decreasing frequency order, so that the most common events appear first. ^Cbash-3.00# plockstat -A -s 5 -p 6401 ^C Mutex hold ------------------------------------------------------------------------------- Count nsec Lock Caller 59 186888 0x10059e280 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 16384 | | 1 libumem.so.1`process_free+0x12c 32768 |@@@@@ | 14 postgres`AllocSetDelete+0x98 65536 |@@ | 5 postgres`MemoryContextDelete+0x78 131072 | | 0 postgres`CommitTransaction+0x240 262144 |@@@@@@@@@@@@@@@ | 39 ------------------------------------------------------------------------------- Count nsec Lock Caller 530 12226 0x10059e280 libumem.so.1`umem_cache_alloc+0x200 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@ | 338 libumem.so.1`umem_cache_alloc+0x200 8192 |@ | 24 libumem.so.1`umem_alloc+0x5c 16384 |@ | 37 libumem.so.1`malloc+0x40 32768 |@@@@@ | 131 postgres`AllocSetAlloc+0x1c4 ------------------------------------------------------------------------------- Count nsec Lock Caller 324 10214 0x100578030 libumem.so.1`vmem_xfree+0x164 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@ | 192 libumem.so.1`vmem_xfree+0x164 8192 |@@@@ | 56 libumem.so.1`process_free+0x12c 16384 |@ | 26 postgres`AllocSetDelete+0x98 32768 |@@@ | 50 postgres`MemoryContextDelete+0x78 ------------------------------------------------------------------------------- Count nsec Lock Caller 161 13585 0x10059e280 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@ | 118 libumem.so.1`process_free+0x12c 8192 | | 4 postgres`AllocSetDelete+0x98 16384 |@ | 10 postgres`MemoryContextDelete+0x78 32768 |@@@ | 24 postgres`PortalDrop+0x160 65536 | | 3 131072 | | 0 262144 | | 2 ------------------------------------------------------------------------------- Count nsec Lock Caller 326 6081 libumem.so.1`vmem0+0xc38 libumem.so.1`vmem_xalloc+0x630 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@ | 170 libumem.so.1`vmem_xalloc+0x630 8192 |@@@@@@@@@@@ | 155 libumem.so.1`vmem_alloc+0x1f8 16384 | | 1 libumem.so.1`vmem_xalloc+0x524 libumem.so.1`vmem_alloc+0x1f8 ------------------------------------------------------------------------------- Count nsec Lock Caller 326 5867 libumem.so.1`vmem0+0x30 libumem.so.1`vmem_alloc+0x248 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@ | 185 libumem.so.1`vmem_alloc+0x248 8192 |@@@@@@@@@@ | 141 libumem.so.1`vmem_sbrk_alloc+0x30 libumem.so.1`vmem_xalloc+0x524 libumem.so.1`vmem_alloc+0x1f8 ------------------------------------------------------------------------------- Count nsec Lock Caller 318 5873 0x100578030 libumem.so.1`vmem_alloc+0x1d0 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@ | 228 libumem.so.1`vmem_alloc+0x1d0 8192 |@@@@@ | 78 libumem.so.1`umem_alloc+0xec 16384 | | 6 libumem.so.1`malloc+0x40 32768 | | 6 postgres`AllocSetAlloc+0x1c4 ------------------------------------------------------------------------------- Count nsec Lock Caller 326 5591 0x100578030 libumem.so.1`vmem_xalloc+0x630 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@ | 213 libumem.so.1`vmem_xalloc+0x630 8192 |@@@@@@@@ | 112 libumem.so.1`vmem_alloc+0x1f8 16384 | | 0 libumem.so.1`umem_alloc+0xec 32768 | | 1 libumem.so.1`malloc+0x40 ------------------------------------------------------------------------------- Count nsec Lock Caller 324 5208 libumem.so.1`vmem0+0xc38 libumem.so.1`vmem_xfree+0x164 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@ | 236 libumem.so.1`vmem_xfree+0x164 8192 |@@@@@@ | 88 libumem.so.1`process_free+0x12c postgres`AllocSetDelete+0x98 postgres`MemoryContextDelete+0x78 ------------------------------------------------------------------------------- Count nsec Lock Caller 326 4108 libumem.so.1`vmem0+0xc38 libumem.so.1`vmem_alloc+0x1d0 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@ | 325 libumem.so.1`vmem_alloc+0x1d0 8192 | | 1 libumem.so.1`vmem_xalloc+0x524 libumem.so.1`vmem_alloc+0x1f8 libumem.so.1`umem_alloc+0xec ------------------------------------------------------------------------------- Count nsec Lock Caller 326 4108 0x100578030 libumem.so.1`vmem_xalloc+0x50c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@ | 325 libumem.so.1`vmem_xalloc+0x50c 8192 | | 1 libumem.so.1`vmem_alloc+0x1f8 libumem.so.1`umem_alloc+0xec libumem.so.1`malloc+0x40 ------------------------------------------------------------------------------- Count nsec Lock Caller 326 4096 libumem.so.1`vmem0+0xc38 libumem.so.1`vmem_xalloc+0x50c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@| 326 libumem.so.1`vmem_xalloc+0x50c libumem.so.1`vmem_alloc+0x1f8 libumem.so.1`vmem_xalloc+0x524 libumem.so.1`vmem_alloc+0x1f8 ------------------------------------------------------------------------------- Count nsec Lock Caller 240 5444 libumem.so.1`vmem0+0x30 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@ | 167 libumem.so.1`process_free+0x12c 8192 |@@@@@@@ | 72 postgres`AllocSetDelete+0x98 16384 | | 0 postgres`MemoryContextDelete+0x78 32768 | | 1 postgres`ExecutorEnd+0x40 ------------------------------------------------------------------------------- Count nsec Lock Caller 123 9057 0x10059e1d0 libumem.so.1`umem_depot_alloc+0xb8 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@ | 60 libumem.so.1`umem_depot_alloc+0xb8 8192 |@@@@ | 24 libumem.so.1`umem_cache_free+0xc4 16384 |@@@@@@@ | 37 libumem.so.1`process_free+0x12c 32768 | | 2 postgres`AllocSetDelete+0x98 ------------------------------------------------------------------------------- Count nsec Lock Caller 200 4935 0x10059e280 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@ | 185 libumem.so.1`process_free+0x12c 8192 | | 4 postgres`AllocSetDelete+0x98 16384 |@ | 10 postgres`MemoryContextDelete+0x78 32768 | | 1 postgres`ExecutorEnd+0x40 ------------------------------------------------------------------------------- Count nsec Lock Caller 164 5219 0x100595700 libumem.so.1`umem_cache_alloc+0x200 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@ | 121 libumem.so.1`umem_cache_alloc+0x200 8192 |@@@@@@ | 42 libumem.so.1`umem_alloc+0x5c 16384 | | 1 libumem.so.1`malloc+0x40 postgres`AllocSetAlloc+0x1c4 ------------------------------------------------------------------------------- Count nsec Lock Caller 122 6748 0x10059e1d0 libumem.so.1`umem_depot_alloc+0xb8 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@ | 43 libumem.so.1`umem_depot_alloc+0xb8 8192 |@@@@@@@@@@@@@@@ | 79 libumem.so.1`umem_cache_alloc+0xa0 libumem.so.1`umem_alloc+0x5c libumem.so.1`malloc+0x40 ------------------------------------------------------------------------------- Count nsec Lock Caller 163 4146 0x100595700 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@ | 161 libumem.so.1`process_free+0x12c 8192 | | 2 postgres`AllocSetDelete+0x98 postgres`MemoryContextDelete+0x78 postgres`PortalDrop+0x160 ------------------------------------------------------------------------------- Count nsec Lock Caller 50 12615 0x10059e280 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@ | 28 libumem.so.1`process_free+0x12c 8192 |@ | 3 postgres`AllocSetDelete+0x98 16384 |@@@ | 8 postgres`MemoryContextDelete+0x78 32768 |@@@@@ | 11 postgres`FreeExecutorState+0x6c ------------------------------------------------------------------------------- Count nsec Lock Caller 123 4096 0x10059e1d0 libumem.so.1`umem_cache_free+0xec nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@| 123 libumem.so.1`umem_cache_free+0xec libumem.so.1`process_free+0x12c postgres`AllocSetDelete+0x98 postgres`MemoryContextDelete+0x78 ------------------------------------------------------------------------------- Count nsec Lock Caller 122 4096 0x10059e1d0 libumem.so.1`umem_cache_alloc+0xc4 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@| 122 libumem.so.1`umem_cache_alloc+0xc4 libumem.so.1`umem_alloc+0x5c libumem.so.1`malloc+0x40 postgres`AllocSetAlloc+0x1c4 ------------------------------------------------------------------------------- Count nsec Lock Caller 37 7970 libumem.so.1`vmem0+0x30 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@ | 2 libumem.so.1`process_free+0x12c 8192 |@@@@@@@@@@@@@@@@@@@@@@ | 35 postgres`AllocSetDelete+0x98 postgres`MemoryContextDelete+0x78 postgres`exec_parse_message+0x130 ------------------------------------------------------------------------------- Count nsec Lock Caller 37 5867 0x10059e280 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@ | 33 libumem.so.1`process_free+0x12c 8192 |@ | 2 postgres`AllocSetDelete+0x98 16384 | | 0 postgres`MemoryContextDelete+0x78 32768 |@ | 2 postgres`exec_parse_message+0x130 ------------------------------------------------------------------------------- Count nsec Lock Caller 39 4516 libumem.so.1`vmem0+0x30 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@ | 35 libumem.so.1`process_free+0x12c 8192 |@@ | 4 postgres`AllocSetDelete+0x98 postgres`MemoryContextDelete+0x78 postgres`PortalDrop+0x160 ------------------------------------------------------------------------------- Count nsec Lock Caller 37 4428 0x10058b700 libumem.so.1`umem_cache_alloc+0x200 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@ | 34 libumem.so.1`umem_cache_alloc+0x200 8192 |@ | 3 libumem.so.1`umem_alloc+0x5c libumem.so.1`malloc+0x40 postgres`base_yy_scan_buffer+0x38 ------------------------------------------------------------------------------- Count nsec Lock Caller 37 4206 0x10058b700 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@ | 36 libumem.so.1`process_free+0x12c 8192 | | 1 postgres`scanner_finish+0x50 postgres`raw_parser+0x3c postgres`pg_parse_query+0x54 ------------------------------------------------------------------------------- Count nsec Lock Caller 11 10426 0x10059e280 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@ | 6 libumem.so.1`process_free+0x12c 8192 |@@@@@@ | 3 postgres`AllocSetDelete+0x98 16384 | | 0 postgres`MemoryContextDelete+0x78 32768 |@@@@ | 2 postgres`ExecEndAgg+0x68 ------------------------------------------------------------------------------- Count nsec Lock Caller 8 5120 libumem.so.1`vmem0+0x30 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@ | 6 libumem.so.1`process_free+0x12c 8192 |@@@@@@ | 2 postgres`AllocSetDelete+0x98 postgres`MemoryContextDelete+0x78 postgres`ExecEndSort+0x24 ------------------------------------------------------------------------------- Count nsec Lock Caller 8 4096 0x10059e280 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@| 8 libumem.so.1`process_free+0x12c postgres`AllocSetDelete+0x98 postgres`MemoryContextDelete+0x78 postgres`ExecEndSort+0x24 ------------------------------------------------------------------------------- Count nsec Lock Caller 8 4096 0x100578030 libumem.so.1`vmem_alloc+0x1d0 nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@| 8 libumem.so.1`vmem_alloc+0x1d0 libumem.so.1`umem_alloc+0xec libumem.so.1`malloc+0x40 postgres`AllocSetAlloc+0x314 ------------------------------------------------------------------------------- Count nsec Lock Caller 3 4096 0x10059e280 libumem.so.1`process_free+0x12c nsec ---- Time Distribution --- count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@| 3 libumem.so.1`process_free+0x12c postgres`AllocSetDelete+0x98 postgres`MemoryContextDelete+0x78 postgres`tbm_free+0x10 bash-3.00#