Thread: LWLock deadlock and gdb advice

On Mon, Jun 29, 2015 at 5:37 PM, Jeff Janes <jeff.janes@gmail.com> wrote:
> Is there a way to use gdb to figure out who holds the lock they are waiting
> for?

Have you considered building with LWLOCK_STATS defined, and LOCK_DEBUG
defined? That might do it.

Otherwise, I suggest dereferencing the "l" argument to
LWLockAcquireWithVar() or something -- set the frame to "3" in your
example backtrace, using "f 3". Then, "p *l". You'll get the tranche
id there, and so on.

-- 
Peter Geoghegan

Jeff Janes wrote:

> I've gotten the LWLock deadlock again.  User backend 24841 holds the
> WALInsertLocks 7 and is blocked attempting to acquire 6 .  So it seems to
> be violating the lock ordering rules (although I don't see that rule
> spelled out in xlog.c)

Hmm, interesting -- pg_stat_statement is trying to re-do an operation
that involves updating a GIN index, while WAL-logging for the original
update is still ongoing, it seems.


> #0  0x0000003dcb6eaf27 in semop () from /lib64/libc.so.6
> #1  0x0000000000671aef in PGSemaphoreLock (sema=0x7f70e9e2a108) at
> pg_sema.c:387
> #2  0x00000000006d79ac in LWLockWaitForVar (lock=0x7f70e13df000,
> valptr=0x7f70e13df028, oldval=0, newval=0x7fffb33cbd48) at lwlock.c:1406
> #3  0x00000000004ee006 in WaitXLogInsertionsToFinish (upto=41590734848) at
> xlog.c:1576
> #4  0x00000000004ee94b in AdvanceXLInsertBuffer (upto=41594920960,
> opportunistic=<value optimized out>) at xlog.c:1888
> #5  0x00000000004f3c42 in GetXLogBuffer (ptr=41594920960) at xlog.c:1669
> #6  0x00000000004f40e7 in CopyXLogRecordToWAL (rdata=0x19bc920,
> fpw_lsn=<value optimized out>) at xlog.c:1313
> #7  XLogInsertRecord (rdata=0x19bc920, fpw_lsn=<value optimized out>) at
> xlog.c:1008
> #8  0x00000000004f7c6c in XLogInsert (rmid=13 '\r', info=32 ' ') at
> xloginsert.c:453
> #9  0x000000000047e210 in ginPlaceToPage (btree=0x7fffb33cc070,
> stack=0x1a5bfe0, insertdata=<value optimized out>, updateblkno=<value
> optimized out>, childbuf=0, buildStats=0x0)
>     at ginbtree.c:418
> #10 0x000000000047f50d in ginInsertValue (btree=0x7fffb33cc070,
> stack=0x1a5bfe0, insertdata=0x7fffb33cc0f0, buildStats=0x0) at
> ginbtree.c:748
> #11 0x0000000000475deb in ginEntryInsert (ginstate=0x7fffb33cc470,
> attnum=5544, key=1, category=<value optimized out>, items=0x7f70e10d9140,
> nitem=51, buildStats=0x0)
>     at gininsert.c:234
> #12 0x000000000048602c in ginInsertCleanup (ginstate=0x7fffb33cc470,
> vac_delay=<value optimized out>, stats=0x0) at ginfast.c:843
> #13 0x00000000004871b9 in ginHeapTupleFastInsert (ginstate=0x7fffb33cc470,
> collector=<value optimized out>) at ginfast.c:436
> #14 0x000000000047625a in gininsert (fcinfo=<value optimized out>) at
> gininsert.c:531
> #15 0x00000000007dc483 in FunctionCall6Coll (flinfo=<value optimized out>,
> collation=<value optimized out>, arg1=<value optimized out>, arg2=<value
> optimized out>,
>     arg3=<value optimized out>, arg4=<value optimized out>,
> arg5=140122789534360, arg6=0) at fmgr.c:1436
> #16 0x00000000004b2247 in index_insert (indexRelation=0x7f70e1190e60,
> values=0x7fffb33cef50, isnull=0x7fffb33cf050 "", heap_t_ctid=0x1a4a794,
> heapRelation=0x7f70e1185a98,
>     checkUnique=UNIQUE_CHECK_NO) at indexam.c:226
> #17 0x00000000005d2e67 in ExecInsertIndexTuples (slot=0x1a497f0,
> tupleid=0x1a4a794, estate=0x1a40768, noDupErr=0 '\000', specConflict=0x0,
> arbiterIndexes=0x0)
>     at execIndexing.c:384
> #18 0x00000000005f0161 in ExecUpdate (tupleid=0x7fffb33cf250, oldtuple=0x0,
> slot=0x1a497f0, planSlot=0x1a42498, epqstate=0x1a40a70, estate=0x1a40768,
> canSetTag=1 '\001')
>     at nodeModifyTable.c:978
> #19 0x00000000005f0b2a in ExecModifyTable (node=0x1a409d0) at
> nodeModifyTable.c:1436
> #20 0x00000000005d6cc8 in ExecProcNode (node=0x1a409d0) at
> execProcnode.c:389
> #21 0x00000000005d5402 in ExecutePlan (queryDesc=0x1a2b220,
> direction=<value optimized out>, count=0) at execMain.c:1549
> #22 standard_ExecutorRun (queryDesc=0x1a2b220, direction=<value optimized
> out>, count=0) at execMain.c:337
> #23 0x00007f70ea39af3b in pgss_ExecutorRun (queryDesc=0x1a2b220,
> direction=ForwardScanDirection, count=0) at pg_stat_statements.c:881
> #24 0x00000000006ea38f in ProcessQuery (plan=0x1a2b3d8,
> sourceText=0x1a2af68 "update foo set count=count+1 where text_array @> $1",
> params=0x1a2afe8, dest=<value optimized out>,
>     completionTag=0x7fffb33cf660 "") at pquery.c:185
> #25 0x00000000006ea5ec in PortalRunMulti (portal=0x19a6128, isTopLevel=1
> '\001', dest=0xc55020, altdest=0xc55020, completionTag=0x7fffb33cf660 "")
> at pquery.c:1279
> #26 0x00000000006eadb3 in PortalRun (portal=0x19a6128,
> count=9223372036854775807, isTopLevel=1 '\001', dest=0x1990630,
> altdest=0x1990630, completionTag=0x7fffb33cf660 "")
>     at pquery.c:816
> #27 0x00000000006e6ffb in exec_execute_message (portal_name=0x1990218 "",
> max_rows=9223372036854775807) at postgres.c:1988
> #28 0x00000000006e8c15 in PostgresMain (argc=<value optimized out>,
> argv=<value optimized out>, dbname=0x19a3210 "jjanes", username=<value
> optimized out>) at postgres.c:4088
> #29 0x00000000006855dd in BackendRun (argc=<value optimized out>,
> argv=<value optimized out>) at postmaster.c:4159
> #30 BackendStartup (argc=<value optimized out>, argv=<value optimized out>)
> at postmaster.c:3835
> #31 ServerLoop (argc=<value optimized out>, argv=<value optimized out>) at
> postmaster.c:1609
> #32 PostmasterMain (argc=<value optimized out>, argv=<value optimized out>)
> at postmaster.c:1254
> #33 0x0000000000610ab0 in main (argc=4, argv=0x1976cf0) at main.c:221


