Skip site navigation (1) Skip section navigation (2)

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 (view raw or flat)
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

Responses

pgsql-performance by date

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

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group