slow dropping of tables, DropRelFileNodeBuffers, tas

Hello,

I was running some tests on PG9.2beta where I'm creating and dropping 
large number of tables (~ 20000).

And I noticed that table dropping was extremely slow -- e.g. like half a 
second per table.

I tried to move the table dropping into bigger transactions (100 per one 
transaction) (increasing in the same time max_locks_per_trans to 128).
And still, the commits took ~ 50-60 seconds.

I tried to oprofile it, and I saw that 99% is spend on 
DropRelFileNodeBuffers, and when compiled with symbols (CFLAGS=-g)
I saw that actually most of the time is spend in tas() function, see 
below:

PU: Intel Architectural Perfmon, speed 1862 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        linenr info                 symbol name
-------------------------------------------------------------------------------
831665   86.6756  s_lock.h:204                tas  831665   100.000  s_lock.h:204                tas [self]
-------------------------------------------------------------------------------
122573   12.7745  bufmgr.c:2048               DropRelFileNodeBuffers  122573   100.000  bufmgr.c:2048
DropRelFileNodeBuffers[self]
 
-------------------------------------------------------------------------------
849       0.0885  xlog.c:697                  XLogInsert  849      100.000  xlog.c:697                  XLogInsert
[self]
-------------------------------------------------------------------------------
269       0.0280  catcache.c:444              CatalogCacheIdInvalidate  269      100.000  catcache.c:444
CatalogCacheIdInvalidate[self]
 
-------------------------------------------------------------------------------
232       0.0242  catcache.c:1787             PrepareToInvalidateCacheTuple  232      100.000  catcache.c:1787
  PrepareToInvalidateCacheTuple [self]
 
-------------------------------------------------------------------------------
202       0.0211  dynahash.c:807              hash_search_with_hash_value  202      100.000  dynahash.c:807
hash_search_with_hash_value [self]
 
-------------------------------------------------------------------------------
199       0.0207  nbtsearch.c:344             _bt_compare  199      100.000  nbtsearch.c:344             _bt_compare
[self]
-------------------------------------------------------------------------------
198       0.0206  list.c:506                  list_member_oid  198      100.000  list.c:506
list_member_oid[self]
 


Is the current behaviour expected ?
Because I saw the comment around droprelfilenodebuffers, saying
"XXX currently it sequentially searches the buffer pool, should be
changed to more clever ways of searching.  However, this 
routine is used only in code paths that aren't very 
performance-critical, and we shouldn't slow down the hot paths to make it 
faster ".

Maybe it is stupid, but I also wonder whether the root cause for what I'm 
seeing can be also responsible for the problems I recently  reported 
about the scaling and locking
http://archives.postgresql.org/pgsql-hackers/2012-05/msg01118.php

Some additional info:
The database is accessed in a single thread, shared_buffers are 10G. 
The tables themselves are empty essentially. the cpu if it matters is 
4 times Xeon E7- 4807 (Westmere architecture).
I did a vacuum full of everything just in case and it didn't help
And another maybe important factor is that I noticed is that
pg_catalog.pg_attribute is quite large (238 meg) (because of the large 
number of tables times columns).

I also stopped PG with gdb a few times and it was always at this backtrace:

(gdb) bt
#0  tas (lock=0x7fa4e3007538 "\001") at ../../../../src/include/storage/s_lock.h:218
#1  0x00000000006e6956 in DropRelFileNodeBuffers (rnode=..., forkNum=VISIBILITYMAP_FORKNUM, firstDelBlock=0) at
bufmgr.c:2062
#2  0x000000000070c014 in smgrdounlink (reln=0x1618210, forknum=VISIBILITYMAP_FORKNUM, isRedo=0 '\000') at smgr.c:354
#3  0x000000000051ecf6 in smgrDoPendingDeletes (isCommit=1 '\001') at storage.c:364
#4  0x00000000004a7b33 in CommitTransaction () at xact.c:1925
#5  0x00000000004a8479 in CommitTransactionCommand () at xact.c:2524
#6  0x0000000000710b3f in finish_xact_command () at postgres.c:2419
#7  0x000000000070ff4e in exec_execute_message (portal_name=0x1608990 "", max_rows=1) at postgres.c:1956
#8  0x0000000000712988 in PostgresMain (argc=2, argv=0x1548568, username=0x1548390 
with only forknum changing to MAIN_FORKNUM or FSM_FORKNUM

Thanks in advance,    Sergey


*****************************************************
Sergey E. Koposov, PhD, Research Associate
Institute of Astronomy, University of Cambridge
Madingley road, CB3 0HA, Cambridge, UK
Tel: +44-1223-337-551 Web: http://www.ast.cam.ac.uk/~koposov/