Priority of WeakArray finalizationProcess

While testing JNIPort on Pharo 1.0 and Pharo 1.1, I noticed that in Pharo
1.0, a JVM (a wrapper object for the Java Virtual Machine) could be
initialized in ca. 4 seconds, while this needed 11 to 12 seconds in Pharo
1.1. When I profiled the JVM startup in 1.1, the profile reported that less
than 20% of the time was spent there; the rest was not accounted for in the
report.

In Squeak 4.1, I encountered a deadlock problem related to Squeak's current
WeakRegistry implementation when the JVM is started. This problem
disappeared when I changed the finalizationProcess of WeakArray such that it
runs at systemBackgroundPriority instead of userBackgroundPriority.

Applying the same change to Pharo 1.1 makes a big difference. The JVM starts
in 4.4 seconds, approximately matching the time it takes in Pharo 1.0.

Starting the JVM in Squeak 4.1 is about 20% faster than Pharo 1.1. As the
difference is in the part which is not accounted for by the time profiler,
it is probably due to the differences in the implementation of
WeakIdentityKeyDictionary which have an impact on the performance of the
finalizationProcess.

I am not sure if changing the priority of the finalizationProcess could
possibly break something, and I also do not yet understand why changing the
priority makes such a big difference both in Squeak and Pharo.

How should this issue be handled? Should I add this as issues to the bug
tracking tools for Pharo and Squeak respectively?

Cheers,
Joachim Geidel

On Sat, 12 Jun 2010, Joachim Geidel wrote:

I think normal processes (with priority 40) could starve the finalization
process if it's priority were <= 40 (#systemBackgroundPriority is 20).

>
> How should this issue be handled? Should I add this as issues to the bug
> tracking tools for Pharo and Squeak respectively?

I uploaded a fix to the Inbox: Collections-ul.362. If you're using a Trunk
image, just update it and load this package to your image. If you're using
a stock 4.1 image, then the easiest way to get the fix, is to add the
following line to the end of WeakKeyDictionary >> #finalizeValues

cleanUpAfterRemove ifTrue: [ self fixCollisionsFrom: array size ]

If you have the time, please check if this fixes the issue for Squeak.


Levente

>
> Cheers,
> Joachim Geidel
>
>
>
>

Am 12.06.10 21:47 schrieb Levente Uzonyi:
> On Sat, 12 Jun 2010, Joachim Geidel wrote:
>> I am not sure if changing the priority of the finalizationProcess could
>> possibly break something, and I also do not yet understand why changing the
>> priority makes such a big difference both in Squeak and Pharo.
>
> I think normal processes (with priority 40) could starve the finalization
> process if it's priority were <= 40 (#systemBackgroundPriority is 20).

That's true, I hadn't thought of that.
 
Unfortunately, this doesn't help with the deadlock issue.

Cheers,
Joachim Geidel

On Sun, 13 Jun 2010, Joachim Geidel wrote:

That's bad news. I tried to start the JVM again with the following
snippet:

| jvmSettings |
JNIPortJNIInterface libraryFile: 'C:\Program
Files\Java\jre6\bin\client\jvm.dll'.
  jvmSettings := (JVMSettings new)
  name: 'JVM with ghost class generation';
  yourself.
  jvmSettings usesGhosts: true.
  jvmSettings jniPortSettings useJNIHelperLibrary: false.
  jvmSettings runtimeSettings classpath:
'.;C:\Users\Levi\Desktop\SQUEAK\Squeak4.1-win32\JNIPort.jar;C:\Users\Levi\Desktop\SQUEAK\Squeak4.1-win32\JNIPort-Tests.jar'.
  Cursor execute showWhile: [JVM newWithSettings: jvmSettings].

But it crashes:

Current byte code: 98
Primitive index: 1060

Loaded plugins:
  C:\Program Files\Java\jre6\bin\client\jvm.dll
  IA32ABI 1 May 2010 (e)
  LocalePlugin 29 April 2010 (i)
  B2DPlugin 29 April 2010 (i)
  BitBltPlugin 29 April 2010 (i)
  SecurityPlugin 29 April 2010 (i)
  FilePlugin 29 April 2010 (i)
  LargeIntegers v1.5 29 April 2010 (i)
  MiscPrimitivePlugin 29 April 2010 (i)