-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 06/30/2015 07:05 PM, Jeff Janes wrote:
> On Mon, Jun 29, 2015 at 11:28 PM, Jeff Janes <jeff.janes@gmail.com> wrote:
>
>> On Mon, Jun 29, 2015 at 5:55 PM, Peter Geoghegan <pg@heroku.com> wrote:
>>
>>> On Mon, Jun 29, 2015 at 5:37 PM, Jeff Janes <jeff.janes@gmail.com> wrote:
>>>> Is there a way to use gdb to figure out who holds the lock they are
>>> waiting
>>>> for?
>>>
>>> Have you considered building with LWLOCK_STATS defined, and LOCK_DEBUG
>>> defined? That might do it.
>>>
>>
>> I hadn't planned on running into this problem, so had not compiled
>> accordingly.
>>
>> I thought LOCK_DEBUG would produce too much output, but now I see it
>> doesn't print anything unless Trace_lwlocks is on (but it still makes more
>> info available to gdb, as Amit mentioned), so I think that should be OK.
>>
>> Since I messed up the gdb session causing the postmaster to SIGKILL all
>> the children and destroy the evidence, I'll repeat the run compiled with
>> LOCK_DEBUG and see what it looks like in the morning.
>>
>
> I've gotten the LWLock deadlock again.  User backend 24841 holds the
> WALInsertLocks 7 and is blocked attempting to acquire 6 .  So it seems to
> be violating the lock ordering rules (although I don't see that rule
> spelled out in xlog.c)
>
> The Checkpoint process, meanwhile, has acquired WALInsertLocks 0 through 6
> and is blocked on 7.
>
> I'm not sure where to go from here.

The user backend 24841 is waiting in a LWLockWaitForVar() call, on 
WALInsertLock 6, and oldval==0. The checkpointer is holding 
WALInsertLock 6, but it has set the insertingat value to PG_UINT64_MAX. 
The LWLockWaitForVar() call should not be blocked on that, because 0 != 
PG_UINT64_MAX.

Looks like the LWLock-scalability patch that made LWlock acquisiton to 
use atomic ops instead of a spinlock broke this. LWLockWaitForVar() is 
supposed to guarantee that it always wakes up from sleep, when the 
variable's value changes. But there is now a race condition in 
LWLockWaitForVar that wasn't there in 9.4:

>         if (mustwait)
>         {
>             /*
>              * Perform comparison using spinlock as we can't rely on atomic 64
>              * bit reads/stores.
>              */
> #ifdef LWLOCK_STATS
>             lwstats->spin_delay_count += SpinLockAcquire(&lock->mutex);
> #else
>             SpinLockAcquire(&lock->mutex);
> #endif
>
>             /*
>              * XXX: We can significantly optimize this on platforms with 64bit
>              * atomics.
>              */
>             value = *valptr;
>             if (value != oldval)
>             {
>                 result = false;
>                 mustwait = false;
>                 *newval = value;
>             }
>             else
>                 mustwait = true;
>             SpinLockRelease(&lock->mutex);
>         }
>         else
>             mustwait = false;
>
>         if (!mustwait)
>             break;                /* the lock was free or value didn't match */
>
>         /*
>          * Add myself to wait queue. Note that this is racy, somebody else
>          * could wakeup before we're finished queuing. NB: We're using nearly
>          * the same twice-in-a-row lock acquisition protocol as
>          * LWLockAcquire(). Check its comments for details.
>          */
>         LWLockQueueSelf(lock, LW_WAIT_UNTIL_FREE, false);

After the spinlock is released above, but before the LWLockQueueSelf() 
call, it's possible that another backend comes in, acquires the lock, 
changes the variable's value, and releases the lock again. In 9.4, the 
spinlock was not released until the process was queued.

Looking at LWLockAcquireWithVar(), it's also no longer holding the 
spinlock while it updates the Var. That's not cool either :-(.
- Heikki

On 06/30/2015 07:37 PM, Alvaro Herrera wrote:
> Jeff Janes wrote:
>
>> I've gotten the LWLock deadlock again.  User backend 24841 holds the
>> WALInsertLocks 7 and is blocked attempting to acquire 6 .  So it seems to
>> be violating the lock ordering rules (although I don't see that rule
>> spelled out in xlog.c)
>
> Hmm, interesting -- pg_stat_statement is trying to re-do an operation
> that involves updating a GIN index, while WAL-logging for the original
> update is still ongoing, it seems.

