ffi/many_listener_callbacks_test.dart timesout/deadlocks on vm-reload-rollback-linux-debug-x64

[aam]

log from build

--- Command "vm" (took 02:00.000233s):
DART_CONFIGURATION=DebugX64 out/DebugX64/dart --hot-reload-rollback-test-mode --use-slow-path --stacktrace-every=100 -Dtest_runner.configuration=vm-reload-rollback-linux-debug-x64 --ignore-unrecognized-flags --packages=/b/s/w/ir/.dart_tool/package_config.json /b/s/w/ir/tests/ffi/many_listener_callbacks_test.dart

exit code:
1

diagnostics:
Process list including children: [23788]
Trying to capture stack trace for pid 23788
PID 23788 - process
TID 23788:
#0  0x00007be61ac91117 __GI___futex_abstimed_wait_cancelable64
#1  0x00007be61ac93a41 pthread_cond_wait@@GLIBC_2.3.2
#2  0x00005b5469dab747 dart::ConditionVariable::WaitMicros(dart::Mutex*, long)
#3  0x00005b546a7e53fd Dart_RunLoop
#4  0x00005b5469da5742 dart::bin::RunMainIsolate(char const*, char const*, char const*, dart::bin::CommandLineOptions*)
#5  0x00005b5469da64c3 dart::bin::main(int, char**)
#6  0x00005b5469da547d main
#7  0x00007be61ac29d90 __libc_start_call_main
#8  0x00007be61ac29e40 __libc_start_main@@GLIBC_2.34
#9  0x00005b5469da21a9 _start
TID 23790:
#0  0x00007be61ad25e2e epoll_wait
#1  0x00005b5469db0985 dart::bin::EventHandlerImplementation::Poll(unsigned long)
#2  0x00005b546a7d50c7 dart::bin::ThreadStart(void*)
#3  0x00007be61ac94ac3 start_thread
#4  0x00007be61ad26850 __clone3
TID 23798:
#0  0x00007be61ac91117 __GI___futex_abstimed_wait_cancelable64
#1  0x00007be61ac93e9b pthread_cond_timedwait@@GLIBC_2.3.2
#2  0x00005b5469dab80f dart::ConditionVariable::WaitMicros(dart::Mutex*, long)
#3  0x00005b546a30a73d dart::MutatorThreadPool::OnEnterIdleLocked(dart::MutexLocker*, dart::ThreadPool::Worker*)
#4  0x00005b546a5170c8 dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#5  0x00005b546a51782d dart::ThreadPool::Worker::Main(unsigned long)
#6  0x00005b546a4829b6 dart::ThreadStart(void*)
#7  0x00007be61ac94ac3 start_thread
#8  0x00007be61ad26850 __clone3
TID 23808:
#0  0x00007be61ac91117 __GI___futex_abstimed_wait_cancelable64
#1  0x00007be61ac93e9b pthread_cond_timedwait@@GLIBC_2.3.2
#2  0x00005b5469dab80f dart::ConditionVariable::WaitMicros(dart::Mutex*, long)
#3  0x00005b546a30a73d dart::MutatorThreadPool::OnEnterIdleLocked(dart::MutexLocker*, dart::ThreadPool::Worker*)
#4  0x00005b546a5170c8 dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#5  0x00005b546a51782d dart::ThreadPool::Worker::Main(unsigned long)
#6  0x00005b546a4829b6 dart::ThreadStart(void*)
#7  0x00007be61ac94ac3 start_thread
#8  0x00007be61ad26850 __clone3
TID 23911:
#0  0x00007be61ac912c0 __GI___lll_lock_wait
#1  0x00007be61ac98002 __pthread_mutex_lock@GLIBC_2.2.5
#2  0x00005b5469dab2cf dart::Mutex::Lock()
#3  0x00005b546a34d279 dart::SafepointMutexLocker::SafepointMutexLocker(dart::ThreadState*, dart::Mutex*)
#4  0x00005b546a2ff6da dart::FfiCallbackMetadata::CreateMetadataEntry(dart::Isolate*, dart::IsolateGroup*, dart::FfiCallbackMetadata::TrampolineType, unsigned long, unsigned long, dart::FfiCallbackMetadata::MetadataEntry**)
#5  0x00005b546a300548 dart::FfiCallbackMetadata::CreateAsyncFfiCallback(dart::Isolate*, dart::Zone*, dart::Function const&, long, dart::FfiCallbackMetadata::MetadataEntry**)
#6  0x00005b546a21f844 dart::BootstrapNatives::DN_Ffi_createNativeCallableListener(dart::Thread*, dart::Zone*, dart::NativeArguments*)
#7  0x00005b546a36a713 dart::NativeEntry::BootstrapNativeCallWrapper(_Dart_NativeArguments*, void (*)(_Dart_NativeArguments*))
#8  0x00007be61a302434
#9  0x00007be6196a8fe7
#10 0x00007be6196a859d
#11 0x00007be6196a534a
#12 0x00007be6196b143e
#13 0x00007be6196b12dd
#14 0x00007be6196b0f86
#15 0x00007be6196b0c4a
#16 0x00007be6196afd3e
#17 0x00007be6196ae940
#18 0x00007be6196ae71c
#19 0x00007be6196ae242
#20 0x00007be6196ade34
#21 0x00007be6196add38
#22 0x00007be6196abc8a
#23 0x00007be6196a2275
#24 0x00007be61a3027c4
#25 0x00005b546a2d5e3e dart::DartEntry::InvokeFunction(dart::Function const&, dart::Array const&, dart::Array const&)
#26 0x00005b546a2d852f dart::DartLibraryCalls::HandleMessage(long, dart::Instance const&)
#27 0x00005b546a31284b dart::IsolateMessageHandler::HandleMessage(std::__2::unique_ptr<dart::Message, std::__2::default_delete<dart::Message> >)
#28 0x00005b546a350969 dart::MessageHandler::HandleMessages(dart::MonitorLocker*, bool, bool)
#29 0x00005b546a351492 dart::MessageHandler::TaskCallback()
#30 0x00005b546a516f3f dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#31 0x00005b546a51782d dart::ThreadPool::Worker::Main(unsigned long)
#32 0x00005b546a4829b6 dart::ThreadStart(void*)
#33 0x00007be61ac94ac3 start_thread
#34 0x00007be61ad26850 __clone3
TID 23920:
#0  0x00007be61ac912c0 __GI___lll_lock_wait
#1  0x00007be61ac98002 __pthread_mutex_lock@GLIBC_2.2.5
#2  0x00005b5469dab2cf dart::Mutex::Lock()
#3  0x00005b546a4c78a8 DLRT_GetFfiCallbackMetadata
#4  0x00007be61af6158b
#5  0x0000000000000000
#6  0x00007be61ac94ac3 start_thread
#7  0x00007be61ad26850 __clone3
TID 23930:
#0  0x00007be61ac91117 __GI___futex_abstimed_wait_cancelable64
#1  0x00007be61ac93a41 pthread_cond_wait@@GLIBC_2.3.2
#2  0x00005b5469dab747 dart::ConditionVariable::WaitMicros(dart::Mutex*, long)
#3  0x00005b546a567640 dart::SafepointHandler::ExitSafepointLocked(dart::Thread*, dart::MonitorLocker*, dart::SafepointLevel)
#4  0x00005b546a5683e5 dart::SafepointHandler::BlockForSafepoint(dart::Thread*)
#5  0x00005b546a310446 dart::IsolateMessageHandler::HandleLibMessage(dart::Array const&)
#6  0x00005b546a312822 dart::IsolateMessageHandler::HandleMessage(std::__2::unique_ptr<dart::Message, std::__2::default_delete<dart::Message> >)
#7  0x00005b546a350969 dart::MessageHandler::HandleMessages(dart::MonitorLocker*, bool, bool)
#8  0x00005b546a350f02 dart::MessageHandler::HandleOOBMessages()
#9  0x00005b546a51024b dart::Thread::HandleInterrupts(unsigned long)
#10 0x00005b546a4c0e75 DRT_InterruptOrStackOverflow
#11 0x00007be61a3022d2
#12 0x00007be6196a9244
#13 0x00007be61a302720
#14 0x0000000000000000
#15 0x00007be61af61658
#16 0x00007be61ac94ac3 start_thread
#17 0x00007be61ad26850 __clone3
TID 23931:
#0  0x00007be61ac912c0 __GI___lll_lock_wait
#1  0x00007be61ac98002 __pthread_mutex_lock@GLIBC_2.2.5
#2  0x00005b5469dab2cf dart::Mutex::Lock()
#3  0x00005b546a4c78a8 DLRT_GetFfiCallbackMetadata
#4  0x00007be61af6158b
#5  0x0000000000000000
#6  0x00007be61ac94ac3 start_thread
#7  0x00007be61ad26850 __clone3
TID 23932:
#0  0x00007be61ac91117 __GI___futex_abstimed_wait_cancelable64
#1  0x00007be61ac93a41 pthread_cond_wait@@GLIBC_2.3.2
#2  0x00005b5469dab747 dart::ConditionVariable::WaitMicros(dart::Mutex*, long)
#3  0x00005b546a50e59d dart::Thread::AddActiveThread(dart::IsolateGroup*, dart::Isolate*, dart::Thread::TaskKind, bool)
#4  0x00005b546a50e38c dart::Thread::EnterIsolate(dart::Isolate*)
#5  0x00005b546a30e5f4 dart::Isolate::InitIsolate(char const*, dart::IsolateGroup*, Dart_IsolateFlags const&, bool)
#6  0x00005b546a30e3d6 dart::IsolateGroup::EnterTemporaryIsolate()
#7  0x00005b546a4c7966 DLRT_GetFfiCallbackMetadata
#8  0x00007be61af6158b
#9  0x0000000000000002
#10 0x00007be61ac94ac3 start_thread
#11 0x00007be61ad26850 __clone3
TID 23933:
#0  0x00007be61ac912c0 __GI___lll_lock_wait
#1  0x00007be61ac98002 __pthread_mutex_lock@GLIBC_2.2.5
#2  0x00005b5469dab2cf dart::Mutex::Lock()
#3  0x00005b546a4c78a8 DLRT_GetFfiCallbackMetadata
#4  0x00007be61af6158b
#5  0x0000000000000000
#6  0x00007be61ac94ac3 start_thread
#7  0x00007be61ad26850 __clone3
TID 23934:
#0  0x00007be61ac912c0 __GI___lll_lock_wait
#1  0x00007be61ac98002 __pthread_mutex_lock@GLIBC_2.2.5
#2  0x00005b5469dab2cf dart::Mutex::Lock()
#3  0x00005b546a4c78a8 DLRT_GetFfiCallbackMetadata
#4  0x00007be61af6158b
#5  0x0000000000000000
#6  0x00007be61ac94ac3 start_thread
#7  0x00007be61ad26850 __clone3
TID 23935:
#0  0x00007be61ac912c0 __GI___lll_lock_wait
#1  0x00007be61ac98002 __pthread_mutex_lock@GLIBC_2.2.5
#2  0x00005b5469dab2cf dart::Mutex::Lock()
#3  0x00005b546a4c78a8 DLRT_GetFfiCallbackMetadata
#4  0x00007be61af6158b
#5  0x0000000000000000
#6  0x00007be61ac94ac3 start_thread
#7  0x00007be61ad26850 __clone3
TID 23936:
#0  0x00007be61ac91117 __GI___futex_abstimed_wait_cancelable64
#1  0x00007be61ac93e9b pthread_cond_timedwait@@GLIBC_2.3.2
#2  0x00005b5469dab80f dart::ConditionVariable::WaitMicros(dart::Mutex*, long)
#3  0x00005b546a5671e2 dart::SafepointHandler::LevelHandler::WaitUntilThreadsReachedSafepointLevel()
#4  0x00005b546a5660bc dart::SafepointHandler::SafepointThreads(dart::Thread*, dart::SafepointLevel)
#5  0x00005b546a314f79 dart::IsolateGroup::ReloadSources(dart::JSONStream*, bool, char const*, char const*, bool)
#6  0x00005b546a4c0ce4 DRT_InterruptOrStackOverflow
#7  0x00007be61a3022d2
#8  0x00007be6196a9244
#9  0x00007be61a302720
#10 0x0000000000000000
#11 0x00007be61af61658
#12 0x00007be61ac94ac3 start_thread
#13 0x00007be61ad26850 __clone3
TID 23942:
#0  0x00007be61ac912c0 __GI___lll_lock_wait
#1  0x00007be61ac98002 __pthread_mutex_lock@GLIBC_2.2.5
#2  0x00005b5469dab2cf dart::Mutex::Lock()
#3  0x00005b546a4c78a8 DLRT_GetFfiCallbackMetadata
#4  0x00007be61af6158b
#5  0x0000000000000000
#6  0x00007be61ac94ac3 start_thread
#7  0x00007be61ad26850 __clone3