The Smalltalk Stack:
289028824 JNIVTableMethod>call:
289027948 JNIPortVTableClient>call:withArguments:
289027828 JNIPortVTableClient>call:with:with:
289027736 JNIPortJNIEnv>EnsureLocalCapacity_capacity:
289027644 JVM>initializeLocalCapacity
288899024 JVM>initializeFromSettings:
288898932 JVM class>newWithSettings:
288898672 UndefinedObject>?
288898580 BlockClosure>ensure:
288898488 Cursor>showWhile:
288897964 UndefinedObject>?
288890960 Compiler>evaluate:in:to:notifying:ifFail:logged:
288890868 TextEditor>evaluateSelection
288890776 BlockClosure>on:do:
288890684 TextEditor>evaluateSelection
288890592 TextEditor>doIt

Any ideas how I could start it without crashing?


Levente

>
> Cheers,
> Joachim Geidel
>
>
>
>

After finding the "official" download for the IAB32 plugin binary at
http://code.google.com/p/pharo/issues/detail?id=1360, comment #3, attachment
squeakVMWithAlien.zip, I could run a first test of JNIPort in Squeak 4.1 on
Windows XP SP3.

It exhibited the same deadlock I saw on Mac OS X, and the deadlock went away
when I prevented finalization to run in parallel to the JVM startup by
lowering the priority of the finalizationProcess to 20. So the problem does
not seem to be platform dependent.

