Re: Problem analyzing performance of query - Mailing list pgsql-general

Tom Lane <tgl@sss.pgh.pa.us> writes:

> Clear?  It'd be nice to have more infrastructure for debugging plpgsql
> code, but so far no one's got round to building any :-(

Thank you. Very useful.

Though one of my worries was that there was some cached plan in the plpgsql.
What might be useful not just for plpgsql but for debugging other applications
would be a "trace" functionality like Oracle's. It could be as simple as a guc
variable which caused all queries to run under EXPLAIN ANALYZE and dumped the
results somewhere for later analysis.


As it happens I've narrowed the problem down and it wasn't related to any
planning at all. I was running EXPLAIN ANALYZE on only the SELECT portion of
the query but the full query was actually an "INSERT INTO foo () (SELECT ...)"
Apparently the INSERT side of it was taking 90% of the time.

Dropping a few gist indexes I was experimenting with have sped it up tenfold.

Now I'm wondering whether it's inevitable slow down of maintaining these
indexes or if something else was wrong. The gist indexes are not something I'm
using currently, but I may need them in the future to deal with larger
datasets.

This table is a pre-generated "cache" of denormalized data. It's periodically
truncated and regenerated. Perhaps each time I truncated it the gist indexes
accumulated dead pages?

Most rows are quite small but there are a few large rows (large integer
arrays) perhaps they caused the gist indexes using gist__intbig_ops to have to
do lots of extra work? How do I tell if the rows are getting toasted?

I did run this under profiling and the gprof output didn't seem to be pointing
the finger at gist functions. A significant amount of time was spent in them
to be sure, but not 90%. That's what initially led me astray or I would have
checked this much earlier.

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
 14.66     14.54    14.54  6327634     0.00     0.00  FunctionCall3
  6.42     20.91     6.37    96792     0.00     0.00  gistchoose
  4.43     25.31     4.40       26     0.17     0.17  ArrayGetNItems
  3.59     28.87     3.56   450164     0.00     0.00  MemoryContextAllocZero
  3.38     32.22     3.35  9505045     0.00     0.00  AllocSetFreeIndex
  2.93     35.12     2.91   181680     0.00     0.00  ExecMakeFunctionResultNoSets
  2.41     37.51     2.39  6431187     0.00     0.00  gistdentryinit
  2.28     39.77     2.26  5320723     0.00     0.00  AllocSetAlloc
  2.24     41.99     2.22  3294701     0.00     0.00  tas
  2.12     44.09     2.10   671001     0.00     0.00  hash_search
  1.71     45.79     1.70  1538836     0.00     0.00  _bt_compare
  1.47     47.25     1.46  1098578     0.00     0.00  nocachegetattr
  1.41     48.65     1.40  1478208     0.00     0.00  ExecEvalVar
  1.40     50.04     1.39   597373     0.00     0.00  StrategyBufferLookup
  1.29     51.31     1.28   769755     0.00     0.00  comparetup_heap
  1.14     52.44     1.13  5548263     0.00     0.00  gistpenalty
  1.11     53.55     1.11    28058     0.00     0.00  XLogInsert
  1.08     54.62     1.07  6687057     0.00     0.00  FunctionCall1
  1.06     55.67     1.05   641646     0.00     0.00  hash_any
  1.06     56.72     1.05    53305     0.00     0.00  gistlayerinsert
  1.04     57.75     1.04   475840     0.00     0.00  gistDeCompressAtt
  1.04     58.78     1.03   991639     0.00     0.00  AllocSetReset
  1.04     59.81     1.03   295968     0.00     0.00  ExecTargetList


[That's 60% of the time already]



--
greg