--- Re-run this test:
python3 tools/test.py -n vm-reload-rollback-linux-debug-x64 ffi/many_listener_callbacks_test/2

perhaps related to 919d503 which made FfiCallbackMetadata::CreateMetadataEntry use SafepointMutexLocker - that is locked by TID 23911, while other threads TID 23920, 23931,... uses MutexLock for the same mutex. All while another thread TID 23936 is waiting for everybody to get to a safepoint to perform a reload.

cc @liamappelbe

[liamappelbe]

perhaps related to 919d503 which made FfiCallbackMetadata::CreateMetadataEntry use SafepointMutexLocker - that is locked by TID 23911, while other threads TID 23920, 23931,... uses MutexLock for the same mutex. All while another thread TID 23936 is waiting for everybody to get to a safepoint to perform a reload.

I don't understand why that would cause a deadlock. All the DLRT_GetFfiCallbackMetadata calls are coming from non-Dart threads, so shouldn't prevent TID 23936 from reaching a safepoint. The thread holding the FCM mutex is one of these threads, TID 23932, and it's waiting for the safepoint to be over. The only thread running real Dart code is TID 23911, which is in FfiCallbackMetadata::CreateMetadataEntry and blocked on the FCM mutex, but it's at a safepoint, because it's holding the mutex using a SafepointMutexLocker. I suppose it must be the case that the DLRT_GetFfiCallbackMetadata are in a scope that prevents the safepoint from happening. In any case, I could probably write a different test that tries to call DLRT_GetFfiCallbackMetadata from a Dart thread.