I don't think pg_stat_statement has anything to do with this. You can 
see from the backtrace that pg_stat_statement is enabled, as the call 
went through the pgss_ExecutorRun executor hook, but that's all.

- Heikki

On 2015-06-30 21:08:53 +0300, Heikki Linnakangas wrote:
> >            /*
> >             * XXX: We can significantly optimize this on platforms with 64bit
> >             * atomics.
> >             */
> >            value = *valptr;
> >            if (value != oldval)
> >            {
> >                result = false;
> >                mustwait = false;
> >                *newval = value;
> >            }
> >            else
> >                mustwait = true;
> >            SpinLockRelease(&lock->mutex);
> >        }
> >        else
> >            mustwait = false;
> >
> >        if (!mustwait)
> >            break;                /* the lock was free or value didn't match */
> >
> >        /*
> >         * Add myself to wait queue. Note that this is racy, somebody else
> >         * could wakeup before we're finished queuing. NB: We're using nearly
> >         * the same twice-in-a-row lock acquisition protocol as
> >         * LWLockAcquire(). Check its comments for details.
> >         */
> >        LWLockQueueSelf(lock, LW_WAIT_UNTIL_FREE, false);
> 
> After the spinlock is released above, but before the LWLockQueueSelf() call,
> it's possible that another backend comes in, acquires the lock, changes the
> variable's value, and releases the lock again. In 9.4, the spinlock was not
> released until the process was queued.

Hm. Right. A recheck of the value after the queuing should be sufficient
to fix? That's how we deal with the exact same scenarios for the normal
lock state, so that shouldn't be very hard to add.

> Looking at LWLockAcquireWithVar(), it's also no longer holding the spinlock
> while it updates the Var. That's not cool either :-(.

Hm. I'd somehow assumed holding the lwlock ought to be sufficient, but
it really isn't. This var stuff isn't fitting all that well into the
lwlock code.

Greetings,

Andres Freund

On 06/30/2015 10:09 PM, Andres Freund wrote:
> On 2015-06-30 21:08:53 +0300, Heikki Linnakangas wrote:
>>>             /*
>>>              * XXX: We can significantly optimize this on platforms with 64bit
>>>              * atomics.
>>>              */
>>>             value = *valptr;
>>>             if (value != oldval)
>>>             {
>>>                 result = false;
>>>                 mustwait = false;
>>>                 *newval = value;
>>>             }
>>>             else
>>>                 mustwait = true;
>>>             SpinLockRelease(&lock->mutex);
>>>         }
>>>         else
>>>             mustwait = false;
>>>
>>>         if (!mustwait)
>>>             break;                /* the lock was free or value didn't match */
>>>
>>>         /*
>>>          * Add myself to wait queue. Note that this is racy, somebody else
>>>          * could wakeup before we're finished queuing. NB: We're using nearly
>>>          * the same twice-in-a-row lock acquisition protocol as
>>>          * LWLockAcquire(). Check its comments for details.
>>>          */
>>>         LWLockQueueSelf(lock, LW_WAIT_UNTIL_FREE, false);
>>
>> After the spinlock is released above, but before the LWLockQueueSelf() call,
>> it's possible that another backend comes in, acquires the lock, changes the
>> variable's value, and releases the lock again. In 9.4, the spinlock was not
>> released until the process was queued.
>
> Hm. Right. A recheck of the value after the queuing should be sufficient
> to fix? That's how we deal with the exact same scenarios for the normal
> lock state, so that shouldn't be very hard to add.

Yeah. It's probably more efficient to not release the spinlock between 
checking the value and LWLockQueueSelf() though.

>> Looking at LWLockAcquireWithVar(), it's also no longer holding the spinlock
>> while it updates the Var. That's not cool either :-(.
>
> Hm. I'd somehow assumed holding the lwlock ought to be sufficient, but
> it really isn't. This var stuff isn't fitting all that well into the
> lwlock code.

I'll take a stab at fixing this tomorrow. I take the blame for not 
documenting the semantics of LWLockAcquireWithVar() and friends well 
enough...

- Heikki

On 2015-06-30 22:19:02 +0300, Heikki Linnakangas wrote:
> >Hm. Right. A recheck of the value after the queuing should be sufficient
> >to fix? That's how we deal with the exact same scenarios for the normal
> >lock state, so that shouldn't be very hard to add.
> 
> Yeah. It's probably more efficient to not release the spinlock between
> checking the value and LWLockQueueSelf() though.

Right now LWLockQueueSelf() takes spinlocks etc itself, and is used that
way in a bunch of callsites... So that'd be harder.  Additionally I'm
planning to get rid of the spinlocks around queuing (they show up as
bottlenecks in contended workloads), so it seems more future proof not
to assume that either way.  On top of that I think we should, when
available (or using the same type of fallback as for 32bit?), use 64 bit
atomics for the var anyway.

> I'll take a stab at fixing this tomorrow.

Thanks! Do you mean both or "just" the second issue?

Greetings,

Andres Freund

On 06/30/2015 11:24 PM, Andres Freund wrote:
> On 2015-06-30 22:19:02 +0300, Heikki Linnakangas wrote:
>>> Hm. Right. A recheck of the value after the queuing should be sufficient
>>> to fix? That's how we deal with the exact same scenarios for the normal
>>> lock state, so that shouldn't be very hard to add.
>>
>> Yeah. It's probably more efficient to not release the spinlock between
>> checking the value and LWLockQueueSelf() though.
>
> Right now LWLockQueueSelf() takes spinlocks etc itself, and is used that
> way in a bunch of callsites... So that'd be harder.  Additionally I'm
> planning to get rid of the spinlocks around queuing (they show up as
> bottlenecks in contended workloads), so it seems more future proof not
> to assume that either way.  On top of that I think we should, when
> available (or using the same type of fallback as for 32bit?), use 64 bit
> atomics for the var anyway.
>
>> I'll take a stab at fixing this tomorrow.
>
> Thanks! Do you mean both or "just" the second issue?

