Quick Links

Re: User concurrency thresholding: where do I look?

From:	"Jignesh K(dot) Shah" <J(dot)K(dot)Shah(at)Sun(dot)COM>
To:	Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc:	Josh Berkus <josh(at)agliodbs(dot)com>, pgsql-performance(at)postgresql(dot)org, Alvaro Herrera <alvherre(at)commandprompt(dot)com>
Subject:	Re: User concurrency thresholding: where do I look?
Date:	2007-07-20 19:46:30
Message-ID:	46A11116.5030905@sun.com
Views:	Raw Message \| Whole Thread \| Download mbox \| Resend email
Thread:
Lists:	pgsql-performance

Tom Lane wrote:
> "Jignesh K. Shah" <J(dot)K(dot)Shah(at)Sun(dot)COM> 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#

In response to

Re: User concurrency thresholding: where do I look? at 2007-07-20 19:13:13 from Tom Lane

Responses

Re: User concurrency thresholding: where do I look? at 2007-07-20 20:16:01 from Tom Lane

Browse pgsql-performance by date

	From	Date	Subject
Next Message	Tom Lane	2007-07-20 20:16:01	Re: User concurrency thresholding: where do I look?
Previous Message	Tom Lane	2007-07-20 19:13:13	Re: User concurrency thresholding: where do I look?