Linked Futures can result in a BinaryPrivateSemaphore beeing signaled twice

Since !120 (merged) I observe that the echo server benchmark does not terminate.
I suspect the EchoClient because the server does work with the rust echo client and accepts new connections.
After reverting afafc707 the benchmark works again therefore I am quite sure that the issue must be somewhere in !120 (merged).

Does it also happen if io_cq_lock_implementation is set to mutex?

Yes it does.

I don't want to shift the blame, but I do wonder if this is not an issue somewhere else than afafc707 that got uncovered by afafc707's different timing behavior (the critical section is shorter with afafc707). Maybe we should try to add a short (1us? 100ns?) sleep() statement before unlocking the cq_lock. Just an idea.

I don't want to blame anyone for anything just share my observation.
!120 (merged) still seams correct to me. I will experiment with sleeping in the critical section

Ok now is the time to blame me. I found a first bug. See !132 (merged)
But not sure If this patch solves all our problems yet.
I thought I have seen a double signal of a Future's semaphore with the CountingTryLock but I can't reproduce it right now.

And I could reproduce the double signal using a build-release-cq-lock-mutex echo server and a debugoptimized-log-error echoclient.

#0  0x00007ffff7b5aef5 in raise () from /usr/lib/libc.so.6
#1  0x00007ffff7b44862 in abort () from /usr/lib/libc.so.6
#2  0x00007ffff7b44747 in __assert_fail_base.cold () from /usr/lib/libc.so.6
#3  0x00007ffff7b53646 in __assert_fail () from /usr/lib/libc.so.6
#4  0x00007ffff7f8e9b6 in BinaryPrivateSemaphore::signalInternal (this=0x7ffff1d08308)
    at ../emper/BinaryPrivateSemaphore.cpp:47
#5  0x00005555555649a9 in PrivateSemaphore::signalAndGetContinuation (this=0x7ffff1d08308)
    at ../emper/PrivateSemaphore.hpp:43
#6  0x000055555556524a in emper::io::Future::completeAndGetContinuation (this=0x7ffff1d08300, res=32)
    at ../emper/io/Future.hpp:113
#7  0x0000555555565951 in emper::io::PartialCompletableFuture::completeAndGetContinuation (
    this=0x7ffff1d08300, res=32) at ../emper/io/Future.hpp:396
#8  0x00007ffff7f9cdbb in emper::io::IoContext::reapCompletions<(CallerEnvironment)0> (
    this=0x7ffff0000900) at ../emper/io/IoContext.cpp:281
#9  0x00007ffff7f9d5b1 in emper::io::IoContext::reapAndScheduleCompletions<(CallerEnvironment)0> (
    this=0x7ffff0000900) at ../emper/io/IoContext.hpp:154
#10 0x00007ffff7f9b90f in emper::io::IoContext::submit<(CallerEnvironment)0> (this=0x7ffff0000900, 
    future=...) at ../emper/io/IoContext.cpp:156
#11 0x00007ffff7f92910 in emper::io::Future::submit (this=0x7ffff1d08290) at ../emper/io/Future.cpp:80
#12 0x00005555555656c4 in emper::io::Future::submitAndWait (this=0x7ffff1d08290)
    at ../emper/io/Future.hpp:280
#13 0x0000555555560e8a in clientFunc (client_id=2432, readySem=..., startSem=..., cps=...)

So a worker is trying to submitting a Future into a ring with an full CQ and therefore has to reap. But it stumbles upon a Future which's semaphore was already signaled.

Maybe this has actually something to do with memory initialization.
I added assert(!state.completed); in Future.hpp:96.
My assumption was that if the Future is actually completed twice the assert would abort before overwriting the values from the first completion and I could observe the original Future state.
But the new assert does not trigger but the original (BinaryPrivateSemaphore) does still.
This means setCompletion which is always called before we signal the Future's semaphore (Future.hpp:102-115) is not called twice this means the Future's semaphore is also not signaled twice.

This leafs us with some sort of memory bug I suppose.

And I finally could reproduce it -Dio_cq_lock_implementation=mutex

