Sled: Transactions are deadlocking at insert_inner

[D1plo1d]

Transactions are deadlocking inside of commit and never returning in my application. LLDB shows the thread as stuck on this line:

while self.tree.insert_inner(k, v_opt.clone(), &mut guard)?.is_err()
{
}

Source things: https://github.com/spacejam/sled/blob/master/src/transaction.rs#L364

1. expected result: I expect TransactionTree::commit to always return a result.
2. actual result: TransactionTree::commit intermittently blocks until I kill the application.
3. sled version: 0.34.2 + some small error handling experiments: https://github.com/D1plo1d/sled/tree/53d0e30a749f27fb808101730f1794a5f85b6216
4. rustc version: rustc 1.44.1 (c7087fe00 2020-06-17)
5. operating system: Ubuntu 20.04
6. minimal code sample that helps to reproduce the issue: Intermittent issue. TBH I could use a hand figuring out how to reliably reproduce my issue.
7. logs, panic messages, stack traces: Not sure what would be helpful here (please let me know!). I added a couple trace! macros to commit and observed that the commit started but never finished.

[D1plo1d]

I tried adding a trace! to that while loop so I could see what error we're getting and now it's not doing it any more. Very unsure about this one - hoping I can get it to happen again with RUST_LOG=trace.

[spacejam]

Could you please supply the additional information from the bug template, to help track down what may have happened?

[D1plo1d]

Will do - sorry for the delay I think I'll have time to give this a proper look into this this week.

[D1plo1d]

@spacejam: I've filled in what I have. If there's more that I can do to help let please me know.

I have a note here that the deadlock was shown by LLDB to be in the line sender.send(rx).is_err() { in subscriber.rs and that in turn calls self.mu.lock(); in threadpool.rs. Is there anything that could cause the threadpool::Queue to permanently lock?

edit: The more I re-read threadpool.rs the more confused I become. All the mutex locks and unlocks seems to makes sense to me.

[spacejam]

@D1plo1d thanks for the additional info! That should help to track this down quickly :)

[D1plo1d]

@spacejam Appreciate it! I'm giving this my best unqualified debugging attempt XD

Condvar will always perform an unfair unlock when releasing the mutex before a wait.

Source: https://github.com/Amanieu/parking_lot/issues/238

I stumbled upon that in Parkinglot's issues. Could Condvar's wait unfairness be related to this?

[spacejam]

@D1plo1d are you able to post more of the stacktraces from lldb? At this point I'm assuming it has something to do with an unexpected interaction between transactional code and subscriptions, which are currently an under-tested interaction point.

I don't think fairness should be an issue, because during testing we do all kinds of randomized sleeping that usually shakes out those kinds of bugs pretty quickly, but it's always a possibility.

[D1plo1d]

transactional code and subscriptions

Oh wow, yes that sounds exactly like my codebase. It's all transactions and subscriptions.

I don't think fairness should be an issue, because during testing we do all kinds of randomized sleeping that usually shakes out those kinds of bugs pretty quickly, but it's always a possibility.

Appreciate that, I'll try to focus on subscriptions + transactions interactions.

are you able to post more of the stacktraces from lldb?

I very sadly did not take a screenshot when I had LLDB open. I can try getting it to happen in LLDB again but it has been happening less frequently (AFAIK it was once last week). Might not be able to get another stack trace easily but I will try.

Edit: It has been happening less frequently since some unknown change in my code. I'm not sure what triggered it. It used to happen multiple times a day and now it's once a week.

[spacejam]

Ok, I think the fastest way to get more info might be to add some subscription threads into some of the intense concurrent transaction tests to try to recreate hopefully a much more pessimistic and gnarly "bug microwave" that causes the bug to pop out in a few seconds instead of a week. I'll write that now and throw it on a test server and see what it comes up with.

[spacejam]

