Issue with finalizing external objects

[chisandrei]

We get some failures in FinalizationRegistry>finalizeEphemeron:. Two stacks are below:

C stack backtrace & registers:


Registers:
ContextFlags: 0x000000000010000f
        rax 0x000000000000001f rbx 0x000001cb005e2c10 rcx 0x000000854633df00 rdx 0x0000000000000002
        rdi 0x00007ffda8c31070 rsi 0x0000000000000000 rbp 0x000001cb77d85d90 rsp 0x000000854633ded0
        r8  0x00007ffda8ccd990 r9  0x000001cb005e1c1f r10 0x0000000000000000 r11 0x000000854633dd40
        r12 0x0000000000000000 r13 0x000000854056d000 r14 0x000001cb77d85d80 r15 0x000001cb77d85d80
        rip 0x00007ffda8bd8edc


C Callstack:

[0x00007FFDBE847E71] RtlFreeHeap
[0x00007FFD8D94C291] skia_null_ptr
[0x00007FFD8D967D23] skia_typeface_drop
[0x00007FFDA8BE0A11] primitiveReleaseWorker
[0x00007FFDA8BDDD63] primitiveReleaseWorker
[0x00007FFDA8BDDC22] primitiveReleaseWorker
[0x00007FFDA8BAB3CE] shortPrintFramesOnStackPageListInUse
[0x0000000320001658] trampoline cePrimReturnEnterCogCode
[0x00007FFDA8C32FF8] primitivePerformWorkerCallAccessorDepth
[0x8000000010400021] not a method
[0x00007FFDA8C33630] primitivePerformWorkerCallAccessorDepth


All Smalltalk process stacks (active first):
Process        0x362b87558 priority 51
       0x300009c38 M TFSameThreadRunner>invokeFunction:withArguments: 0x1dd3ff8: a(n) TFSameThreadRunner
       0x300009c98 I >primRelease: 0x3dbc058: a(n)
       0x300009cd8 M [] in >release: 0x3dbc058: a(n)
       0x300009d08 M FullBlockClosure(BlockClosure)>on:do: 0x62c001c0: a(n) FullBlockClosure
       0x300009d48 M (GtBoxerExternalObject class)>release: 0x3dbc058: a(n)
       0x300009d80 M (GtBoxerExternalObject class)>finalizeResourceData: 0x3dbc058: a(n)
       0x300009db8 M FFIExternalResourceExecutor>finalize 0x6012c4c8: a(n) FFIExternalResourceExecutor
       0x300009df0 M [] in FinalizationRegistry>finalizeEphemeron: 0x1de80d8: a(n) FinalizationRegistry
       0x300009e20 M FullBlockClosure(BlockClosure)>on:do: 0x62bffee0: a(n) FullBlockClosure
       0x300009e60 M FullBlockClosure(BlockClosure)>on:fork: 0x62bffee0: a(n) FullBlockClosure
       0x300009ea0 M FinalizationRegistry>handleErrorsDuring: 0x1de80d8: a(n) FinalizationRegistry
       0x300009ed8 M FinalizationRegistry>finalizeEphemeron: 0x1de80d8: a(n) FinalizationRegistry
       0x300009f10 M FinalizationRegistryEntry>mourn 0x60120938: a(n) FinalizationRegistryEntry
       0x300009f48 M WeakArray class>mournLoopWith: 0x16300: a(n) WeakArray class
       0x300009fa0 I [] in WeakArray class>finalizationProcess 0x16300: a(n) WeakArray class
       0x300009fe0 I [] in FullBlockClosure>newProcess 0x62b87388: a(n) FullBlockClosure

--- The full stack ---
[ :anError |
			(GtVirtualMachineSymbolNotFoundError new
				symbolName: moduleSymbol;
				moduleName: module) signal ] in GtVirtualMachineFFIBackend>>loadSymbol:module:
FullBlockClosure(BlockClosure)>>cull:
Context>>evaluateSignal:
Context>>handleSignal:
PrimitiveFailed(Exception)>>signal
PrimitiveFailed class(SelectorException class)>>signalFor:
GtVirtualMachineFFIBackend(ProtoObject)>>primitiveFailed:
GtVirtualMachineFFIBackend(ProtoObject)>>primitiveFailed
GtVirtualMachineFFIBackend>>primLoadSymbol:module:
[ self primLoadSymbol: moduleSymbol module: encodedString ] in GtVirtualMachineFFIBackend>>loadSymbol:module:
FullBlockClosure(BlockClosure)>>on:do:
GtVirtualMachineFFIBackend>>loadSymbol:module:
ExternalAddress class>>loadSymbol:module:
GtVirtualMachineExternalFunction(TFExternalFunction)>>validate
TFSameThreadRunner>>invokeFunction:withArguments:
LGitCommit class>>commit_free:
LGitCommit class(LGitExternalObject class)>>finalizeResourceData:
FFIExternalResourceExecutor>>finalize
[ 
		anEphemeron value finalize ] in FinalizationRegistry>>finalizeEphemeron:

Seems that the system tries to deallocate already deallocated memory on startup. On startup ExternalAdress allSubInstancesDo: #beNull gets called. But it seems that the finalizer runs on startup before that and it tries to deallocate some of the ExternalAdress that should be null. It seems that finalizationProcess spawns a new process for each item in the registry, and we did not see anything in there that stops the image from being saved with the finalization process active.

[girba]

This did not address the problem.
The stdout is still being written to continuously:

[Glutin] Could not init env logger
[Warning] Failed to release SkiaCompositionTransformationLayer(@ 16r200D46EA1A0) due to Could not find 'compositor_layer_drop' in '/Users/tudor/jenkins/workspace/feenkcom_gtoolkit_main/glamoroustoolkit/GlamorousToolkit.app/Contents/MacOS/Plugins/libSkia.dylib'
...

[chisandrei]

Here is the startup order. ExternalObject >> #startUp: happens before FFIMethodRegistry >> #startUp:.

ExternalObject >> #startUp: sets all ExternalAddress in the image to null.
However, there is validate method in an FFI function which loads the symbol from a moduleName if a handle is null.

So if an FFI function is called after ExternalObject >> #startUp: but before or during FFIMethodRegistry >> #startUp: then we get this problem.

Ideally we should to make sure that finalizer does nothing during startUp: of the system:

• If finalizer wakes up before ExternalObject >> #startUp: then we get a hard crash due to double free memory
• If finalizer wakes up after ExternalObject >> #startUp: but before FFIMethodRegistry >> #startUp: then we get symbol not found error
• If finalizer wakes up after FFIMethodRegistry >> #startUp: then we are fine

Finalizer process is supposed to restart at priority 100, so after FFIMethodRegistry >> #startUp:. However, what about its process from before the save? WeakArray implements startUp: but not shutdown:. WeakArray could terminate the finalizer process on shutdown:, then it will not run during the init of the core of the system.

One possible solution could be:

This terminates the finalizer process regardless if we actually shutdown or not. The reason is that we must make sure that a saved image never has a running finalizer process. It is possible to save an image and just force quit it later.

[chisandrei]

To add to the previous comment seems like the issues that we are seeing might come from FinalizationRegistry>>#finalizeEphemeron:. To finalize an object the VM sends mourn to that object,
So it is not the finalization process that kicks in, it is the VM's GC during startUp:. From what we see this is the only difference in the weak behaviour between Pharo 10 and Pharo 11.

Seems that in Pharo 11, FinalizationRegistryEntry>mourn can be sent either by GC or by WeakArray class>finalizationProcess. In Pharo 10 it was just by WeakArray class>finalizationProcess and we did not see these issues.

[chisandrei]

The issue that we see seems related to FFIMethodRegistry getting into a bad state.

We saw we can get in FFIMethodRegistry multiple entries for the same compiled methods. We saw that for example, especially methods for performing the release of external objects, were executed from multiple processes. We also use quite a lot of background processes. To solve other bugs and be able to call the same FFI method from multiple threads in parallel we added to FFICalloutAPI>>#function:library: a mutex to make sure that it only gets compiled once. For example below we get two compiled methods for SkiaCompositionLayer class>>#primRelease:.

When looking at those multiple methods we saw that we can get into a situation where the ffiNonCompiledMethod property of an FFI method is actually another FFI method. This seems two happen as when same same FFI method is called in parallel from two processes, the first method is set correctly, and then the second time the same FFI method is compiled, the code sender methodClass methodDict at: sender selector. returns actually the FFI method, not the original one.

The side-effect of this is that when doing FFIMethodRegistry resetAll depending on the order in which the same versions of a method were restored, the reset could actually install in the class an FFI method instead of the original method. For example the code below shows that after a reset we were getting FFI methods installed in the image that were not in the registry.

So when we copy the image to a new platform or location those compiled methods were not refreshed and were pointing to the wrong libraries. This was leading to errors in various places. As a temporary fix, we changed the logic from FFICalloutAPI>>#function:library: to not install an FFI method if an FFI method is actually installed (feenkcom/gtoolkit-vm-bindings@8ae318e). So it should be safe to run the same FFI method in parallel and it will be installed in the registry only once.

In GT we extracted part of the logic from FFICalloutAPI>>#function:library: into a method so we can guard the compilation using a mutex: FFICalloutAPI>>#compileFunction:library:sender:. We noticed that if we add a signal to this method we get events that the same FFI method is compiled multiple times, for example SkiaPictureRecorder class>>#primRelease:.

If we look at the stack we notice that those calls are coming from different finalisation processes.

The only possibility for that is if we get multiple finalisation processes waiting on the mutex in FFICalloutAPI>>#compileFunction:library:sender:. In WeakArray class>>#finalizationProcess the first action is to signal the semaphore, so in theory if the current finalisation process gets stuck, another one could start.

We also saw cases when we got more compiled methods in a wrong state (this screenshot is from Pharo 10; all the ones above from Pharo 11):