Another question I have is what distinguishes this from the GC based deadlock that was fixed by that change? It's almost identical, except that it's the GC trying to reach a safepoint, rather than the hot reload flow. That deadlock was indeed fixed by FfiCallbackMetadata::CreateMetadataEntry using SafepointMutexLocker. What's different about the safepoint that dart::IsolateGroup::ReloadSources is trying to enter?

Stepping back, when I look at this family of deadlocks, intuitively I keep coming back to the idea that DLRT_GetFfiCallbackMetadata shouldn't be holding the FCM mutex for so long, or shouldn't be holding such a strong lock. It just needs to hold some sort of lock that ensures that the target isolate isn't destroyed. The FCM mutex is a roundabout way of doing this (FfiCallbackMetadata::DeleteAllCallbacks holds this mutex and is called during Isolate::LowLevelShutdown). We don't need to prevent further FfiCallbackMetadata::CreateMetadataEntry calls. But to fix this deadlock, it would be enough to split/modify the FCM lock so that it add and delete are still mutually excluded, and delete excludes get, but add and get could coexist. Something like a RW lock, but where add does a weaker sort of write that still allows reads. Maybe it could be called a Read-Update-Write lock (where add uses update, and delete uses write)?

[liamappelbe]

cc @mraleph

[mraleph]