I could trigger the assert(currentState != signaled); from BinaryPrivateSemaphore.cpp:47 with the new test case in LinkFutureTest introduced by !134 (merged).

The meson cmds I used:

meson build-debugoptimized-no-log-cq-mutex -Dlog_level=Error -Dio_cq_lock_implementation=mutex
meson test -C build-debugoptimized-no-log-cq-mutex --repeat=100

mentioned in merge request !136 (merged)

With !136 (merged) I still could reproduce this bug using our LinkFutureTest on repetition 751.

changed title from Echo benchmark hangs since afafc7073f3fa2493fd21a346b2034b0cbfcdf80 to Linked Futures can result in a BinaryPrivateSemaphore beeing signaled twice

changed the description

For documentation purposes here what we have discovered so far:

• The Future whose BinarySemaphore has bpsState == signaled when signaling it in Future::completeAndGetContinuation is not completed twice because we have an assert for that in Future::setCompletion which is always called before sem.signal{,AndGetContinuation}.

• It does not seam to be a memory corruption where someone writes to the front of a Future object

  • bpsState is explicitly set to signaled (which is 1)
  • we introduced a canary at the front of Future and moved the semaphore to the back and still only the BPS state was changed to signaled

Backtrace from a crash produced by a -Dlog_level=Error -Dio_cq_lock_implementation=mutex build's LinkFutureTest on 03727b29.

#0  0x00007ffff7b64ef5 in raise () from /usr/lib/libc.so.6
#1  0x00007ffff7b4e862 in abort () from /usr/lib/libc.so.6
#2  0x00007ffff7b4e747 in __assert_fail_base.cold () from /usr/lib/libc.so.6
#3  0x00007ffff7b5d646 in __assert_fail () from /usr/lib/libc.so.6
#4  0x00007ffff7f8c3b8 in BinaryPrivateSemaphore::signalInternal (this=0x7fffe8082f48)
    at ../emper/BinaryPrivateSemaphore.cpp:47
#5  0x000055555555fb8f in PrivateSemaphore::signalAndGetContinuation (this=0x7fffe8082f48)
    at ../emper/PrivateSemaphore.hpp:43
#6  0x000055555555fd9e in emper::io::Future::completeAndGetContinuation (this=0x7fffe8082f40, res=8)
    at ../emper/io/Future.hpp:115
#7  0x00005555555604cb in emper::io::PartialCompletableFuture::completeAndGetContinuation (
    this=0x7fffe8082f40, res=8) at ../emper/io/Future.hpp:398
#8  0x00007ffff7f9aadb in emper::io::IoContext::reapCompletions<(CallerEnvironment)1> (
    this=0x7fffe0000900) at ../emper/io/IoContext.cpp:308
#9  0x00007ffff7f9fee3 in emper::io::IoContext::reapAndScheduleCompletions<(CallerEnvironment)1> (
    this=0x7fffe0000900) at ../emper/io/IoContext.hpp:175
#10 0x00007ffff7f9f543 in emper::io::GlobalIoContext::globalCompleterFunc (arg=0x55555557d840)
    at ../emper/io/GlobalIoContext.cpp:106
#11 0x00007ffff7b09299 in start_thread () from /usr/lib/libpthread.so.0
#12 0x00007ffff7c27053 in clone () from /usr/lib/libc.so.6

locals from the frame 8 emper::io::IoContext::reapCompletions<(CallerEnvironment)1>

(gdb) i locals
future = 0x7fffe8082f40
continuation = 0x7fffe4008d80
completion = {first = 8, second = 0x7fffe8082f40}
cqe_data = 0x7fffe8082f40
tptr = {tptr = 140737086238528}
res = 8
tag = emper::io::PointerTags::Future
i = 0
__PRETTY_FUNCTION__ = "std::vector<Fiber*> emper::io::IoContext::reapCompletions() [with CallerEnvironment callerEnvironment = ANYWHERE]"
CQE_BATCH_COUNT = 16
reReapCount = 0
maxRaceFreeCompleterAttempts = 1
reapedCompletions = {_M_elems = {{first = 8, second = 0x7fffe8082f40}, {first = 8, 
      second = 0x7fffe8082fb0}, {first = 0, second = 0x0} <repeats 14 times>}}
