slow dropping of tables, DropRelFileNodeBuffers, tas

From: Sergey Koposov <koposov(at)ast(dot)cam(dot)ac(dot)uk>
To: pgsql-hackers(at)postgresql(dot)org
Subject: slow dropping of tables, DropRelFileNodeBuffers, tas
Date: 2012-05-30 00:40:01
Message-ID: alpine.LRH.2.02.1205300012201.6351@calx046.ast.cam.ac.uk
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

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/

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Tatsuo Ishii 2012-05-30 00:58:16 Re: pg_dump and thousands of schemas
Previous Message Robert Haas 2012-05-30 00:19:31 hash index concurrency