Both. Here's the patch.

Previously, LWLockAcquireWithVar set the variable associated with the
lock atomically with acquiring it. Before the lwlock-scalability
changes, that was straightforward because you held the spinlock anyway,
but it's a lot harder/expensive now. So I changed the way acquiring a
lock with a variable works. There is now a separate flag,
LW_FLAG_VAR_SET, which indicates that the current lock holder has
updated the variable. The LWLockAcquireWithVar function is gone - you
now just use LWLockAcquire(), which always clears the LW_FLAG_VAR_SET
flag, and you can call LWLockUpdateVar() after that if you want to set
the variable immediately. LWLockWaitForVar() always waits if the flag is
not set, i.e. it will not return regardless of the variable's value, if
the current lock-holder has not updated it yet.

This passes make check, but I haven't done any testing beyond that. Does
this look sane to you?

- Heikki

On 2015-07-16 PM 04:03, Jeff Janes wrote:
> On Wed, Jul 15, 2015 at 8:44 AM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> 
>>
>> Both. Here's the patch.
>>
>> Previously, LWLockAcquireWithVar set the variable associated with the lock
>> atomically with acquiring it. Before the lwlock-scalability changes, that
>> was straightforward because you held the spinlock anyway, but it's a lot
>> harder/expensive now. So I changed the way acquiring a lock with a variable
>> works. There is now a separate flag, LW_FLAG_VAR_SET, which indicates that
>> the current lock holder has updated the variable. The LWLockAcquireWithVar
>> function is gone - you now just use LWLockAcquire(), which always clears
>> the LW_FLAG_VAR_SET flag, and you can call LWLockUpdateVar() after that if
>> you want to set the variable immediately. LWLockWaitForVar() always waits
>> if the flag is not set, i.e. it will not return regardless of the
>> variable's value, if the current lock-holder has not updated it yet.
>>
>>
> I ran this for a while without casserts and it seems to work.  But with
> casserts, I get failures in the autovac process on the GIN index.
> 
> I don't see how this is related to the LWLock issue, but I didn't see it
> without your patch.  Perhaps the system just didn't survive long enough to
> uncover it without the patch (although it shows up pretty quickly).  It
> could just be an overzealous Assert, since the casserts off didn't show
> problems.
> 
> bt and bt full are shown below.
> 

I got a similar assert failure but with a btree index
(pg_attribute_relid_attnum_index). The backtrace looks like Jeff's:

(gdb) bt
#0  0x0000003969632625 in raise () from /lib64/libc.so.6
#1  0x0000003969633e05 in abort () from /lib64/libc.so.6
#2  0x000000000092eb9e in ExceptionalCondition (conditionName=0x9c2220
"!(((PageHeader) (page))->pd_special >= (__builtin_offsetof
(PageHeaderData, pd_linp)))",   errorType=0x9c0c41 "FailedAssertion", fileName=0x9c0c10 "nbtree.c",
lineNumber=903) at assert.c:54
#3  0x00000000004e02d8 in btvacuumpage (vstate=0x7fff2c7655f0, blkno=9,
orig_blkno=9) at nbtree.c:903
#4  0x00000000004e0067 in btvacuumscan (info=0x7fff2c765cd0,
stats=0x279f7d0, callback=0x668f6d <lazy_tid_reaped>,
callback_state=0x279e338, cycleid=49190)   at nbtree.c:821
#5  0x00000000004dfdde in btbulkdelete (fcinfo=0x7fff2c7657d0) at nbtree.c:676
#6  0x0000000000939769 in FunctionCall4Coll (flinfo=0x7fff2c765bb0,
collation=0, arg1=140733939342544, arg2=0, arg3=6721389, arg4=41542456) at
fmgr.c:1375
#7  0x00000000004d2a01 in index_bulk_delete (info=0x7fff2c765cd0,
stats=0x0, callback=0x668f6d <lazy_tid_reaped>, callback_state=0x279e338)
at indexam.c:690
#8  0x000000000066861d in lazy_vacuum_index (indrel=0x7fd40ab846f0,
stats=0x279e770, vacrelstats=0x279e338) at vacuumlazy.c:1367
#9  0x00000000006678a8 in lazy_scan_heap (onerel=0x274ec90,
vacrelstats=0x279e338, Irel=0x279e790, nindexes=2, scan_all=0 '\000') at
vacuumlazy.c:1098
#10 0x00000000006660f7 in lazy_vacuum_rel (onerel=0x274ec90, options=99,
params=0x27bdc88, bstrategy=0x27bdd18) at vacuumlazy.c:244
#11 0x0000000000665c1a in vacuum_rel (relid=1249, relation=0x7fff2c7662a0,
options=99, params=0x27bdc88) at vacuum.c:1388
#12 0x00000000006643ce in vacuum (options=99, relation=0x7fff2c7662a0,
relid=1249, params=0x27bdc88, va_cols=0x0, bstrategy=0x27bdd18,
isTopLevel=1 '\001')   at vacuum.c:293
#13 0x000000000075d23c in autovacuum_do_vac_analyze (tab=0x27bdc80,
bstrategy=0x27bdd18) at autovacuum.c:2807
#14 0x000000000075c632 in do_autovacuum () at autovacuum.c:2328
#15 0x000000000075b457 in AutoVacWorkerMain (argc=0, argv=0x0) at
autovacuum.c:1647
#16 0x000000000075b0a5 in StartAutoVacWorker () at autovacuum.c:1454
#17 0x000000000076f9cc in StartAutovacuumWorker () at postmaster.c:5261
#18 0x000000000076f28a in sigusr1_handler (postgres_signal_arg=10) at
postmaster.c:4918
#19 <signal handler called>
#20 0x00000039696e1353 in __select_nocancel () from /lib64/libc.so.6
#21 0x000000000076ace7 in ServerLoop () at postmaster.c:1582
#22 0x000000000076a538 in PostmasterMain (argc=3, argv=0x26f9330) at
postmaster.c:1263
#23 0x00000000006c1c2e in main (argc=3, argv=0x26f9330) at main.c:223