Ok I think I've reproduced it by adding 5 subscriber threads to the concurrent_tree_transactions test. Here are the portions of the thread stacks that have sled:: as a prefix:

flusher thread: 

Thread 45 (Thread 0x7faff6df6700 (LWP 24173)):
#10 sled::concurrency_control::ConcurrencyControl::read (self=<optimized out>) at src/concurrency_control.rs:85
#11 sled::concurrency_control::read () at src/concurrency_control.rs:55
#12 sled::pagecache::iobuf::flush (iobufs=0x7fb004001328) at src/pagecache/iobuf.rs:1039
#13 0x0000558797b9082c in sled::pagecache::logger::Log::flush (self=0x80) at src/pagecache/logger.rs:37
#14 sled::pagecache::PageCache::flush (self=<optimized out>) at src/pagecache/mod.rs:756
#15 <sled::context::Context as core::ops::drop::Drop>::drop (self=0x7faff6df5920) at src/context.rs:61

read/write waiting transaction threads:

Thread 44 (Thread 0x7faff71f8700 (LWP 24171)):
#10 sled::concurrency_control::ConcurrencyControl::write (self=<optimized out>) at src/concurrency_control.rs:102
#11 sled::concurrency_control::write () at src/concurrency_control.rs:59
#12 sled::transaction::TransactionalTrees::stage (self=<optimized out>) at src/transaction.rs:387
#13 0x0000558797ab32ff in sled::tree::Tree::transaction ()

...32 identical stacktraces as above

currently executing transaction, blocked on Subscribers::reserve

Thread 23 (Thread 0x7fb001dee700 (LWP 24149)):
#9  sled::subscriber::Subscribers::reserve (self=<optimized out>, key=<optimized out>) at src/subscriber.rs:261
#10 0x0000558797b99d01 in sled::tree::Tree::insert_inner (self=<optimized out>, key=..., value=..., guard=0x7fb001ded5f0) at src/tree.rs:156
#11 0x0000558797b7ad36 in sled::transaction::TransactionalTree::commit (self=0x7fafac000b20) at src/transaction.rs:364
#12 sled::transaction::TransactionalTrees::commit (self=<optimized out>, guard=<optimized out>) at src/transaction.rs:408
#13 0x0000558797ab22f2 in sled::tree::Tree::transaction ()

threadpool threads hanging out

Thread 9 (Thread 0x7fb0039fc700 (LWP 24135)):
#8  sled::threadpool::Queue::recv_timeout (self=0x7fb0040065a0, duration=...) at src/threadpool.rs:53
#9  sled::threadpool::perform_work (is_immortal=true) at src/threadpool.rs:103
#10 0x0000558797ba5a08 in sled::threadpool::spawn_new_thread::{{closure}} () at src/threadpool.rs:161

... 5 identical stacktraces as above

all subscribing threads have terminated, but thread 23 is blocked trying to send data to one of the already terminated receiver threads.

so, thread 23 is the culprit, where it's trying to send data into a SyncSender that has been filled up with 1024 items. It is interesting to me that the call to SyncSender::send is not erroring out, because the corresponding mpsc::Receiver has been dropped, and I expect this to instantly error out.

The band-aid solution is to make the bounded mpsc channel into an unbounded one. But I think it's important to figure out why this call to SyncSender::send is not erroring out, despite its backing Receiver having been dropped. And I don't really like the idea of silently letting the system blow up memory usage when there is a slow subscriber.

[D1plo1d]

Sorry, I got pulled away on something but just to quickly confirm for you thread 23 looks exactly like the issue I saw in LLDB. I think you've got it recreated.

The band-aid solution is to make the bounded mpsc channel into an unbounded one. But I think it's important to figure out why this call to SyncSender::send is not erroring out, despite its backing Receiver having been dropped. And I don't really like the idea of silently letting the system blow up memory usage when there is a slow subscriber.

I agree, getting to the bottom of this would be good.

