Re: issue with gininsert under very high load

On 02/12/2014 02:50 PM, Andres Freund wrote:
> On 2014-02-12 14:39:37 -0500, Andrew Dunstan wrote:
>> On investigation I found that a number of processes were locked waiting for
>> one wedged process to end its transaction, which never happened (this
>> transaction should normally take milliseconds). oprofile revealed that
>> postgres was spending 87% of its time in s_lock(), and strace on the wedged
>> process revealed that it was in a tight loop constantly calling select(). It
>> did not respond to a SIGTERM. I attached a debugger to the wedged process
>> and got this backtrace:
>>
>> #0 0x000000386a2eaf37 in semop () from /lib64/libc.so.6
>> #1 0x00000000006021a7 in PGSemaphoreLock ()
>> #2 0x00000000006463a1 in LWLockAcquire ()
>> #3 0x0000000000631997 in ReadBuffer_common ()
>> #4 0x00000000006322ee in ReadBufferExtended ()
>> #5 0x0000000000467475 in ginPrepareFindLeafPage ()
>> #6 0x000000000046663f in ginInsertItemPointers ()
>> #7 0x0000000000462adc in ginEntryInsert ()
>> #8 0x000000000046cad0 in ginInsertCleanup ()
>> #9 0x000000000046d7c6 in ginHeapTupleFastInsert ()
>> #10 0x0000000000462cfa in gininsert ()
>> #11 0x0000000000722b33 in FunctionCall6Coll ()
>> #12 0x000000000048bdff in index_insert ()
>> #13 0x0000000000587595 in ExecInsertIndexTuples ()
>> #14 0x00000000005948e1 in ExecModifyTable ()
>> #15 0x000000000057e718 in ExecProcNode ()
>> #16 0x000000000057d512 in standard_ExecutorRun ()
>> [...]
>>
>>
>>
>> Armed with this the client identified a single gin index (on an array of
>> text) that could have been involved, and on removing the index the problem
>> simply went away, and they have now been live on 9.3 for 36 hours without a
>> mishap.
>>
>> The client is attempting to create a self-contained reproducible test, but
>> understandably are not going to re-add the index to their production system.
>>
>> I'm not terribly familiar with the gin code, so I'm reporting this in the
>> hope that other people who are more familiar with it than I am might know
>> where to look for a potential race condition or other bug that might have
>> caused this.
> That's a deficiency of the gin fastupdate cache: a) it bases it's size
> on work_mem which usually makes it *far* too big b) it doesn't perform the
> cleanup in one go if it can get a suitable lock, but does independent
> locking for each entry. That usually leads to absolutely horrific
> performance under concurreny.
>
> The fix is usually to just turn FASTUPDATE off for all indexes. If it's
> done after the initial creation, the table should be vacuumed afterwards
> to flush it.
>
> There's previously been talk about changing the limits to something more
> reasonable but it got stalled in bikeshedding IIRC.
>

So this doesn't work just when it might be most useful?

cheers

andrew