Thanks,
Amit

Hi,

On 2015-07-19 11:49:14 -0700, Jeff Janes wrote:
> After applying this patch to commit fdf28853ae6a397497b79f, it has survived
> testing long enough to convince that this fixes the problem.

What was the actual workload breaking with the bug? I ran a small
variety and I couldn't reproduce it yet. I'm not saying there's no bug,
I just would like to be able to test my version of the fixes...

Andres

Hi,

Finally getting to this.

On 2015-07-15 18:44:03 +0300, Heikki Linnakangas wrote:
> Previously, LWLockAcquireWithVar set the variable associated with the lock
> atomically with acquiring it. Before the lwlock-scalability changes, that
> was straightforward because you held the spinlock anyway, but it's a lot
> harder/expensive now. So I changed the way acquiring a lock with a variable
> works. There is now a separate flag, LW_FLAG_VAR_SET, which indicates that
> the current lock holder has updated the variable. The LWLockAcquireWithVar
> function is gone - you now just use LWLockAcquire(), which always clears the
> LW_FLAG_VAR_SET flag, and you can call LWLockUpdateVar() after that if you
> want to set the variable immediately.
>
> This passes make check, but I haven't done any testing beyond that. Does
> this look sane to you?

The prime thing I dislike about the patch is how long it now holds the
spinlock in WaitForVar. I don't understand why that's necessary? There's
no need to hold a spinlock until after the  mustwait = (pg_atomic_read_u32(&lock->state) & LW_VAL_EXCLUSIVE) != 0;
unless I miss something?

In an earlier email you say:
> After the spinlock is released above, but before the LWLockQueueSelf() call,
> it's possible that another backend comes in, acquires the lock, changes the
> variable's value, and releases the lock again. In 9.4, the spinlock was not
> released until the process was queued.

But that's not a problem. The updater in that case will have queued a
wakeup for all waiters, including WaitForVar()?

I'll try to reproduce the problem now. But I do wonder if it's possibly
just the missing spinlock during the update.

Andres

On 07/29/2015 02:39 PM, Andres Freund wrote:
> On 2015-07-15 18:44:03 +0300, Heikki Linnakangas wrote:
>> Previously, LWLockAcquireWithVar set the variable associated with the lock
>> atomically with acquiring it. Before the lwlock-scalability changes, that
>> was straightforward because you held the spinlock anyway, but it's a lot
>> harder/expensive now. So I changed the way acquiring a lock with a variable
>> works. There is now a separate flag, LW_FLAG_VAR_SET, which indicates that
>> the current lock holder has updated the variable. The LWLockAcquireWithVar
>> function is gone - you now just use LWLockAcquire(), which always clears the
>> LW_FLAG_VAR_SET flag, and you can call LWLockUpdateVar() after that if you
>> want to set the variable immediately.
>>
>> This passes make check, but I haven't done any testing beyond that. Does
>> this look sane to you?
>
> The prime thing I dislike about the patch is how long it now holds the
> spinlock in WaitForVar. I don't understand why that's necessary? There's
> no need to hold a spinlock until after the
>     mustwait = (pg_atomic_read_u32(&lock->state) & LW_VAL_EXCLUSIVE) != 0;
> unless I miss something?
>
> In an earlier email you say:
>> After the spinlock is released above, but before the LWLockQueueSelf() call,
>> it's possible that another backend comes in, acquires the lock, changes the
>> variable's value, and releases the lock again. In 9.4, the spinlock was not
>> released until the process was queued.
>
> But that's not a problem. The updater in that case will have queued a
> wakeup for all waiters, including WaitForVar()?

If you release the spinlock before LWLockQueueSelf(), then no. It's 
possible that the backend you wanted to wait for updates the variable's 
value before you've queued up. Or even releases the lock, and it gets 
re-acquired by another backend, before you've queued up.

Or are you thinking of just moving the SpinLockRelease to after 
LWLockQueueSelf(), i.e. to the other side of the "mustwait = ..." line? 
That'd probably be ok.

- Heikki

On 2015-07-29 14:55:54 +0300, Heikki Linnakangas wrote:
> On 07/29/2015 02:39 PM, Andres Freund wrote:
> >In an earlier email you say:
> >>After the spinlock is released above, but before the LWLockQueueSelf() call,
> >>it's possible that another backend comes in, acquires the lock, changes the
> >>variable's value, and releases the lock again. In 9.4, the spinlock was not
> >>released until the process was queued.
> >
> >But that's not a problem. The updater in that case will have queued a
> >wakeup for all waiters, including WaitForVar()?
> 
> If you release the spinlock before LWLockQueueSelf(), then no. It's possible
> that the backend you wanted to wait for updates the variable's value before
> you've queued up. Or even releases the lock, and it gets re-acquired by
> another backend, before you've queued up.

For normal locks the equivalent problem is solved by re-checking wether
a conflicting lock is still held after enqueuing. Why don't we do the
same here? Doing it that way has the big advantage that we can just
remove the spinlocks entirely on platforms with atomic 64bit
reads/writes.

Greetings,

Andres Freund