It is interesting to me that the call to SyncSender::send is not erroring out, because the corresponding mpsc::Receiver has been dropped, and I expect this to instantly error out.

I see what you mean - it is very surprising that SyncSender::send is not erroring out, definitely not what I'd expect from the docs:

Like asynchronous channels, if the Receiver is disconnected while trying to send with the SyncSender, the send method will return a SendError. Similarly, If the SyncSender is disconnected while trying to recv, the recv method will return a RecvError.

Overall I am quite happy that you've recreated the issue. This feels like much more progress then I'd hope for today. I've got to run but I'm going to continue looking at this tomorrow. When I get back to this I'm thinking I'll try and look into:

1. Is the Receiver cloned anywhere and could a cloned reference somehow somewhere be keeping the channel open?
2. Start reading the std lib SyncSender and looking for concurrency weirdness

Edit: Realized 1 doesn't make as much sense. I was thinking of cloned senders.

[D1plo1d]

@spacejam How would you feel about swapping out channel for crossbeam-channel and seeing if we have better luck with their implementation?

Send and receive operations on a disconnected channel never block.

Source: https://docs.rs/crossbeam-channel/0.4.3/crossbeam_channel/#disconnection

[D1plo1d]

Update: I did not have any luck today looking for concurrency issues in the SyncChannel code.

Relevant Stdlib files:

1: https://github.com/rust-lang/rust/blob/master/library/std/src/sync/mpsc/mod.rs
1: https://github.com/rust-lang/rust/blob/master/library/std/src/sync/mpsc/sync.rs#L195
1: https://github.com/rust-lang/rust/blob/master/library/std/src/sync/mpsc/blocking.rs

[D1plo1d]

The band-aid solution is to make the bounded mpsc channel into an unbounded one. But I think it's important to figure out why this call to SyncSender::send is not erroring out, despite its backing Receiver having been dropped. And I don't really like the idea of silently letting the system blow up memory usage when there is a slow subscriber.

Looking back at my code base I think an unbounded API would fix my issues - with the benefit of hindsight it looks like my Subscribers were probably just becoming full.

The deadlocking of commits still feels bizarre - I'd much prefer a commit to error if it is unable to write to the subscribers then deadlock my application - but at least it makes sense to me now.

Edit: For anyone coming from the stdlib issue, @spacejam's findings are separate from this and may still represent an issue in stdlib.

[soro]

After reading the code in stdlib in master, I am pretty confident there is only one scenario in which this could possibly happen, because the code is pretty straightforward and looks correct to me. The destructor has to take the lock and then drain the queue of waiting threads, waking them up - if the thread running the destructor was forcibly killed while the destructor was running, that would of course fail, but at that point you probably have bigger issues.

[soro]

Ok, so I think what happens here is a deadlock in the sled code. The destructor of a subscription can not proceed if the sender is blocked on sending, because the write lock cannot be acquired while a read lock is being held, which is going to be the case here. If the receiver is however not processing any more input and the destructor of the subscription was called, we are at an impasse. The receiver instance will be dropped after the destructor of subscription has run, which is never, and the send cannot notice the inactivity. Fix would be to run the destructor of the Receiver explicitly before taking the lock, i.e. before
https://github.com/spacejam/sled/blob/50982abb6ebfce5092ac94903fed8819847ae61f/src/subscriber.rs#L99

Edit: submitted https://github.com/spacejam/sled/pull/1161 to try to fix the problem

[D1plo1d]

Ok, I'll update the stdlib issue as well since that destructor blocking should at least be documented.

[soro]

Oh no, the destructor that blocks is the subscription destructor in sled, not the receiver destructor. That locks too, but in a way that cooperates correctly with the writing side. There is no issue in stdlib afaict.
Also, I would leave this issue open until testing has been done that confirms that my change fixes this problem.

[D1plo1d]

Ok, sounds good. I updated the stdlib issue to say that it was an issue on the Sled side.