Creation of tsearch2 index is very slow
Hello!
I noticed that the creation of a GIST index for tsearch2 takes very
long - about 20 minutes. CPU utilization is 100 %, the resulting
index file size is ~25 MB. Is this behaviour normal?
Full text columns: title author_list
tsearch2 word lists: fti_title fti_author_list
tsearch2 indexes: idx_fti_title idx_fti_author_list
The table has 700,000 records. When I create a normal B-Tree index
on the same column for testing purposes, it works quite fast
(approx. 30 seconds).
The columns that should be indexed are small, only about 10 words on
average.
System specs:
Athlon64 X2 3800+, 2 GB RAM
PostgreSQL 8.1.2, Windows XP SP2
I've never noticed this problem before, so could it probably be
related to v8.1.2? Or is something in my configuration or table
definition that causes this sluggishness?
Thanks very much in advance for your help!
- Stephan
This is the table definition:
-----------------------------------------------------------------
CREATE TABLE publications
(
id int4 NOT NULL DEFAULT nextval('publications_id_seq'::regclass),
publication_type_id int4 NOT NULL DEFAULT 0,
keyword text NOT NULL,
mdate date,
"year" date,
title text,
fti_title tsvector,
author_list text,
fti_author_list tsvector,
overview_timestamp timestamp,
overview_xml text,
CONSTRAINT publications_pkey PRIMARY KEY (keyword) USING INDEX
TABLESPACE dblp_index,
CONSTRAINT publications_publication_type_id_fkey FOREIGN KEY
(publication_type_id)
REFERENCES publication_types (id) MATCH SIMPLE
ON UPDATE RESTRICT ON DELETE RESTRICT,
CONSTRAINT publications_year_check CHECK (date_part('month'::text,
"year") = 1::double precision AND date_part('day'::text, "year") =
1::double precision)
)
WITHOUT OIDS;
CREATE INDEX fki_publications_publication_type_id
ON publications
USING btree
(publication_type_id)
TABLESPACE dblp_index;
CREATE INDEX idx_fti_author_list
ON publications
USING gist
(fti_author_list)
TABLESPACE dblp_index;
CREATE INDEX idx_fti_title
ON publications
USING gist
(fti_title)
TABLESPACE dblp_index;
CREATE INDEX idx_publications_year
ON publications
USING btree
("year")
TABLESPACE dblp_index;
CREATE INDEX idx_publications_year_part
ON publications
USING btree
(date_part('year'::text, "year"))
TABLESPACE dblp_index;
CREATE TRIGGER tsvectorupdate_all
BEFORE INSERT OR UPDATE
ON publications
FOR EACH ROW
EXECUTE PROCEDURE multi_tsearch2();
PS:
What I forgot to mention was that inserting records into the table
is also about 2-3 times slower than before (most likely due to the
slow index update operations).
I dropped the whole database and restored the dumpfile, but the
result it the same. When the index is recreated after COPYing the
data, it takes more than 20 minutes for _each_ of both tsearch2
indexes. So the total time to restore this table is more than 45
minutes!
- Stephan
Stephan Vollmer <svollmer@gmx.de> writes:
I noticed that the creation of a GIST index for tsearch2 takes very
long - about 20 minutes. CPU utilization is 100 %, the resulting
index file size is ~25 MB. Is this behaviour normal?
This has been complained of before. GIST is always going to be slower
at index-building than btree; in the btree case there's a simple optimal
strategy for making an index (ie, sort the keys) but for GIST we don't
know anything better to do than insert the keys one at a time.
However, I'm not sure that anyone's tried to do any performance
optimization on the GIST insert code ... there might be some low-hanging
fruit there. It'd be interesting to look at a gprof profile of what the
backend is doing during the index build. Do you have the ability to do
that, or would you be willing to give your data to someone else to
investigate with? (The behavior is very possibly data-dependent, which
is why I want to see a profile with your specific data and not just some
random dataset or other.)
regards, tom lane
Tom Lane wrote:
Stephan Vollmer <svollmer@gmx.de> writes:
I noticed that the creation of a GIST index for tsearch2 takes very
long - about 20 minutes. CPU utilization is 100 %, the resulting
index file size is ~25 MB. Is this behaviour normal?This has been complained of before. GIST is always going to be slower
at index-building than btree; in the btree case there's a simple optimal
strategy for making an index (ie, sort the keys) but for GIST we don't
know anything better to do than insert the keys one at a time.
Ah, ok. That explains a lot, although I wonder why it is so much slower.
However, I'm not sure that anyone's tried to do any performance
optimization on the GIST insert code ... there might be some low-hanging
fruit there. It'd be interesting to look at a gprof profile of what the
backend is doing during the index build. Do you have the ability to do
that, or would you be willing to give your data to someone else to
investigate with?
Unfortunately, I'm not able to investigate it further myself as I'm
quite a Postgres newbie. But I could provide someone else with the
example table. Maybe someone else could find out why it is so slow.
I dropped all unnecessary columns and trimmed the table down to
235,000 rows. The dumped table (compressed with RAR) is 7,1 MB. I
don't have a website to upload it but I could send it to someone via
e-mail.
With this 235,000 row table, index creation times are:
- GIST 347063 ms
- B-Tree 2515 ms
Thanks for your help!
- Stephan
On Fri, Jan 20, 2006 at 10:35:21AM -0500, Tom Lane wrote:
However, I'm not sure that anyone's tried to do any performance
optimization on the GIST insert code ... there might be some low-hanging
fruit there. It'd be interesting to look at a gprof profile of what the
backend is doing during the index build. Do you have the ability to do
that, or would you be willing to give your data to someone else to
investigate with? (The behavior is very possibly data-dependent, which
is why I want to see a profile with your specific data and not just some
random dataset or other.)
The cost on inserting would generally go to either penalty, or
picksplit. Certainly if you're inserting lots of values in a short
interval, I can imagine picksplit being nasty, since the algorithms for
a lot of datatypes are not really reknown for their speed.
I'm wondering if you could possibly improve the process by grouping
into larger blocks. For example, pull out enough tuples to cover 4
pages and then call picksplit three times to split it into the four
pages. This gives you 4 entries for the level above the leaves. Keep
reading tuples and splitting until you get enough for the next level
and call picksplit on those. etc etc.
The thing is, you never call penalty here so it's questionable whether
the tree will be as efficient as just inserting. For example, if have a
data type representing ranges (a,b), straight inserting can produce the
perfect tree order like a b-tree (assuming non-overlapping entries).
The above process will produce something close, but not quite...
Should probably get out a pen-and-paper to model this. After all, if
the speed of the picksplit increases superlinearly to the number of
elements, calling it will larger sets may prove to be a loss overall...
Perhaps the easiest would be to allow datatypes to provide a bulkinsert
function, like b-tree does? The question is, what should be its input
and output?
Have a nice day,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/
Show quoted text
Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.
Stephan Vollmer <svollmer@gmx.de> writes:
Unfortunately, I'm not able to investigate it further myself as I'm
quite a Postgres newbie. But I could provide someone else with the
example table. Maybe someone else could find out why it is so slow.
I'd be willing to take a look, if you'll send me the dump file off-list.
I dropped all unnecessary columns and trimmed the table down to
235,000 rows. The dumped table (compressed with RAR) is 7,1 MB. I
don't have a website to upload it but I could send it to someone via
e-mail.
Don't have RAR --- gzip or bzip2 is fine ...
regards, tom lane
Martijn van Oosterhout <kleptog@svana.org> writes:
The cost on inserting would generally go to either penalty, or
picksplit. Certainly if you're inserting lots of values in a short
interval, I can imagine picksplit being nasty, since the algorithms for
a lot of datatypes are not really reknown for their speed.
Tut tut ... in the words of the sage, it is a capital mistake to
theorize in advance of the data. You may well be right, but on the
other hand it could easily be something dumb like an O(N^2) loop over
a list structure.
I'll post some gprof numbers after Stephan sends me the dump. We
should probably move the thread to someplace like pgsql-perform, too.
regards, tom lane
[ thread moved to pgsql-performance ]
I've obtained a gprof profile on Stephan's sample case (many thanks for
providing the data, Stephan). The command is
CREATE INDEX foo ON publications_test USING gist (fti_title);
where fti_title is a tsvector column. There are 236984 rows in the
table, most with between 4 and 10 words in fti_title.
sum(length(fti_title)) yields 1636202 ... not sure if this is a
relevant measure, however.
Using CVS tip with a fairly vanilla configuration (including
--enable-cassert), here are all the hotspots down to the 1% level:
% cumulative self self total
time seconds seconds calls s/call s/call name
20.19 1.90 1.90 588976 0.00 0.00 gistchoose
19.02 3.69 1.79 683471 0.00 0.00 XLogInsert
5.95 4.25 0.56 3575135 0.00 0.00 LWLockAcquire
4.46 4.67 0.42 3579005 0.00 0.00 LWLockRelease
4.14 5.06 0.39 3146848 0.00 0.00 AllocSetAlloc
3.72 5.41 0.35 236984 0.00 0.00 gistdoinsert
3.40 5.73 0.32 876047 0.00 0.00 hash_search
2.76 5.99 0.26 3998576 0.00 0.00 LockBuffer
2.28 6.21 0.22 11514275 0.00 0.00 gistdentryinit
1.86 6.38 0.18 841757 0.00 0.00 UnpinBuffer
1.81 6.55 0.17 12201023 0.00 0.00 FunctionCall1
1.81 6.72 0.17 237044 0.00 0.00 AllocSetCheck
1.49 6.86 0.14 236984 0.00 0.00 gistmakedeal
1.49 7.00 0.14 10206985 0.00 0.00 FunctionCall3
1.49 7.14 0.14 1287874 0.00 0.00 MemoryContextAllocZero
1.28 7.26 0.12 826179 0.00 0.00 PinBuffer
1.17 7.37 0.11 875785 0.00 0.00 hash_any
1.17 7.48 0.11 1857292 0.00 0.00 MemoryContextAlloc
1.17 7.59 0.11 221466 0.00 0.00 PageIndexTupleDelete
1.06 7.69 0.10 9762101 0.00 0.00 gistpenalty
Clearly, one thing that would be worth doing is suppressing the WAL
traffic when possible, as we already do for btree builds. It seems
that gistchoose may have some internal ineffiency too --- I haven't
looked at the code yet. The other thing that jumps out is the very
large numbers of calls to gistdentryinit, FunctionCall1, FunctionCall3.
Some interesting parts of the calls/calledby graph are:
-----------------------------------------------
0.35 8.07 236984/236984 gistbuildCallback [14]
[15]: 89.5 0.35 8.07 236984 gistdoinsert [15] 0.14 3.55 236984/236984 gistmakedeal [16] 1.90 0.89 588976/588976 gistchoose [17] 0.07 0.83 825960/841757 ReadBuffer [19] 0.09 0.10 825960/1287874 MemoryContextAllocZero [30] 0.12 0.05 1888904/3998576 LockBuffer [29] 0.13 0.00 825960/3575135 LWLockAcquire [21] 0.10 0.00 825960/3579005 LWLockRelease [26] 0.06 0.00 473968/3146848 AllocSetAlloc [27] 0.03 0.00 473968/1857292 MemoryContextAlloc [43] 0.02 0.00 825960/1272423 gistcheckpage [68] ----------------------------------------------- 0.14 3.55 236984/236984 gistdoinsert [15]
0.14 3.55 236984/236984 gistmakedeal [16]39.2 0.14 3.55 236984 gistmakedeal [16] 1.20 0.15 458450/683471 XLogInsert [18] 0.01 0.66 224997/224997 gistxlogInsertCompletion [20] 0.09 0.35 444817/444817 gistgetadjusted [23] 0.08 0.17 456801/456804 formUpdateRdata [32] 0.17 0.01 827612/841757 UnpinBuffer [35] 0.11 0.00 221466/221466 PageIndexTupleDelete [42] 0.02 0.08 456801/460102 gistfillbuffer [45] 0.06 0.04 1649/1649 gistSplit [46] 0.08 0.00 685099/3579005 LWLockRelease [26] 0.03 0.05 446463/446463 gistFindCorrectParent [50] 0.04 0.02 685099/3998576 LockBuffer [29] 0.04 0.00 1649/1649 gistextractbuffer [58] 0.03 0.00 460102/460121 write_buffer [66] 0.02 0.00 825960/826092 ReleaseBuffer [69] 0.02 0.00 221402/221402 gistadjscans [82] 0.00 0.00 1582/1582 gistunion [131] 0.00 0.00 1649/1649 formSplitRdata [147] 0.00 0.00 1649/1649 gistjoinvector [178] 0.00 0.00 3/3 gistnewroot [199] 0.00 0.00 458450/461748 gistnospace [418] 0.00 0.00 458450/458450 WriteNoReleaseBuffer [419] 0.00 0.00 1652/1671 WriteBuffer [433] ----------------------------------------------- 1.90 0.89 588976/588976 gistdoinsert [15]
1.90 0.89 588976/588976 gistchoose [17]29.7 1.90 0.89 588976 gistchoose [17] 0.25 0.17 9762101/10892174 FunctionCall3 <cycle 1> [38] 0.18 0.14 9762101/11514275 gistdentryinit [28] 0.10 0.00 9762101/9762101 gistpenalty [47] 0.04 0.02 588976/1478610 gistDeCompressAtt [39] ----------------------------------------------- 0.00 0.00 1/683471 gistbuild [12] 0.00 0.00 1/683471 log_heap_update [273] 0.00 0.00 1/683471 RecordTransactionCommit [108] 0.00 0.00 1/683471 smgrcreate [262] 0.00 0.00 3/683471 gistnewroot [199] 0.00 0.00 5/683471 heap_insert [116] 0.00 0.00 12/683471 _bt_insertonpg [195] 0.59 0.07 224997/683471 gistxlogInsertCompletion [20] 1.20 0.15 458450/683471 gistmakedeal [16]
0.07 0.83 825960/841757 ReadBuffer [19]
0.09 0.10 825960/1287874 MemoryContextAllocZero [30]
0.12 0.05 1888904/3998576 LockBuffer [29]
0.13 0.00 825960/3575135 LWLockAcquire [21]
0.10 0.00 825960/3579005 LWLockRelease [26]
0.06 0.00 473968/3146848 AllocSetAlloc [27]
0.03 0.00 473968/1857292 MemoryContextAlloc [43]
0.02 0.00 825960/1272423 gistcheckpage [68]
-----------------------------------------------
0.14 3.55 236984/236984 gistdoinsert [15]89.5 0.35 8.07 236984 gistdoinsert [15] 0.14 3.55 236984/236984 gistmakedeal [16] 1.90 0.89 588976/588976 gistchoose [17] 0.07 0.83 825960/841757 ReadBuffer [19] 0.09 0.10 825960/1287874 MemoryContextAllocZero [30] 0.12 0.05 1888904/3998576 LockBuffer [29] 0.13 0.00 825960/3575135 LWLockAcquire [21] 0.10 0.00 825960/3579005 LWLockRelease [26] 0.06 0.00 473968/3146848 AllocSetAlloc [27] 0.03 0.00 473968/1857292 MemoryContextAlloc [43] 0.02 0.00 825960/1272423 gistcheckpage [68] ----------------------------------------------- 0.14 3.55 236984/236984 gistdoinsert [15]
[16]: 39.2 0.14 3.55 236984 gistmakedeal [16] 1.20 0.15 458450/683471 XLogInsert [18] 0.01 0.66 224997/224997 gistxlogInsertCompletion [20] 0.09 0.35 444817/444817 gistgetadjusted [23] 0.08 0.17 456801/456804 formUpdateRdata [32] 0.17 0.01 827612/841757 UnpinBuffer [35] 0.11 0.00 221466/221466 PageIndexTupleDelete [42] 0.02 0.08 456801/460102 gistfillbuffer [45] 0.06 0.04 1649/1649 gistSplit [46] 0.08 0.00 685099/3579005 LWLockRelease [26] 0.03 0.05 446463/446463 gistFindCorrectParent [50] 0.04 0.02 685099/3998576 LockBuffer [29] 0.04 0.00 1649/1649 gistextractbuffer [58] 0.03 0.00 460102/460121 write_buffer [66] 0.02 0.00 825960/826092 ReleaseBuffer [69] 0.02 0.00 221402/221402 gistadjscans [82] 0.00 0.00 1582/1582 gistunion [131] 0.00 0.00 1649/1649 formSplitRdata [147] 0.00 0.00 1649/1649 gistjoinvector [178] 0.00 0.00 3/3 gistnewroot [199] 0.00 0.00 458450/461748 gistnospace [418] 0.00 0.00 458450/458450 WriteNoReleaseBuffer [419] 0.00 0.00 1652/1671 WriteBuffer [433] ----------------------------------------------- 1.90 0.89 588976/588976 gistdoinsert [15]
1.20 0.15 458450/683471 XLogInsert [18]21.4 1.79 0.22 683471 XLogInsert [18] 0.11 0.00 683471/3575135 LWLockAcquire [21] 0.08 0.00 687340/3579005 LWLockRelease [26] 0.03 0.00 683471/683471 GetCurrentTransactionIdIfAny [65] 0.01 0.00 15604/15604 AdvanceXLInsertBuffer [111] 0.00 0.00 3/10094 BufferGetBlockNumber [95] 0.00 0.00 3869/3870 XLogWrite [281] 0.00 0.00 3870/3871 LWLockConditionalAcquire [428] 0.00 0.00 3/3 BufferGetFileNode [611] ----------------------------------------------- 0.00 0.00 3164/11514275 gistunion [131] 0.01 0.00 270400/11514275 gistSplit [46] 0.03 0.02 1478610/11514275 gistDeCompressAtt [39] 0.18 0.14 9762101/11514275 gistchoose [17]
0.01 0.66 224997/224997 gistxlogInsertCompletion [20]
0.09 0.35 444817/444817 gistgetadjusted [23]
0.08 0.17 456801/456804 formUpdateRdata [32]
0.17 0.01 827612/841757 UnpinBuffer [35]
0.11 0.00 221466/221466 PageIndexTupleDelete [42]
0.02 0.08 456801/460102 gistfillbuffer [45]
0.06 0.04 1649/1649 gistSplit [46]
0.08 0.00 685099/3579005 LWLockRelease [26]
0.03 0.05 446463/446463 gistFindCorrectParent [50]
0.04 0.02 685099/3998576 LockBuffer [29]
0.04 0.00 1649/1649 gistextractbuffer [58]
0.03 0.00 460102/460121 write_buffer [66]
0.02 0.00 825960/826092 ReleaseBuffer [69]
0.02 0.00 221402/221402 gistadjscans [82]
0.00 0.00 1582/1582 gistunion [131]
0.00 0.00 1649/1649 formSplitRdata [147]
0.00 0.00 1649/1649 gistjoinvector [178]
0.00 0.00 3/3 gistnewroot [199]
0.00 0.00 458450/461748 gistnospace [418]
0.00 0.00 458450/458450 WriteNoReleaseBuffer [419]
0.00 0.00 1652/1671 WriteBuffer [433]
-----------------------------------------------
1.90 0.89 588976/588976 gistdoinsert [15]89.5 0.35 8.07 236984 gistdoinsert [15] 0.14 3.55 236984/236984 gistmakedeal [16] 1.90 0.89 588976/588976 gistchoose [17] 0.07 0.83 825960/841757 ReadBuffer [19] 0.09 0.10 825960/1287874 MemoryContextAllocZero [30] 0.12 0.05 1888904/3998576 LockBuffer [29] 0.13 0.00 825960/3575135 LWLockAcquire [21] 0.10 0.00 825960/3579005 LWLockRelease [26] 0.06 0.00 473968/3146848 AllocSetAlloc [27] 0.03 0.00 473968/1857292 MemoryContextAlloc [43] 0.02 0.00 825960/1272423 gistcheckpage [68] ----------------------------------------------- 0.14 3.55 236984/236984 gistdoinsert [15]
[17]: 29.7 1.90 0.89 588976 gistchoose [17] 0.25 0.17 9762101/10892174 FunctionCall3 <cycle 1> [38] 0.18 0.14 9762101/11514275 gistdentryinit [28] 0.10 0.00 9762101/9762101 gistpenalty [47] 0.04 0.02 588976/1478610 gistDeCompressAtt [39] ----------------------------------------------- 0.00 0.00 1/683471 gistbuild [12] 0.00 0.00 1/683471 log_heap_update [273] 0.00 0.00 1/683471 RecordTransactionCommit [108] 0.00 0.00 1/683471 smgrcreate [262] 0.00 0.00 3/683471 gistnewroot [199] 0.00 0.00 5/683471 heap_insert [116] 0.00 0.00 12/683471 _bt_insertonpg [195] 0.59 0.07 224997/683471 gistxlogInsertCompletion [20] 1.20 0.15 458450/683471 gistmakedeal [16]
0.25 0.17 9762101/10892174 FunctionCall3 <cycle 1> [38]1.5 0.14 0.00 10206985 FunctionCall3 <cycle 1> [38] 0.00 0.00 10206918/22855929 data_start [414] 0.00 0.00 67/67 btbeginscan [486] 67 RelationGetIndexScan <cycle 1> [212]
0.18 0.14 9762101/11514275 gistdentryinit [28]4.0 0.22 0.16 11514275 gistdentryinit [28] 0.16 0.00 11514275/12201023 FunctionCall1 [36] ----------------------------------------------- 0.00 0.00 67/12201023 index_endscan <cycle 1> [167] 0.01 0.00 686681/12201023 gistcentryinit [62] 0.16 0.00 11514275/12201023 gistdentryinit [28]
0.10 0.00 9762101/9762101 gistpenalty [47]
0.04 0.02 588976/1478610 gistDeCompressAtt [39]
-----------------------------------------------
0.00 0.00 1/683471 gistbuild [12]
0.00 0.00 1/683471 log_heap_update [273]
0.00 0.00 1/683471 RecordTransactionCommit [108]
0.00 0.00 1/683471 smgrcreate [262]
0.00 0.00 3/683471 gistnewroot [199]
0.00 0.00 5/683471 heap_insert [116]
0.00 0.00 12/683471 _bt_insertonpg [195]
0.59 0.07 224997/683471 gistxlogInsertCompletion [20]
1.20 0.15 458450/683471 gistmakedeal [16]39.2 0.14 3.55 236984 gistmakedeal [16] 1.20 0.15 458450/683471 XLogInsert [18] 0.01 0.66 224997/224997 gistxlogInsertCompletion [20] 0.09 0.35 444817/444817 gistgetadjusted [23] 0.08 0.17 456801/456804 formUpdateRdata [32] 0.17 0.01 827612/841757 UnpinBuffer [35] 0.11 0.00 221466/221466 PageIndexTupleDelete [42] 0.02 0.08 456801/460102 gistfillbuffer [45] 0.06 0.04 1649/1649 gistSplit [46] 0.08 0.00 685099/3579005 LWLockRelease [26] 0.03 0.05 446463/446463 gistFindCorrectParent [50] 0.04 0.02 685099/3998576 LockBuffer [29] 0.04 0.00 1649/1649 gistextractbuffer [58] 0.03 0.00 460102/460121 write_buffer [66] 0.02 0.00 825960/826092 ReleaseBuffer [69] 0.02 0.00 221402/221402 gistadjscans [82] 0.00 0.00 1582/1582 gistunion [131] 0.00 0.00 1649/1649 formSplitRdata [147] 0.00 0.00 1649/1649 gistjoinvector [178] 0.00 0.00 3/3 gistnewroot [199] 0.00 0.00 458450/461748 gistnospace [418] 0.00 0.00 458450/458450 WriteNoReleaseBuffer [419] 0.00 0.00 1652/1671 WriteBuffer [433] ----------------------------------------------- 1.90 0.89 588976/588976 gistdoinsert [15]
[18]: 21.4 1.79 0.22 683471 XLogInsert [18] 0.11 0.00 683471/3575135 LWLockAcquire [21] 0.08 0.00 687340/3579005 LWLockRelease [26] 0.03 0.00 683471/683471 GetCurrentTransactionIdIfAny [65] 0.01 0.00 15604/15604 AdvanceXLInsertBuffer [111] 0.00 0.00 3/10094 BufferGetBlockNumber [95] 0.00 0.00 3869/3870 XLogWrite [281] 0.00 0.00 3870/3871 LWLockConditionalAcquire [428] 0.00 0.00 3/3 BufferGetFileNode [611] ----------------------------------------------- 0.00 0.00 3164/11514275 gistunion [131] 0.01 0.00 270400/11514275 gistSplit [46] 0.03 0.02 1478610/11514275 gistDeCompressAtt [39] 0.18 0.14 9762101/11514275 gistchoose [17]
0.11 0.00 683471/3575135 LWLockAcquire [21]
0.08 0.00 687340/3579005 LWLockRelease [26]
0.03 0.00 683471/683471 GetCurrentTransactionIdIfAny [65]
0.01 0.00 15604/15604 AdvanceXLInsertBuffer [111]
0.00 0.00 3/10094 BufferGetBlockNumber [95]
0.00 0.00 3869/3870 XLogWrite [281]
0.00 0.00 3870/3871 LWLockConditionalAcquire [428]
0.00 0.00 3/3 BufferGetFileNode [611]
-----------------------------------------------
0.00 0.00 3164/11514275 gistunion [131]
0.01 0.00 270400/11514275 gistSplit [46]
0.03 0.02 1478610/11514275 gistDeCompressAtt [39]
0.18 0.14 9762101/11514275 gistchoose [17]29.7 1.90 0.89 588976 gistchoose [17] 0.25 0.17 9762101/10892174 FunctionCall3 <cycle 1> [38] 0.18 0.14 9762101/11514275 gistdentryinit [28] 0.10 0.00 9762101/9762101 gistpenalty [47] 0.04 0.02 588976/1478610 gistDeCompressAtt [39] ----------------------------------------------- 0.00 0.00 1/683471 gistbuild [12] 0.00 0.00 1/683471 log_heap_update [273] 0.00 0.00 1/683471 RecordTransactionCommit [108] 0.00 0.00 1/683471 smgrcreate [262] 0.00 0.00 3/683471 gistnewroot [199] 0.00 0.00 5/683471 heap_insert [116] 0.00 0.00 12/683471 _bt_insertonpg [195] 0.59 0.07 224997/683471 gistxlogInsertCompletion [20] 1.20 0.15 458450/683471 gistmakedeal [16]
[28]: 4.0 0.22 0.16 11514275 gistdentryinit [28] 0.16 0.00 11514275/12201023 FunctionCall1 [36] ----------------------------------------------- 0.00 0.00 67/12201023 index_endscan <cycle 1> [167] 0.01 0.00 686681/12201023 gistcentryinit [62] 0.16 0.00 11514275/12201023 gistdentryinit [28]
0.16 0.00 11514275/12201023 FunctionCall1 [36]1.8 0.17 0.00 12201023 FunctionCall1 [36] 0.00 0.00 67/67 btendscan [231] 0.00 0.00 12200956/22855929 data_start [414] ----------------------------------------------- 67 index_beginscan_internal <cycle 1> [169] 0.01 0.01 444817/10892174 gistgetadjusted [23] 0.25 0.17 9762101/10892174 gistchoose [17]
-----------------------------------------------
0.00 0.00 67/12201023 index_endscan <cycle 1> [167]
0.01 0.00 686681/12201023 gistcentryinit [62]
0.16 0.00 11514275/12201023 gistdentryinit [28]4.0 0.22 0.16 11514275 gistdentryinit [28] 0.16 0.00 11514275/12201023 FunctionCall1 [36] ----------------------------------------------- 0.00 0.00 67/12201023 index_endscan <cycle 1> [167] 0.01 0.00 686681/12201023 gistcentryinit [62] 0.16 0.00 11514275/12201023 gistdentryinit [28]
[36]: 1.8 0.17 0.00 12201023 FunctionCall1 [36] 0.00 0.00 67/67 btendscan [231] 0.00 0.00 12200956/22855929 data_start [414] ----------------------------------------------- 67 index_beginscan_internal <cycle 1> [169] 0.01 0.01 444817/10892174 gistgetadjusted [23] 0.25 0.17 9762101/10892174 gistchoose [17]
0.00 0.00 67/67 btendscan [231]
0.00 0.00 12200956/22855929 data_start [414]
-----------------------------------------------
67 index_beginscan_internal <cycle 1> [169]
0.01 0.01 444817/10892174 gistgetadjusted [23]
0.25 0.17 9762101/10892174 gistchoose [17]29.7 1.90 0.89 588976 gistchoose [17] 0.25 0.17 9762101/10892174 FunctionCall3 <cycle 1> [38] 0.18 0.14 9762101/11514275 gistdentryinit [28] 0.10 0.00 9762101/9762101 gistpenalty [47] 0.04 0.02 588976/1478610 gistDeCompressAtt [39] ----------------------------------------------- 0.00 0.00 1/683471 gistbuild [12] 0.00 0.00 1/683471 log_heap_update [273] 0.00 0.00 1/683471 RecordTransactionCommit [108] 0.00 0.00 1/683471 smgrcreate [262] 0.00 0.00 3/683471 gistnewroot [199] 0.00 0.00 5/683471 heap_insert [116] 0.00 0.00 12/683471 _bt_insertonpg [195] 0.59 0.07 224997/683471 gistxlogInsertCompletion [20] 1.20 0.15 458450/683471 gistmakedeal [16]
[38]: 1.5 0.14 0.00 10206985 FunctionCall3 <cycle 1> [38] 0.00 0.00 10206918/22855929 data_start [414] 0.00 0.00 67/67 btbeginscan [486] 67 RelationGetIndexScan <cycle 1> [212]
0.00 0.00 10206918/22855929 data_start [414]
0.00 0.00 67/67 btbeginscan [486]
67 RelationGetIndexScan <cycle 1> [212]
Now that we have some data, we can start to think about how to improve
matters ...
regards, tom lane
On Fri, Jan 20, 2006 at 02:14:29PM -0500, Tom Lane wrote:
[ thread moved to pgsql-performance ]
I've obtained a gprof profile on Stephan's sample case (many thanks for
providing the data, Stephan). The command is
<snip>
Something I'm missing is the calls to tsearch functions. I'm not 100%
familiar with gprof, but is it possible those costs have been added
somewhere else because it's in a shared library? Perhaps the costs went
into FunctionCall1/3?
Have a nice day,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/
Show quoted text
Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.
Martijn van Oosterhout <kleptog@svana.org> writes:
Something I'm missing is the calls to tsearch functions. I'm not 100%
familiar with gprof, but is it possible those costs have been added
somewhere else because it's in a shared library? Perhaps the costs went
into FunctionCall1/3?
I think that the tsearch functions must be the stuff charged as
"data_start" (which is not actually any symbol in our source code).
That is showing as being called by FunctionCallN which is what you'd
expect.
If the totals given by gprof are correct, then it's down in the noise.
I don't think I trust that too much ... but I don't see anything in the
gprof manual about how to include a dynamically loaded library in the
profile. (I did compile tsearch2 with -pg, but that's evidently not
enough.)
I'll see if I can link tsearch2 statically to resolve this question.
regards, tom lane
On Fri, Jan 20, 2006 at 03:21:45PM -0500, Tom Lane wrote:
If the totals given by gprof are correct, then it's down in the noise.
I don't think I trust that too much ... but I don't see anything in the
gprof manual about how to include a dynamically loaded library in the
profile. (I did compile tsearch2 with -pg, but that's evidently not
enough.)
There is some mention on the web of an environment variable you can
set: LD_PROFILE=<libname>
These pages seem relevent:
http://sourceware.org/ml/binutils/2002-04/msg00047.html
http://www.scit.wlv.ac.uk/cgi-bin/mansec?1+gprof
It's wierd how some man pages for gprof describe this feature, but the
one on my local system doesn't mention it.
I'll see if I can link tsearch2 statically to resolve this question.
That'll work too...
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/
Show quoted text
Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.
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
On Fri, Jan 20, 2006 at 04:19:15PM -0500, Tom Lane wrote:
% 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
<snip>
So we gotta fix hemdistsign ...
lol! Yeah, I guess so. Pretty nasty loop. LOOPBIT will iterate 8*63=504
times and it's going to do silly bit handling on each and every
iteration.
Given that all it's doing is counting bits, a simple fix would be to
loop over bytes, use XOR and count ones. For extreme speedup create a
lookup table with 256 entries to give you the answer straight away...
Have a nice day,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/
Show quoted text
Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.
On Fri, Jan 20, 2006 at 10:37:54PM +0100, Martijn van Oosterhout wrote:
Given that all it's doing is counting bits, a simple fix would be to
loop over bytes, use XOR and count ones. For extreme speedup create a
lookup table with 256 entries to give you the answer straight away...
For extra obfscation:
unsigned v = (unsigned)c;
int num_bits = (v * 0x1001001001001ULL & 0x84210842108421ULL) % 0x1f;
(More more-or-less intelligent options at
http://graphics.stanford.edu/~seander/bithacks.html#CountBitsSetNaive :-) )
/* Steinar */
--
Homepage: http://www.sesse.net/
Martijn van Oosterhout <kleptog@svana.org> writes:
Given that all it's doing is counting bits, a simple fix would be to
loop over bytes, use XOR and count ones. For extreme speedup create a
lookup table with 256 entries to give you the answer straight away...
Yeah, I just finished doing that and got about a 20x overall speedup
(30-some seconds to build the index instead of 10 minutes). However,
hemdistsign is *still* 70% of the runtime after doing that. The problem
seems to be that gtsvector_picksplit is calling it an inordinate number
of times:
0.53 30.02 1649/1649 FunctionCall2 <cycle 2> [19]
[20]: 52.4 0.53 30.02 1649 gtsvector_picksplit [20] 29.74 0.00 23519673/33035195 hemdistsign [18] 0.14 0.00 22985469/22985469 hemdistcache [50] 0.12 0.00 268480/10030581 makesign [25] 0.02 0.00 270400/270400 fillcache [85] 0.00 0.00 9894/4077032 AllocSetAlloc [34] 0.00 0.00 9894/2787477 MemoryContextAlloc [69]
29.74 0.00 23519673/33035195 hemdistsign [18]
0.14 0.00 22985469/22985469 hemdistcache [50]
0.12 0.00 268480/10030581 makesign [25]
0.02 0.00 270400/270400 fillcache [85]
0.00 0.00 9894/4077032 AllocSetAlloc [34]
0.00 0.00 9894/2787477 MemoryContextAlloc [69]
(hemdistcache calls hemdistsign --- I think gprof is doing something
funny with tail-calls here, and showing hemdistsign as directly called
from gtsvector_picksplit when control really arrives through hemdistcache.)
The bulk of the problem is clearly in this loop, which performs O(N^2)
comparisons to find the two entries that are furthest apart in hemdist
terms:
for (k = FirstOffsetNumber; k < maxoff; k = OffsetNumberNext(k))
{
for (j = OffsetNumberNext(k); j <= maxoff; j = OffsetNumberNext(j))
{
if (k == FirstOffsetNumber)
fillcache(&cache[j], GETENTRY(entryvec, j));
size_waste = hemdistcache(&(cache[j]), &(cache[k]));
if (size_waste > waste)
{
waste = size_waste;
seed_1 = k;
seed_2 = j;
}
}
}
I wonder if there is a way to improve on that.
regards, tom lane
On Fri, Jan 20, 2006 at 04:50:17PM -0500, Tom Lane wrote:
I wonder if there is a way to improve on that.
Ooh, the farthest pair problem (in an N-dimensional vector space, though).
I'm pretty sure problems like this has been studied quite extensively in the
literature, although perhaps not with the same norm. It's known under both
"farthest pair" and "diameter", and probably others. I'm fairly sure it
should be solvable in at least O(n log n).
/* Steinar */
--
Homepage: http://www.sesse.net/
At 05:16 PM 1/20/2006, Steinar H. Gunderson wrote:
On Fri, Jan 20, 2006 at 04:50:17PM -0500, Tom Lane wrote:
I wonder if there is a way to improve on that.
Ooh, the farthest pair problem (in an N-dimensional vector space, though).
I'm pretty sure problems like this has been studied quite extensively in the
literature, although perhaps not with the same norm. It's known under both
"farthest pair" and "diameter", and probably others. I'm fairly sure it
should be solvable in at least O(n log n).
If the N-dimensional space is Euclidean (any <x, x+1> is the same
distance apart in dimension x), then finding the farthest pair can be
done in at least O(n).
If you do not want the actual distance and can create the proper data
structures, particularly if you can update them incrementally as you
generate pairs, it is often possible to solve this problem in O(lg n) or O(1).
I'll do some grinding.
Ron
On Fri, Jan 20, 2006 at 04:50:17PM -0500, Tom Lane wrote:
(hemdistcache calls hemdistsign --- I think gprof is doing something
funny with tail-calls here, and showing hemdistsign as directly called
from gtsvector_picksplit when control really arrives through hemdistcache.)
It may be the compiler. All these functions are declared static, which
gives the compiler quite a bit of leeway to rearrange code.
The bulk of the problem is clearly in this loop, which performs O(N^2)
comparisons to find the two entries that are furthest apart in hemdist
terms:
Ah. A while ago someone came onto the list asking about bit strings
indexing[1]http://archives.postgresql.org/pgsql-general/2005-11/msg00473.php. If I'd known tsearch worked like this I would have pointed
him to it. Anyway, before he went off to implement it he mentioned
"Jarvis-Patrick clustering", whatever that means.
Probably more relevent was this thread[2]http://archives.postgresql.org/pgsql-hackers/2005-11/msg01067.php on -hackers a while back with
pseudo-code[3]http://archives.postgresql.org/pgsql-hackers/2005-11/msg01069.php. How well it works, I don't know, it worked for him
evidently, he went away happy...
[1]: http://archives.postgresql.org/pgsql-general/2005-11/msg00473.php
[2]: http://archives.postgresql.org/pgsql-hackers/2005-11/msg01067.php
[3]: http://archives.postgresql.org/pgsql-hackers/2005-11/msg01069.php
Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/
Show quoted text
Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.
At 04:37 PM 1/20/2006, Martijn van Oosterhout wrote:
On Fri, Jan 20, 2006 at 04:19:15PM -0500, Tom Lane wrote:
% 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<snip>
So we gotta fix hemdistsign ...
lol! Yeah, I guess so. Pretty nasty loop. LOOPBIT will iterate 8*63=504
times and it's going to do silly bit handling on each and every
iteration.Given that all it's doing is counting bits, a simple fix would be to
loop over bytes, use XOR and count ones. For extreme speedup create a
lookup table with 256 entries to give you the answer straight away...
For an even more extreme speedup, don't most modern CPUs have an asm
instruction that counts the bits (un)set (AKA "population counting")
in various size entities (4b, 8b, 16b, 32b, 64b, and 128b for 64b
CPUs with SWAR instructions)?
Ron
On Fri, Jan 20, 2006 at 05:46:34PM -0500, Ron wrote:
For an even more extreme speedup, don't most modern CPUs have an asm
instruction that counts the bits (un)set (AKA "population counting")
in various size entities (4b, 8b, 16b, 32b, 64b, and 128b for 64b
CPUs with SWAR instructions)?
None in the x86 series that I'm aware of, at least.
You have instructions for finding the highest set bit, though.
/* Steinar */
--
Homepage: http://www.sesse.net/