I don't understand why that would cause a deadlock.

Our safepoints have different levels: safepoint which allows GC does not necessarily allow reload because it is not safe, see SafepointLevel enum and Thread::current_safepoint_level() which computes it. So we deadlock because we don't allow reload when in the VM runtime code - unless this is overriden via ReloadParticipationScope.

I must admit I did consider that this can happen and then happily forgot about it, good that the test caught it.

I am thinking that we can just plaster ReloadParticipationScope here and in DeleteCallback (before SafepointMutexLocker) and call it a done - the book keeping which is happening here does not seem to be affected if reload happens here.

I do agree that locking seem rather coarse, but I currently don't see much better alternative - you need to hold some sort of lock until you have entered the isolate. Whether it is one lock or some more fine grained lock (e.g. per entry lock?) does not matter - we can't release it until we ensure that we have successfully entered the isolate.

[liamappelbe]

I am thinking that we can just plaster ReloadParticipationScope here and in DeleteCallback (before SafepointMutexLocker) and call it a done - the book keeping which is happening here does not seem to be affected if reload happens here.

Tried your suggestion. It fixes the test in release mode, but in debug more it hits an assertion failure. If I'm reading this comment right, it seems that we're generally not allowed to enter ReloadParticipationScope, then acquire a SafepointMutexLocker.

[mraleph]

The comment actually disagrees with the implementation which was changed in 077d7c9. The comment specifically talks how we assume that reload safepoint can occur only in very specific places, so we assume that inversion of locking order (acquire safepoint -> acquire lock vs participate in safepoint -> acquire lock) do not occur - but the implementation actually prohibits this instead. FWIW I don't think there is any inversion of locking order possible in this particular code, so it would have been fine to declare participation in reload here - but alas due to stricter checking we can't.

