X-Original-To: pgsql-performance-postgresql.org@localhost.postgresql.org Received: from localhost (av.hub.org [200.46.204.144]) by postgresql.org (Postfix) with ESMTP id E75D09DC85B for ; Fri, 20 Jan 2006 17:19:18 -0400 (AST) Received: from postgresql.org ([200.46.204.71]) by localhost (av.hub.org [200.46.204.144]) (amavisd-new, port 10024) with ESMTP id 78561-03 for ; Fri, 20 Jan 2006 17:19:19 -0400 (AST) X-Greylist: from auto-whitelisted by SQLgrey- Received: from sss.pgh.pa.us (sss.pgh.pa.us [66.207.139.130]) by postgresql.org (Postfix) with ESMTP id 369199DC842 for ; Fri, 20 Jan 2006 17:19:15 -0400 (AST) Received: from sss2.sss.pgh.pa.us (tgl@localhost [127.0.0.1]) by sss.pgh.pa.us (8.13.1/8.13.1) with ESMTP id k0KLJFWm026959; Fri, 20 Jan 2006 16:19:15 -0500 (EST) To: Martijn van Oosterhout cc: Stephan Vollmer , pgsql-performance@postgreSQL.org Subject: Re: [GENERAL] Creation of tsearch2 index is very slow In-reply-to: <20060120205132.GF31908@svana.org> References: <43D0ED57.1020608@gmx.de> <17454.1137771321@sss.pgh.pa.us> <20060120170452.GC31908@svana.org> <26153.1137784469@sss.pgh.pa.us> <20060120201036.GE31908@svana.org> <26583.1137788505@sss.pgh.pa.us> <20060120205132.GF31908@svana.org> Comments: In-reply-to Martijn van Oosterhout message dated "Fri, 20 Jan 2006 21:51:32 +0100" Date: Fri, 20 Jan 2006 16:19:15 -0500 Message-ID: <26958.1137791955@sss.pgh.pa.us> From: Tom Lane X-Virus-Scanned: by amavisd-new at hub.org X-Spam-Status: No, score=0.094 required=5 tests=[AWL=0.094] X-Spam-Score: 0.094 X-Spam-Level: X-Archive-Number: 200601/362 X-Sequence-Number: 16840 Well, I feel like a fool, because I failed to notice that the total runtime shown in that profile wasn't anywhere close to the actual wall clock time. gprof is indeed simply not counting the time spent in dynamically-linked code. With tsearch2 statically linked into the backend, a more believable picture emerges: % cumulative self self total time seconds seconds calls Ks/call Ks/call name 98.96 1495.93 1495.93 33035195 0.00 0.00 hemdistsign 0.27 1500.01 4.08 10030581 0.00 0.00 makesign 0.11 1501.74 1.73 588976 0.00 0.00 gistchoose 0.10 1503.32 1.58 683471 0.00 0.00 XLogInsert 0.05 1504.15 0.83 246579 0.00 0.00 sizebitvec 0.05 1504.93 0.78 446399 0.00 0.00 gtsvector_union 0.03 1505.45 0.52 3576475 0.00 0.00 LWLockRelease 0.03 1505.92 0.47 1649 0.00 0.00 gtsvector_picksplit 0.03 1506.38 0.47 3572572 0.00 0.00 LWLockAcquire 0.02 1506.74 0.36 444817 0.00 0.00 gtsvector_same 0.02 1507.09 0.35 4077089 0.00 0.00 AllocSetAlloc 0.02 1507.37 0.28 236984 0.00 0.00 gistdoinsert 0.02 1507.63 0.26 874195 0.00 0.00 hash_search 0.02 1507.89 0.26 9762101 0.00 0.00 gtsvector_penalty 0.01 1508.08 0.19 236984 0.00 0.00 gistmakedeal 0.01 1508.27 0.19 841754 0.00 0.00 UnpinBuffer 0.01 1508.45 0.18 22985469 0.00 0.00 hemdistcache 0.01 1508.63 0.18 3998572 0.00 0.00 LockBuffer 0.01 1508.81 0.18 686681 0.00 0.00 gtsvector_compress 0.01 1508.98 0.17 11514275 0.00 0.00 gistdentryinit So we gotta fix hemdistsign ... regards, tom lane