Re: [SQL] JOIN index/sequential select problem

On Wed, 12 May 1999, Tom Lane wrote:
> gjerde@icebox.org writes:
> > Then postgres is not guessing right.  Even tho the table only has 
> > ~200 rows, the query still takes forever to finish.  I have let it go for
> > a few minutes, and it still wasn't done..
> Something wrong there; even with a nested loop, it shouldn't take more
> than a few seconds to process that query.  Please dig into it a little
> more (do you have gprof?) and find where it's spending the time.

Yes, it definately takes too long.  I just let it run its course with
profiling on, and it took a good 25 minutes.

Compiling postgres with -pg created 2 gmon.out files.  One in postgres
home dir(/home/postgres/) and one in the database
directory(/home/postgres/data/base/parts).  The first one had very little
in it, while the second one is the one below, which seemed to be the right
stuff.

gprof says: %   cumulative   self              self     totaltime   seconds   seconds    calls  us/call  us/call  name
100.00      0.01     0.01        3  3333.33  3333.33  ValidatePgVersion 0.00      0.01     0.00 11745603     0.00
0.00 AllocSetAlloc 0.00      0.01     0.00 11745603     0.00     0.00  MemoryContextAlloc 0.00      0.01     0.00
11743401    0.00     0.00  PortalHeapMemoryAlloc 0.00      0.01     0.00 11743016     0.00     0.00  AllocSetFree 0.00
   0.01     0.00 11743016     0.00     0.00  MemoryContextFree 0.00      0.01     0.00 11741730     0.00     0.00
AllocSetContains0.00      0.01     0.00 11741730     0.00     0.00  PortalHeapMemoryFree 0.00      0.01     0.00
11741472    0.00     0.00  ExecEvalExpr   0.00      0.01     0.00  7828744     0.00     0.00  LockBuffer  0.00
0.01    0.00  7827998     0.00     0.00  fmgr_c 0.00      0.01     0.00  4145068     0.00     0.00  hash_search    0.00
    0.01     0.00  4135600     0.00     0.00  call_hash     0.00      0.01     0.00  4135235     0.00     0.00
tag_hash0.00      0.01     0.00  4110386     0.00     0.00  SpinAcquire 0.00      0.01     0.00  4110386     0.00
0.00 SpinRelease 0.00      0.01     0.00  3925111     0.00     0.00  BufferGetBlockNumber 0.00      0.01     0.00
3923168    0.00     0.00  BufTableLookup 0.00      0.01     0.00  3923168     0.00     0.00  BufferAlloc 0.00      0.01
   0.00  3923168     0.00     0.00  ReadBufferWithBufferLock 0.00      0.01     0.00  3923127     0.00     0.00
ReleaseBuffer0.00      0.01     0.00  3922903     0.00     0.00  ReadBuffer 0.00      0.01     0.00  3915548     0.00
 0.00  fmgr_info    0.00      0.01     0.00  3915548     0.00     0.00  fmgr_isbuiltin    0.00      0.01     0.00
3915387    0.00     0.00  _bt_checkkeys    0.00      0.01     0.00  3914991     0.00     0.00  _bt_step 0.00      0.01
  0.00  3914710     0.00     0.00  nocachegetattr 0.00      0.01     0.00  3914656     0.00     0.00  ExecEvalVar 0.00
   0.01     0.00  3914584     0.00     0.00  fmgr   0.00      0.01     0.00  3914247     0.00     0.00  ExecClearTuple
0.00     0.01     0.00  3914143     0.00     0.00  int4eq        0.00      0.01     0.00  3914032     0.00     0.00
ExecStoreTuple0.00      0.01     0.00  3913780     0.00     0.00  btgettuple  0.00      0.01     0.00  3913780     0.00
   0.00  index_getnext 0.00      0.01     0.00  3913589     0.00     0.00  HeapTupleSatisfiesSnapshot 0.00      0.01
0.00  3913589     0.00     0.00  IndexNext 0.00      0.01     0.00  3913570     0.00     0.00  FormRetrieveIndexResult
0.00     0.01     0.00  3913570     0.00     0.00  heap_fetch 0.00      0.01     0.00  3913516     0.00     0.00
_bt_next0.00      0.01     0.00  3913414     0.00     0.00  ExecMakeFunctionResult 0.00      0.01     0.00  3913413
0.00    0.00  ExecEvalFuncArgs 0.00      0.01     0.00  3913413     0.00     0.00  ExecEvalOper      0.00      0.01
0.00 3913413     0.00     0.00  ExecQualClause   0.00      0.01     0.00  3913391     0.00     0.00  ExecQual 0.00
0.01    0.00  3913381     0.00     0.00  _bt_restscan   0.00      0.01     0.00  3913380     0.00     0.00  DoMatch
0.00     0.01     0.00  3913380     0.00     0.00  fixedlen_like 0.00      0.01     0.00  3913380     0.00     0.00
like0.00      0.01     0.00  3913380     0.00     0.00  textlike      0.00      0.01     0.00  3840791     0.00
0.00 PinBuffer 0.00      0.01     0.00    85733     0.00     0.00  AddBufferToFreelist
 

On the other hand, I did have a backend close on me earlier today.  I
didn't notice the core file until now however.  The query(I think) that
made this was a very simple SELECT.  However, I was doing some other
queries at about the same time(the query with problems above)
Here's what gdb had to say: 
(gdb) bt
#0  0x40101111 in __kill ()
#1  0x40100d66 in raise (sig=6) at ../sysdeps/posix/raise.c:27
#2  0x40102447 in abort () at ../sysdeps/generic/abort.c:88
#3  0x80d734d in s_lock_stuck ()
#4  0x80d73c1 in s_lock ()
#5  0x80d6049 in WaitIO ()
#6  0x80d58a8 in BufferAlloc ()
#7  0x80d56ed in ReadBufferWithBufferLock ()
#8  0x80d5688 in ReadBuffer ()
#9  0x806c2f7 in heap_fetch ()
#10 0x80982f3 in IndexNext ()
#11 0x80946c9 in ExecScan ()
#12 0x8098410 in ExecIndexScan ()
#13 0x809313e in ExecProcNode ()
#14 0x8099694 in ExecNestLoop ()
#15 0x8093147 in ExecProcNode ()
#16 0x8092529 in ExecutePlan ()
#17 0x8091c2e in ExecutorRun ()

Thanks,
Ole Gjerde