Anyway, I think one question we could ask is if the lock DLRT_GetFfiCallbackMetadata is even necessary. It does guard against some races, but does not guard against all possible races e.g. async callback can be deleted and replaced with another callback and it will just end up being called (if replacement happens before the call);

We could simply stop trying to cover this case and say that VM crashes when you try to do that - it is not that different from native side trying to access memory which we freed.

Do you remember what was the motivation for trying to catch such situations?

[liamappelbe]

FWIW I don't think there is any inversion of locking order possible in this particular code, so it would have been fine to declare participation in reload here - but alas due to stricter checking we can't.

Maybe we can weaken the assert?

Anyway, I think one question we could ask is if the lock DLRT_GetFfiCallbackMetadata is even necessary. It does guard against some races, but does not guard against all possible races e.g. async callback can be deleted and replaced with another callback and it will just end up being called (if replacement happens before the call);

Are you sure the callback could be deleted and replaced? The IsSameCallback call is supposed to guard against that.

Do you remember what was the motivation for trying to catch such situations?

Generally, the goal is that calling a dead callback should be a no-op. Even if we considered it ok to crash, we'd want to FATAL with a useful message, not blindly call the function. Calling the function might not even crash. If the replacement's signature matches (or even just takes up the same amount of stack space), it would be called without issue. This would be very confusing for users, and hard to debug.

[mraleph]

Maybe we can weaken the assert?

FWIW, I do agree with the intent of @rmacnak-google's change that it is safer to prohibit it rather than cross fingers and hope we always do it right. We are going to make mistakes. So maybe weakening assert is not a good idea.

I think something like this is a possibility - but it is ugly and brittle.

Are you sure the callback could be deleted and replaced? The IsSameCallback call is supposed to guard against that.

The IsSameCallback only guards against replacement which occurs after the first (unlocked) call to LookupMetadataForTrampoline. If replacement happens before the first call to LookupMetadataForTrampoline then IsAlive check will pass. In other words this double checking only guards against situations which occur literally concurrently with the invocation itself.

Generally, the goal is that calling a dead callback should be a no-op.

If that's the goal we should not be recycling them, because if we recycle them then you can end up in the situation where you will call the wrong callback.

So I think we have a choice:

• We don't provide any guarantees - if the users misuses FFI API around callables they get strange behaviors (similar to how misusing malloc/free will lead to strange issues). If that's the case we can remove this locking and we can recycle callback trampolines and metadata.
• We do provide guarantees that disposed callbacks become no-ops. In this case we can't recycle trampolines and metadata and we need some sort of locking in place.

cc @dcharkes for second opinion.

[dcharkes]

we can't recycle trampolines and metadata

This lead to a memory leak with long running Dart processes which create new callbacks continiously. (For example: Dart on the server with some continuation-style callbacks changed in something like a database. Similar to the use case of the user who reported the initial deadlock.)

I do agree with @liamappelbe that things are very hard for users to debug if they go wrong. So, I'd prefer we FATAL on as many cases as we can.

I also agree that if users misuse the API, we shouldn't no-op. We should FATAL instead.

If the only way to FATAL on all misuses is to not recycle and leak memory, then maybe we should introduce a flag for that --ffi-sanitizer (FSAN).

Generally, the goal is that calling a dead callback should be a no-op.

@liamappelbe I don't have a recollection of this in our design process. Also I don't see any documentation or tests exercising this. Do you have a reference to a CL/comment/doc somewhere?

FYI @mkustermann (for when you're back)

[mraleph]

This lead to a memory leak with long running Dart processes which create new callbacks continiously.

Yep! Which leads me to conclusion that we do need to recycle these callbacks - and consequently this means we can't really provide any strong guarantees that users get a useful error message.

I think the best we can do (short of leaking memory) is to delay recycling e.g. never put deleted callbacks at the start of the free list - which would help if free list is long enough.

The problem is fundamentally the same as detecting misuse of malloc/free.

I do agree with @liamappelbe that things are very hard for users to debug if they go wrong. So, I'd prefer we FATAL on as many cases as we can.

Then I think we have to have special mode for this, as you suggest. But that requires a lot of design in itself - we should probably fix locking issue first and then do design to solve the other problem.

[dcharkes]

The problem is fundamentally the same as detecting misuse of malloc/free.

Agreed.

Then I think we have to have special mode for this, as you suggest. But that requires a lot of design in itself - we should probably fix locking issue first and then do design to solve the other problem.

SGTM (edit: We gotta make sure that VM flag is available for flutter in debug mode.)