Tom Lane wrote:
"Jignesh K. Shah" <[EMAIL PROTECTED]> 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#
---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at
http://www.postgresql.org/about/donate