On 07/29/2015 03:08 PM, Andres Freund wrote:
> On 2015-07-29 14:55:54 +0300, Heikki Linnakangas wrote:
>> On 07/29/2015 02:39 PM, Andres Freund wrote:
>>> In an earlier email you say:
>>>> After the spinlock is released above, but before the LWLockQueueSelf() call,
>>>> it's possible that another backend comes in, acquires the lock, changes the
>>>> variable's value, and releases the lock again. In 9.4, the spinlock was not
>>>> released until the process was queued.
>>>
>>> But that's not a problem. The updater in that case will have queued a
>>> wakeup for all waiters, including WaitForVar()?
>>
>> If you release the spinlock before LWLockQueueSelf(), then no. It's possible
>> that the backend you wanted to wait for updates the variable's value before
>> you've queued up. Or even releases the lock, and it gets re-acquired by
>> another backend, before you've queued up.
>
> For normal locks the equivalent problem is solved by re-checking wether
> a conflicting lock is still held after enqueuing. Why don't we do the
> same here? Doing it that way has the big advantage that we can just
> remove the spinlocks entirely on platforms with atomic 64bit
> reads/writes.

Ah, ok, that should work, as long as you also re-check the variable's 
value after queueing. Want to write the patch, or should I?

- Heikki

On 2015-07-29 15:14:23 +0300, Heikki Linnakangas wrote:
> Ah, ok, that should work, as long as you also re-check the variable's value
> after queueing. Want to write the patch, or should I?

I'll try. Shouldn't be too hard.

Andres

On 2015-07-29 14:22:23 +0200, Andres Freund wrote:
> On 2015-07-29 15:14:23 +0300, Heikki Linnakangas wrote:
> > Ah, ok, that should work, as long as you also re-check the variable's value
> > after queueing. Want to write the patch, or should I?
>
> I'll try. Shouldn't be too hard.

What do you think about something roughly like the attached?

- Andres

On 2015-07-29 09:23:32 -0700, Jeff Janes wrote:
> On Tue, Jul 28, 2015 at 9:06 AM, Jeff Janes <jeff.janes@gmail.com> wrote:
> I've reproduced it again against commit b2ed8edeecd715c8a23ae462.
> 
> It took 5 hours on a 8 core "Intel(R) Xeon(R) CPU E5-2650".
> 
> I also reproduced it in 3 hours on the same machine with both JJ_torn_page
> and JJ_xid set to zero (i.e. turned off, no induced crashes), so the
> fault-injection patch should not be necessary to get the issue..

Hm, that's a single socket or dual socket E5-2650 system? That CPU
itself has 8 cores, and can work in a dual socket system, that's why I
ask.

<div dir="ltr"><div class="gmail_extra"><div class="gmail_quote">On Wed, Jul 29, 2015 at 9:26 AM, Andres Freund <span
dir="ltr"><<ahref="mailto:andres@anarazel.de" target="_blank">andres@anarazel.de</a>></span> wrote:<br
/><blockquoteclass="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">On 2015-07-29
09:23:32-0700, Jeff Janes wrote:<br /><span class="">> On Tue, Jul 28, 2015 at 9:06 AM, Jeff Janes <<a
href="mailto:jeff.janes@gmail.com">jeff.janes@gmail.com</a>>wrote:<br /> > I've reproduced it again against
commitb2ed8edeecd715c8a23ae462.<br /> ><br /> > It took 5 hours on a 8 core "Intel(R) Xeon(R) CPU E5-2650".<br />
><br/> > I also reproduced it in 3 hours on the same machine with both JJ_torn_page<br /> > and JJ_xid set to
zero(i.e. turned off, no induced crashes), so the<br /> > fault-injection patch should not be necessary to get the
issue..<br/><br /></span>Hm, that's a single socket or dual socket E5-2650 system? That CPU<br /> itself has 8 cores,
andcan work in a dual socket system, that's why I<br /> ask.<br /></blockquote></div><br /></div><div
class="gmail_extra">Itis a virtual machine, and I think a property of the VM software is that any given virtual machine
canonly run on one socket of the underlying hardware.  The real machine is dual socket, though.</div><div
class="gmail_extra"><br/></div><div class="gmail_extra">Cheers,</div><div class="gmail_extra"><br /></div><div
class="gmail_extra">Jeff</div></div>

On 07/29/2015 04:10 PM, Andres Freund wrote:
> On 2015-07-29 14:22:23 +0200, Andres Freund wrote:
>> On 2015-07-29 15:14:23 +0300, Heikki Linnakangas wrote:
>>> Ah, ok, that should work, as long as you also re-check the variable's value
>>> after queueing. Want to write the patch, or should I?
>>
>> I'll try. Shouldn't be too hard.
>
> What do you think about something roughly like the attached?

Hmm. Imagine this:

Backend A has called LWLockWaitForVar(X) on a lock, and is now waiting 
on it. The lock holder releases the lock, and wakes up A. But before A 
wakes up and sees that the lock is free, another backend acquires the 
lock again. It runs LWLockAcquireWithVar to the point just before 
setting the variable's value. Now A wakes up, sees that the lock is 
still (or again) held, and that the variable's value still matches the 
old one, and goes back to sleep. The new lock holder won't wake it up 
until it updates the value again, or to releases the lock.

I think that's OK given the current usage of this in WALInsertLocks, but 
it's scary. At the very least you need comments to explain that race 
condition. You didn't like the new LW_FLAG_VAR_SET flag and the API 
changes I proposed? That eliminates the race condition.

Either way, there is a race condition that if the new lock holder sets 
the variable to the *same* value as before, the old waiter won't 
necessarily wake up even though the lock was free or had a different 
value in between. But that's easier to explain and understand than the 
fact that the value set by LWLockAcquireWithVar() might not be seen by a 
waiter, until you release the lock or update it again.

Another idea is to have LWLockAcquire check the wait queue after setting 
the variable, and wake up anyone who's already queued up. You could just 
call LWLockUpdateVar() from LWLockAcquireCommon to set the variable. I 
would prefer the approach from my previous patch more, though. That 
would avoid having to acquire the spinlock in LWLockAcquire altogether, 
and I actually like the API change from that independently from any 
correctness issues.