The JNIPort tests pass except for one failure because of the broken UTF-16
encoder (http://bugs.squeak.org/view.php?id=7544) and three errors because
the function vsnprintf is not found in the standard library, but this is
only needed for a special callback hook of the Java virtual machine which
allows redirecting debugging output such that it can be traced in Smalltalk
instead being emitted on stderr.

I don't have the crashes you see. I just used the VM and IAB32ABI.dll which
are in squeakVMWithAlien.zip. What operating system do you have? Is it a 64
bit system?

Joachim

Am 13.06.10 14:46 schrieb Levente Uzonyi:

On Sun, 13 Jun 2010, Joachim Geidel wrote:

I used Igor's NativeBoost VM, since it has the Alien plugin, but something
must be wrong with that, because the code works with the VM you linked.

So I could start the JVM and reproduce the deadlock. The problem seems to
be that somehow the JVM's mutex (sharedMutex) is not released by the UI
process (which is starting the JVM). When I interrupt the process, I get a
debugger with this stack trace:

[] in Semaphore>>critical:
BlockClosure>>ensure:
Semaphore>>critical:
Semaphore>>critical:ifError:
JNIPortWeakRegistry(WeakRegistry)>>protected:
JNIPortWeakRegistry(WeakRegistry)>>add:executor:
JNIPortWeakRegistry(WeakRegistry)>>add:
JNIPortWeakRegistry>>registerValueOf:
JVMWithoutCallbacks(JVM)>>own:
JavaLangReflectMethod(JavaClassInstance)>>jniObject:static:
etc.

If I select JVMWithoutCallbacks(JVM)>>own: in the debugger and inspect the
instance variable "sharedMutex", I find that the UI process is still the
owner of the mutex, the mutex's semaphore has no signals and the process
is in the list of the semaphore. But the process is not in the critical
section of the mutex, because the block containing the #critical: send is
already evaluated (JNIPortWeakRegistry>>registerValueOf:). So the mutex is
"locked", but it's not used by the process that "locks" it.
The deadlock occurs, because the finalization process is trying to access
the same mutex to finalize the objects, while it's also in the critical
section of the WeakRegistry's semaphore. While this is happening, the UI
process is trying to register new objects to the WeakRegistry.
I couldn't find out how can the Mutex have this invalid state.


Levente

Am 13.06.10 20:35 schrieb Levente Uzonyi:

I am going to look into this, but this week I am quite busy, so it may take
some time.

However, I think that it's unsafe to send #finalize to the executors while
WeakRegistry is still in the protected block in finalizeValues. You don't
have control over what finalize is doing, and this can lead to deadlocks if
a #finalize waits on a Semaphore. Would it be possible to collect the
objects to be finalized in a collection in the protected block, and finalize
them afterwards?

Joachim

On Mon, 14 Jun 2010, Joachim Geidel wrote:

After looking at the deadlock again, I found that it's a simple 2 process
- 2 lock circular wait deadlock.

Here is the stack trace of the user process (which isn't the UI process
as I called it previously):
[] in Semaphore>>critical:
BlockClosure>>ensure:
Semaphore>>critical:
Semaphore>>critical:ifError:
JNIPortWeakRegistry(WeakRegistry)>>protected:
JNIPortWeakRegistry(WeakRegistry)>>add:executor:
JNIPortWeakRegistry(WeakRegistry)>>add:
JNIPortWeakRegistry>>registerValueOf:
JVMWithoutCallbacks(JVM)>>own:
JavaLangReflectMethod(JavaClassInstance)>>jniObject:static:
JavaLangReflectMethod class(JavaClassInstance class)>>jniObject:static:
StaticJavaLangObject(JavaClassStatic)>>basicWrapJNIObject:
[] in StaticJavaLangObject(JavaClassStatic)>>wrapJNIObject:
JavaObjectRegistry>>basicFindOrRelease:ifAbsentPut:
[] in JavaObjectRegistry>>findOrRelease:ifAbsentPut:
BlockClosure>>ensure:
[] in Mutex>>critical:
[] in Semaphore>>critical:
BlockClosure>>ensure:
Semaphore>>critical:

And here is the finalization process' stack trace:
[] in Semaphore>>critical:
BlockClosure>>ensure:
Semaphore>>critical:
Mutex>>critical:
JVMWithoutCallbacks(JVM)>>disown:
JavaLangReflectMethod(JavaClassInstance)>>free
JavaLangReflectMethod(JavaClassInstance)>>finalize
ByteSymbol(Symbol)>>value:
WeakIdentityKeyDictionary(WeakKeyDictionary)>>finalizeValues
[] in JNIPortWeakRegistry(WeakRegistry)>>finalizeValues
[] in [] in Semaphore>>critical:ifError:
BlockClosure>>on:do:
BlockClosure>>ifError:
[] in Semaphore>>critical:ifError:
[] in Semaphore>>critical:
BlockClosure>>ensure:
Semaphore>>critical:
Semaphore>>critical:ifError:
JNIPortWeakRegistry(WeakRegistry)>>protected:
JNIPortWeakRegistry(WeakRegistry)>>finalizeValues

So the user process entered the mutex of the JVM and it's trying to enter
the WeakRegistry's semaphore, while the finalization process entered the
WeakRegistry's semaphore and it's trying to enter the JVM's mutex.

(The mutex's owner was is not nil when the deadlock happens, because the
code enters the mutex more than once, so that's normal.)

This deadlock doesn't happen in Pharo, because it uses the old
WeakRegistry >> #finalizeValues implementation which does the actual
finalization outside the critical section. I will soon upload a version of
the Collections package to the Inbox which does the same. With this code
it took 2.9 seconds to start the JVM on my notebook.


Levente

>
> Joachim
>
>
>
>

Levente,

Thanks a lot for analyzing this! I think I should have a more thorough look
at all those Semaphores and Mutexes in JNIPort. Maybe some of them can be
eliminated, which would also be better for performance.

2.9 seconds sound good even though in VisualWorks it's in the sub-second
range. OTOH, the JVM is started just once when an application runs, and I
have some optimizations ready for the final release of JNIPort.

Thanks again
Joachim

Am 14.06.10 22:06 schrieb Levente Uzonyi:

On Tue, 15 Jun 2010, Joachim Geidel wrote:

> Levente,
>
> Thanks a lot for analyzing this! I think I should have a more thorough look
> at all those Semaphores and Mutexes in JNIPort. Maybe some of them can be
> eliminated, which would also be better for performance.
>
> 2.9 seconds sound good even though in VisualWorks it's in the sub-second
> range. OTOH, the JVM is started just once when an application runs, and I
> have some optimizations ready for the final release of JNIPort.

If Igor's new finalization mechanism will be integrated (in 4.2), then it
will be possible to cut 0.3 seconds down from the runtime. I also expect
that in 1-2 years we will have an inlining JIT available which could get
the execution time into the sub-second range.


Levente