continuationFibers = std::vector of length 0, capacity 2
cqes = {_M_elems = {0x7ffff7f1c1e0, 0x7ffff7f1c1f0, 0x0, 0x0, 0x55555557d400, 0x7ffff7ffe1e0, 0x27, 
    0x555555563642 <std::__copy_move<false, true, std::random_access_iterator_tag>::__copy_m<Fiber**>(Fiber** const*, Fiber** const*, Fiber***)+74>, 0x0, 0x55555557d3d8, 0x55555557d400, 0x55555557d3f8, 0x0, 
    0x1, 0x7ffff79ade00, 0x7ffff7bb23ac <_int_malloc+2732>}}
count = 2
globalCompleterAttempts = 0

The Futures in reapedCompletions (note we call completeAndGetContinuation() on those from low to high indices). reapedCompletions[0].second - the WriteFuture triggering the assert in 5:

(gdb) p *((Future*)0x7fffe8082f40)
$4 = {<Logger<(LogSubsystem)8>> = {<No data fields>}, 
  _vptr.Future = 0x555555569a50 <vtable for emper::io::WriteFuture+16>, 
  sem = {<PrivateSemaphore> = {<Blockable<(LogSubsystem)0>> = {<Logger<(LogSubsystem)0>> = {<No data fields>}, runtime = @0x7fffffffde40, contextManager = @0x55555557d680}, 
      _vptr.PrivateSemaphore = 0x555555569b40 <vtable for BinaryPrivateSemaphore+16>}, bpsState = {
      static _S_min_alignment = 4, static _S_alignment = 4, _M_i = BinaryPrivateSemaphore::signaled, 
      static is_always_lock_free = <optimized out>}, blockedContext = 0x0}, state = {
    submitted = 1 '\001', completed = 1 '\001', retrieved = 0 '\000', dependency = 1 '\001', 
    cancelled = 0 '\000', forgotten = 0 '\000'}, op = emper::io::Operation::WRITE, fd = 13, 
  buf = 0x7fffe8082f20, len = 8, offsetOrFlags = 0, returnValue = 8, dependency = 0x0, callback = 0x0}

The WriteFuture is completed because we call BPS::signalAndGetContinuation after Future::setCompletion but we are not completing the Future twice because Future::setCompletion asserts that the Future in not completed yet. reapedCompletions[1].second - the ReadFuture dependent on the WriteFuture:

(gdb) p *((Future*)0x7fffe8082fb0)
$5 = {<Logger<(LogSubsystem)8>> = {<No data fields>}, 
  _vptr.Future = 0x555555569af0 <vtable for emper::io::ReadFuture+16>, 
  sem = {<PrivateSemaphore> = {<Blockable<(LogSubsystem)0>> = {<Logger<(LogSubsystem)0>> = {<No data fields>}, runtime = @0x7fffffffde40, contextManager = @0x55555557d680}, 
      _vptr.PrivateSemaphore = 0x555555569b40 <vtable for BinaryPrivateSemaphore+16>}, bpsState = {
      static _S_min_alignment = 4, static _S_alignment = 4, _M_i = BinaryPrivateSemaphore::blocked, 
      static is_always_lock_free = <optimized out>}, blockedContext = 0x7fffe80734c0}, state = {
    submitted = 1 '\001', completed = 0 '\000', retrieved = 0 '\000', dependency = 0 '\000', 
    cancelled = 0 '\000', forgotten = 0 '\000'}, op = emper::io::Operation::READ, fd = 13, 
  buf = 0x7fffe8082f28, len = 8, offsetOrFlags = 0, returnValue = 0, dependency = 0x7fffe8082f40, 
  callback = 0x0}

Unfortunately I can't see anything suspicious here. But I think it is still interesting that I only see the assert for the Dependency-Future never for the Dependent-Future.

closed with merge request !136 (merged)

mentioned in commit f2a2a12f

I think this was closed by accident since it is not solved.

Unfortunatly this does not fix #13

Apparently this line from !136 (merged)'s description closed this issue

reopened

mentioned in issue #29