Re: [GENERAL] Creation of tsearch2 index is very slow

[ 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]
[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]
[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]
[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]
[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]
[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]

Now that we have some data, we can start to think about how to improve
matters ...

            regards, tom lane