The changes in LWLockWaitForVar() and LWLockConflictsWithVar() seem OK 
in principle. You'll want to change LWLockConflictsWithVar() so that the 
spinlock is held only over the "value = *valptr" line, though; the other 
stuff just modifies local variables and don't need to be protected by 
the spinlock. Also, when you enter LWLockWaitForVar(), you're checking 
if the lock is held twice in a row; first at the top of the function, 
and again inside LWLockConflictsWithVar. You could just remove the 
"quick test" at the top.

- Heikki

On 2015-07-29 20:23:24 +0300, Heikki Linnakangas wrote:
> Backend A has called LWLockWaitForVar(X) on a lock, and is now waiting on
> it. The lock holder releases the lock, and wakes up A. But before A wakes up
> and sees that the lock is free, another backend acquires the lock again. It
> runs LWLockAcquireWithVar to the point just before setting the variable's
> value. Now A wakes up, sees that the lock is still (or again) held, and that
> the variable's value still matches the old one, and goes back to sleep. The
> new lock holder won't wake it up until it updates the value again, or to
> releases the lock.

I'm not sure whether this observation is about my patch or the general
lwlock variable mechanism. In my opinion that behaviour exists today
both in 9.4 and 9.5.

But I think that's fine because that "race" seems pretty
fundamental. After all, you could have called LWLockWaitForVar() just
after the second locker had set the variable to the same value.


> You didn't like the new LW_FLAG_VAR_SET flag and the API changes I
> proposed?

I do slightly dislike the additional bit of math in AttemptLock. But
what I really disliked about the patch is the reliance on holding the
spinlock over longer times and conditionally acquiring spinlocks.  I
didn't see a need for the flags change to fix the issue at hand, that's
why I didn't incorporate it. I'm not fundamentally against it.

> Either way, there is a race condition that if the new lock holder sets the
> variable to the *same* value as before, the old waiter won't necessarily
> wake up even though the lock was free or had a different value in between.
> But that's easier to explain and understand than the fact that the value set
> by LWLockAcquireWithVar() might not be seen by a waiter, until you release
> the lock or update it again.

I can't really se a use for the API that'd allow that and care about the
waits. Because quite fundamentally you could just started waiting after
the variable was set to the value at the same time.

> Another idea is to have LWLockAcquire check the wait queue after setting the
> variable, and wake up anyone who's already queued up.

Ugh, not a fan of that.

> The changes in LWLockWaitForVar() and LWLockConflictsWithVar() seem OK in
> principle. You'll want to change LWLockConflictsWithVar() so that the
> spinlock is held only over the "value = *valptr" line, though; the other
> stuff just modifies local variables and don't need to be protected by the
> spinlock.

good point.,

> Also, when you enter LWLockWaitForVar(), you're checking if the
> lock is held twice in a row; first at the top of the function, and again
> inside LWLockConflictsWithVar. You could just remove the "quick test" at the
> top.

Yea, I was thinking about removing it. The first check was there
previously, so I left it in place. We do execute a bit more code once
we've disabled interrupts (extraWaits, re-enabling interrupts). I don't
think it'll matter much, but it seemed like an independent thing.

Greetings,

Andres Freund

On 07/29/2015 09:35 PM, Andres Freund wrote:
> On 2015-07-29 20:23:24 +0300, Heikki Linnakangas wrote:
>> Backend A has called LWLockWaitForVar(X) on a lock, and is now waiting on
>> it. The lock holder releases the lock, and wakes up A. But before A wakes up
>> and sees that the lock is free, another backend acquires the lock again. It
>> runs LWLockAcquireWithVar to the point just before setting the variable's
>> value. Now A wakes up, sees that the lock is still (or again) held, and that
>> the variable's value still matches the old one, and goes back to sleep. The
>> new lock holder won't wake it up until it updates the value again, or to
>> releases the lock.
>
> I'm not sure whether this observation is about my patch or the general
> lwlock variable mechanism. In my opinion that behaviour exists today
> both in 9.4 and 9.5.

In 9.4, LWLockAcquire holds the spinlock when it marks the lock as held, 
until it has updated the variable. And LWLockWaitForVar() holds the 
spinlock when it checks that the lock is held and that the variable's 
value matches. So it cannot happen on 9.4.

To reiterate, with 9.5, it's possible that a backend is sleeping in 
LWLockWaitForVar(oldvar=123), even though the lock is currently held by 
another backend with value 124. That seems wrong, or surprising at the 
very least.

> But I think that's fine because that "race" seems pretty
> fundamental. After all, you could have called LWLockWaitForVar() just
> after the second locker had set the variable to the same value.

I'm not talking about setting it to the same value. I'm talking about 
setting it to a different value. (I talked about setting it to the same 
value later in the email, and I agree that's a pretty fundamental 
problem and exists with 9.4 as well).

- Heikki

On 2015-07-30 17:36:52 +0300, Heikki Linnakangas wrote:
> In 9.4, LWLockAcquire holds the spinlock when it marks the lock as held,
> until it has updated the variable. And LWLockWaitForVar() holds the spinlock
> when it checks that the lock is held and that the variable's value matches.
> So it cannot happen on 9.4.

The first paragraph talked about "the same value", but that was just
referring to it not yet having been cleared i think...

> To reiterate, with 9.5, it's possible that a backend is sleeping in
> LWLockWaitForVar(oldvar=123), even though the lock is currently held by
> another backend with value 124. That seems wrong, or surprising at the very
> least.

With my patch that can't really happen that way though? The value is
re-checked after queuing. If it has changed by then we're done. And if
it hasn't yet changed we're guaranteed to be woken up once it's being
changed?


I generaly don't mind adding some sort of flag clearing or such, but I'd
rather not have it in the retry loop in the general LWLockAttemptLock
path - I found that very small amounts of instructions in there have a
measurable impact.

Greetings,

Andres Freund

On 2015-07-30 09:03:01 -0700, Jeff Janes wrote:
> On Wed, Jul 29, 2015 at 6:10 AM, Andres Freund <andres@anarazel.de> wrote:
> > What do you think about something roughly like the attached?
> >
> 
> I've not evaluated the code, but applying it does solve the problem I was
> seeing.

Cool, thanks for testing! How long did you run the test and how long did
it, on average, previously take for the issue to occur?

Regards,

Andres

On 07/30/2015 09:14 PM, Andres Freund wrote:
> On 2015-07-30 17:36:52 +0300, Heikki Linnakangas wrote:
>> In 9.4, LWLockAcquire holds the spinlock when it marks the lock as held,
>> until it has updated the variable. And LWLockWaitForVar() holds the spinlock
>> when it checks that the lock is held and that the variable's value matches.
>> So it cannot happen on 9.4.
>
> The first paragraph talked about "the same value", but that was just
> referring to it not yet having been cleared i think...
>
>> To reiterate, with 9.5, it's possible that a backend is sleeping in
>> LWLockWaitForVar(oldvar=123), even though the lock is currently held by
>> another backend with value 124. That seems wrong, or surprising at the very
>> least.
>
> With my patch that can't really happen that way though? The value is
> re-checked after queuing. If it has changed by then we're done. And if
> it hasn't yet changed we're guaranteed to be woken up once it's being
> changed?

Ok, let me try explaining it again. With your patch, 
LWLockAcquireWithVar looks like this (simplified, assuming the lock is 
free):

1. Set LW_VAL_EXCLUSIVE
3. (Acquire spinlock) Set *valptr = val (Release spinlock)

LWLockWaitForVar looks like this:

1. Check if lock is free
2. (Acquire Spinlock) Read *valptr, compare with oldval (Release spinlock)
3. LWLockQueueSelf
4. Re-check that *valptr is still equal to oldval
5. sleep.

This is the race condition:

Backend A            Backend B
---------            ---------
LWLockAcquireWithVar(123)  Set LW_VAL_EXCLUSIVE  Set *valptr = 123            LWLockWaitForVar(123)              See
thatthe lock is held              Read *valptr, it matches              LWLockQueueSelf
 
LWLockRelease()
LWLockAcquireWithVar(124)  Set LW_VAL_EXCLUSIVE              wakes up              See that the lock is still/again
held             Read *valptr, it's still 123              LWLockQueueSelf              Re-check that *valptr is still
123.             go to sleep.  Set *valptr = 124
 


Now, Backend B's LWLockWaitForVar(123) call is sleeping, even though the 
lock was free'd and reacquired with different value, 124. It won't wake 
up until A updates the value or releases the lock again.

This was not possible in 9.4. It was possible in 9.4 too when the value 
was same in both LWLockAcquireWithVar() calls, and I think that's 
acceptable, but not when the values differ.

> I generaly don't mind adding some sort of flag clearing or such, but I'd
> rather not have it in the retry loop in the general LWLockAttemptLock
> path - I found that very small amounts of instructions in there have a
> measurable impact.

I doubt clearing a bit would matter there, although you might have a 
better instinct on that...

- Heikki

Hi Jeff, Heikki,

On 2015-07-31 09:48:28 -0700, Jeff Janes wrote:
> I had run it for 24 hours, while it usually took less than 8 hours to look
> up before.  I did see it within a few minutes one time when I checked out a
> new HEAD and then forgot to re-apply your or Heikki's patch.
> 
> But now I've got the same situation again, after 15 hours, with your
> patch.  This is probably all down to luck.  The only differences that I can
> think of is that I advanced the base to e8e86fbc8b3619da54c, and turned on
> JJ_vac and set log_autovacuum_min_duration=0.

It's quite possible that you hit the remaining race-condition that
Heikki was talking about. So that'd make it actually likely to be hit
slightly later - but as you say this is just a game of chance.

I've attached a version of the patch that should address Heikki's
concern. It imo also improves the API and increases debuggability by not
having stale variable values in the variables anymore. (also attached is
a minor optimization that Heikki has noticed)

I plan to commit the patch tomorrow, so it's included in alpha2.

Regards,

Andres

On 2015-08-02 17:04:07 +0200, Andres Freund wrote:
> I've attached a version of the patch that should address Heikki's
> concern. It imo also improves the API and increases debuggability by not
> having stale variable values in the variables anymore. (also attached is
> a minor optimization that Heikki has noticed)

...

Andres Freund <andres@anarazel.de> writes:
> I plan to commit the patch tomorrow, so it's included in alpha2.

Please try to commit anything you want in alpha2 *today*.  I'd
prefer to see some successful buildfarm cycles on such patches
before we wrap.
        regards, tom lane

On 2015-08-02 12:33:06 -0400, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> > I plan to commit the patch tomorrow, so it's included in alpha2.
> 
> Please try to commit anything you want in alpha2 *today*.  I'd
> prefer to see some successful buildfarm cycles on such patches
> before we wrap.

Ok, will do that.

On 2015-08-05 11:22:55 -0700, Jeff Janes wrote:
> On Sun, Aug 2, 2015 at 8:05 AM, Andres Freund <andres@anarazel.de> wrote:
> 
> > On 2015-08-02 17:04:07 +0200, Andres Freund wrote:
> > > I've attached a version of the patch that should address Heikki's
> > > concern. It imo also improves the API and increases debuggability by not
> > > having stale variable values in the variables anymore. (also attached is
> > > a minor optimization that Heikki has noticed)
> >
> >
> I've run these (from your git commit) for over 60 hours with no problem, so
> I think it's solved.

Cool! Thanks for the testing.

> If there are still problems, hopefully they will come out in other tests.
> I don't know why the gin test was efficient at provoking the problem while
> none of the other ones (btree-upsert, gist, brin, btree-foreign key,
> btree-prepare transaction) I've played around with.  Perhaps it is just due
> to the amount of WAL which gin generates.

I'm not sure either... I've been able to reproduce a version of the
issue by judiciously sprinkling pg_usleep()'s over the code.

Regards,

Andres