Skip to content

Commit 9d2dfc5

Browse files
jonpryorjonpryor
committed
[Android.Interop-Tests] Dig deeper in performance differences
Commit 03f8d12 suggests that Java method invocations with Java.Interop take ~36x as much time as the equivalent method invocation within Xamarin.Android; why is that? What more information can we determine? Throw in several more tests, collate the results, and print them all to stdout: # "Full" Invocations: JNIEnv::CallObjectMethod() + JNIEnv::DeleteLocalRef() for 10000 iterations Java.Interop Object.toString() Timing: 00:00:14.3097031; 1.43097031 ms/iteration -- ~184.765063313367x Xamarin.Android Object.toString() Timing: 00:00:00.0774481; 0.00774481 ms/iteration # JNIEnv::CallObjectMethod() for 500 iterations Java.Interop Object.toString() Timing: 00:00:00.0164056; 0.0328112 ms/CallVirtualObjectMethod() -- ~5.47400734067401x Xamarin.Android CallObjectMethod() Timing: 00:00:00.0029970; 0.005994 ms/CallObjectMethod() # JNIEnv::DeleteLocalRef() for 500 iterations Java.Interop JniLocalReference.Dispose() Timing: 00:00:00.7162322; 1.4324644 ms/Dispose() -- ~1391.82316362223x Xamarin.Android DeleteLocalRef() Timing: 00:00:00.0005146; 0.0010292 ms/DeleteLocalRef() ## Breaking down the above Object.toString() + JniLocalReference.Dispose() timings, the JNI calls: # JNIEnv::CallObjectMethod: SafeHandle vs. IntPtr Java.Interop safeCall() Timing: 00:00:00.0049525; 0.009905 ms/SafeHandle JNIEnv::CallObjectMethodA() -- ~2.04682592163994x Java.Interop unsafeCall() Timing: 00:00:00.0024196; 0.0048392 ms/IntPtr JNIEnv::CallObjectMethodA() # JNIEnv::DeleteLocalRef: SafeHandle vs. IntPtr Java.Interop safeDel() Timing: 00:00:00.0005431; 0.0010862 ms/SafeHandle JNIEnv::DeleteLocalRef() -- ~1.38123092573754x Java.Interop unsafeDel() Timing: 00:00:00.0003932; 0.0007864 ms/IntPtr JNIEnv::DeleteLocalRef More analysis needs to be done, as the numbers can be all over the place -- usually the "Full" overhead is ~36x, not 184x, but it varies by quite a lot. More importantly is *why* the Java.Interop times are so much longer than the Xamarin.Android times. That brings us to the second and third sets of numbers for JNIEnv::CallObjectMethod() and JNIEnv::DeleteLocalRef(). We can see that JniInstanceMethodID.CallVirtualObjectMethod() takes ~5x longer than JNIEnv.CallObjectMethod(), but the real killer is that JniLocalReference.Dispose() takes (here) ~1391x longer than JNIEnv::DeleteLocalRef()! The cause for this is that there's a lot of "bookkeeping" work around JniLocalReferences -- see commits 2f9fece and b2f0d6a, presumably among others -- and this bookkeeping has large costs associated with it. Unfortunately, *everything* uses JNI Local References, so this extra work shows up *everywhere*. :-( Moving on, we hit the next question: how much overhead does using SafeHandle types vs. IntPtr create? In the case of a SafeHandle-based JNIEnv::CallObjectMethod() and JNIEnv::DeleteLocalRef(), we see that using SafeHandles results in ~20% - 100%+ overhead, depending on I have absolutely no idea (it varies A LOT). Why the overheads on using SafeHandle types? > kumpera: that's by design! > basically it turns Foo(sf) into: > sf.DangerousAddRef (); Foo (sf.handle); sf.DangerousRelease () > that requires a pair of CAS > jonp: because it needs to be threadsafe. :-( > kumpera: yes > and safe. All of which provides more fodder for asking: how much additional overhead is acceptable, and what can be done to fix it? Aside/Note: One oddity to ask/observe is that this patch adds SafeHandleDelegate_CallObjectMethodA and SafeHandleDelegate_DeleteLocalRef types to Android.Interop.dll. Why? The reason why is because if those types are instead declared in Android.Interop-Tests.dll, things blow up REAL GOOD: [FAIL] CompareJniInvocationTiming : System.NullReferenceException : Object reference not set to an instance of an object at System.Runtime.InteropServices.SafeHandle.DangerousAddRef (System.Boolean& success) [0x00000] in <filename unknown>:0 at (wrapper managed-to-native) object:wrapper_native_0xb4db2a69 (Java.Interop.JniEnvironmentSafeHandle,Java.Interop.JniReferenceSafeHandle,Java.Interop.JniInstanceMethodID,Java.Interop.JValue[]) at (wrapper delegate-invoke) <Module>:invoke_intptr_intptr_intptr_intptr_JValue[] (intptr,intptr,intptr,Java.Interop.JValue[]) at Android.InteropTests.TestsSample.GetJICallObjectMethodAndDeleteLocalRefTimings (System.TimeSpan& callVirtualObjectMethodTime, System.TimeSpan& disposeTime, System.TimeSpan& safeCallObjectMethodTime, System.TimeSpan& safeDeleteLocalRefTime, System.TimeSpan Time, System.TimeSpan& unsafeDeleteLocalRefTime) [0x00269] in /Users/jon/Dropbox/Developer/Java.Interop/src/Android.Interop/Tests/TestsSample.cs:164 at Android.InteropTests.TestsSample.CompareJniInvocationTiming () [0x00026] in /Users/jon/Dropbox/Developer/Java.Interop/src/Android.Interop/Tests/TestsSample.cs:188 at (wrapper managed-to-native) System.Reflection.MonoMethod:InternalInvoke (System.Reflection.MonoMethod,object,object[],System.Exception&) at System.Reflection.MonoMethod.Invoke (System.Object obj, BindingFlags invokeAttr, System.Reflection.Binder binder, System.Object[] parameters, System.Globalization.CultureInfo culture) [0x00000] in <filename unknown>:0 The above stack trace was generated by copying the SafeHandleDelegate_CallObjectMethodA and SafeHandleDelegate_DeleteLocalRef declarations from AndroidVM.cs into TestsSample.cs, then run the app, run the tests, and the tests fail with the above. What's "interesting" is that the call stack is accurrate, but insane. What TestsSample.GetJICallObjectMethodAndDeleteLocalRefTimings() does is grab the function pointer for JNIEnv::CallObjectMethodA, then create two different delegates around those function pointers: IntPtr JNIEnv_CallObjectMethodA = Marshal.ReadIntPtr (Marshal.ReadIntPtr (JNIEnv.Handle), JNIEnvOffset_CallObjectMethodA); var safeCall = (SafeHandleDelegate_CallObjectMethodA) Marshal.GetDelegateForFunctionPointer (JNIEnv_CallObjectMethodA, typeof (SafeHandleDelegate_CallObjectMethodA)); var usafeCall = (IntPtrDelegate_CallObjectMethodA) Marshal.GetDelegateForFunctionPointer (JNIEnv_CallObjectMethodA, typeof (IntPtrDelegate_CallObjectMethodA)); These delegates are then invoked; invoking safeCall() works, but invoking usafeCall() fails: urs [i] = usafeCall (uh, uo, ut, args); i.e. we're invoking a delegate of type IntPtrDelegate_CallObjectMethodA, which uses IntPtrs, not SafeHandles, yet the call stack states that we're invoking SafeHandle.DangerousAddRef()! (Wat.) There appears to be some internal mono sharing of the function pointer, causing the two separate delegates, with two separate delegate types, to use the same codepath. Wat. But that only happens if the delegate types are declared in the Android.Interop-Tests.dll assembly! Move the declaration of one of the "pair" to another assembly, and the code works as expected.
1 parent 03f8d12 commit 9d2dfc5

File tree

3 files changed

+198
-10
lines changed

3 files changed

+198
-10
lines changed

‎src/Android.Interop/Java.Interop/AndroidVM.cs

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,10 @@
44

55
namespace Java.Interop {
66

7+
// FOR TEST PURPOSES ONLY
8+
public delegate JniLocalReference SafeHandleDelegate_CallObjectMethodA (JniEnvironmentSafeHandle env, JniReferenceSafeHandle instance, JniInstanceMethodID method, JValue[] args);
9+
public delegate void SafeHandleDelegate_DeleteLocalRef (JniEnvironmentSafeHandle env, IntPtr handle);
10+
711
class AndroidVMBuilder : JavaVMOptions {
812

913
public AndroidVMBuilder ()

‎src/Android.Interop/Tests/Android.Interop-Tests.csproj

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -47,7 +47,9 @@
4747
<Reference Include="Xamarin.Android.NUnitLite" />
4848
</ItemGroup>
4949
<ItemGroup>
50-
<Compile Include="MainActivity.cs" />
50+
<Compile Include="MainActivity.cs">
51+
<DependentUpon>TestsSample.cs</DependentUpon>
52+
</Compile>
5153
<Compile Include="TestsSample.cs" />
5254
<Compile Include="Resources\Resource.designer.cs" />
5355
<Compile Include="Properties\AssemblyInfo.cs" />

‎src/Android.Interop/Tests/TestsSample.cs

Lines changed: 191 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,53 +1,235 @@
11
using System;
22
using System.Diagnostics;
3+
using System.Runtime.InteropServices;
34

45
using NUnit.Framework;
56

67
using Android.Runtime;
78

89
using Java.Interop;
910

11+
using JValue = Java.Interop.JValue;
12+
1013
namespace Android.InteropTests {
1114

15+
delegate IntPtr IntPtrDelegate_CallObjectMethodA (IntPtr env, IntPtr instance, IntPtr method, JValue[] args);
16+
delegate void IntPtrDelegate_DeleteLocalRef (IntPtr env, IntPtr handle);
17+
1218
[TestFixture]
1319
public class TestsSample {
1420

15-
const int ToString_Iterations = 10000;
21+
const int Unified_ToString_Iterations = 10000;
22+
const int MaxLocalRefs = 500;
1623

17-
[Test]
18-
public void XAMethodCallTimings ()
24+
// offsetof (JNIEnv, CallObjectMethodA)/sizeof(void*)
25+
const int JNIEnvIndex_CallObjectMethodA = 36;
26+
27+
// offsetof (JNIEnv, DeleteLocalRef)/sizeof(void*)
28+
const int JNIEnvIndex_DeleteLocalRef = 23;
29+
30+
static readonly int JNIEnvOffset_CallObjectMethodA = JNIEnvIndex_CallObjectMethodA * IntPtr.Size;
31+
static readonly int JNIEnvOffset_DeleteLocalRef = JNIEnvIndex_DeleteLocalRef * IntPtr.Size;
32+
33+
TimeSpan GetXAMethodCallTiming ()
1934
{
2035
var k = JNIEnv.FindClass ("java/lang/Object");
2136
var c = JNIEnv.GetMethodID (k, "<init>", "()V");
2237
var o = JNIEnv.NewObject (k, c);
2338
var t = JNIEnv.GetMethodID (k, "toString", "()Ljava/lang/String;");
2439

2540
var sw = Stopwatch.StartNew ();
26-
for (int i = 0; i < ToString_Iterations; ++i) {
41+
for (int i = 0; i < Unified_ToString_Iterations; ++i) {
2742
var r = JNIEnv.CallObjectMethod (o, t);
2843
JNIEnv.DeleteLocalRef (r);
2944
}
3045
sw.Stop ();
31-
Console.WriteLine ("Xamarin.Android Object.toString() Timing: {0}", sw.Elapsed);
46+
return sw.Elapsed;
3247
}
3348

34-
[Test]
35-
public void JIMethodCallTimings ()
49+
TimeSpan GetJIMethodCallTiming ()
3650
{
3751
using (var k = new JniType ("java/lang/Object"))
3852
using (var c = k.GetConstructor ("()V"))
3953
using (var o = k.NewObject (c))
4054
using (var t = k.GetInstanceMethod ("toString", "()Ljava/lang/String;")) {
4155

4256
var sw = Stopwatch.StartNew ();
43-
for (int i = 0; i < ToString_Iterations; ++i) {
57+
for (int i = 0; i < Unified_ToString_Iterations; ++i) {
4458
using (var r = t.CallVirtualObjectMethod (o)) {
4559
}
4660
}
4761
sw.Stop ();
48-
Console.WriteLine (" Java.Interop Object.toString() Timing: {0}", sw.Elapsed);
62+
return sw.Elapsed;
63+
}
64+
}
65+
66+
void GetXACallObjectMethodAndDeleteLocalRefTimings (out TimeSpan callObjectMethodTiming, out TimeSpan deleteLocalRefTiming)
67+
{
68+
var k = JNIEnv.FindClass ("java/lang/Object");
69+
var c = JNIEnv.GetMethodID (k, "<init>", "()V");
70+
var o = JNIEnv.NewObject (k, c);
71+
var t = JNIEnv.GetMethodID (k, "toString", "()Ljava/lang/String;");
72+
73+
do {
74+
var r = JNIEnv.CallObjectMethod (o, t);
75+
JNIEnv.DeleteLocalRef (r);
76+
} while (false);
77+
78+
var rs = new IntPtr [MaxLocalRefs];
79+
80+
var sw = Stopwatch.StartNew ();
81+
for (int i = 0; i < MaxLocalRefs; ++i) {
82+
rs [i] = JNIEnv.CallObjectMethod (o, t);
83+
}
84+
sw.Stop ();
85+
callObjectMethodTiming = sw.Elapsed;
86+
87+
sw.Restart ();
88+
for (int i = 0; i < MaxLocalRefs; ++i) {
89+
JNIEnv.DeleteLocalRef (rs [i]);
90+
}
91+
sw.Stop ();
92+
deleteLocalRefTiming = sw.Elapsed;
93+
}
94+
95+
void GetJICallObjectMethodAndDeleteLocalRefTimings (
96+
out TimeSpan callVirtualObjectMethodTime, out TimeSpan disposeTime,
97+
out TimeSpan safeCallObjectMethodTime, out TimeSpan safeDeleteLocalRefTime,
98+
out TimeSpan unsafeCallObjectMethodTime, out TimeSpan unsafeDeleteLocalRefTime)
99+
{
100+
101+
using (var k = new JniType ("java/lang/Object"))
102+
using (var c = k.GetConstructor ("()V"))
103+
using (var o = k.NewObject (c))
104+
using (var t = k.GetInstanceMethod ("toString", "()Ljava/lang/String;")) {
105+
106+
using (var r = t.CallVirtualObjectMethod (o)) {
107+
}
108+
109+
var rs = new JniLocalReference [MaxLocalRefs];
110+
111+
var sw = Stopwatch.StartNew ();
112+
for (int i = 0; i < rs.Length; ++i) {
113+
rs [i] = t.CallVirtualObjectMethod (o);
114+
}
115+
sw.Stop ();
116+
callVirtualObjectMethodTime = sw.Elapsed;
117+
118+
sw.Restart ();
119+
for (int i = 0; i < rs.Length; ++i) {
120+
rs [i].Dispose ();
121+
}
122+
sw.Stop ();
123+
disposeTime = sw.Elapsed;
124+
125+
IntPtr JNIEnv_CallObjectMethodA = Marshal.ReadIntPtr (Marshal.ReadIntPtr (JNIEnv.Handle), JNIEnvOffset_CallObjectMethodA);
126+
IntPtr JNIEnv_DeleteLocalRef = Marshal.ReadIntPtr (Marshal.ReadIntPtr (JNIEnv.Handle), JNIEnvOffset_DeleteLocalRef);
127+
128+
var safeCall = (SafeHandleDelegate_CallObjectMethodA)
129+
Marshal.GetDelegateForFunctionPointer (JNIEnv_CallObjectMethodA, typeof (SafeHandleDelegate_CallObjectMethodA));
130+
var safeDel = (SafeHandleDelegate_DeleteLocalRef)
131+
Marshal.GetDelegateForFunctionPointer (JNIEnv_DeleteLocalRef, typeof (SafeHandleDelegate_DeleteLocalRef));
132+
var usafeCall = (IntPtrDelegate_CallObjectMethodA)
133+
Marshal.GetDelegateForFunctionPointer (JNIEnv_CallObjectMethodA, typeof (IntPtrDelegate_CallObjectMethodA));
134+
var usafeDel = (IntPtrDelegate_DeleteLocalRef)
135+
Marshal.GetDelegateForFunctionPointer (JNIEnv_DeleteLocalRef, typeof (IntPtrDelegate_DeleteLocalRef));
136+
137+
var sh = JniEnvironment.Current.SafeHandle;
138+
var uh = sh.DangerousGetHandle ();
139+
var args = new JValue [0];
140+
141+
sw.Restart ();
142+
for (int i = 0; i < rs.Length; ++i) {
143+
rs [i] = safeCall (sh, o, t, args);
144+
}
145+
sw.Stop ();
146+
safeCallObjectMethodTime = sw.Elapsed;
147+
148+
sw.Restart ();
149+
for (int i = 0; i < rs.Length; ++i) {
150+
safeDel (sh, rs [i].DangerousGetHandle ());
151+
rs [i].SetHandleAsInvalid ();
152+
}
153+
sw.Stop ();
154+
safeDeleteLocalRefTime = sw.Elapsed;
155+
156+
var urs = new IntPtr [MaxLocalRefs];
157+
var ut = t.DangerousGetHandle ();
158+
var uo = o.DangerousGetHandle ();
159+
160+
sw.Restart ();
161+
for (int i = 0; i < urs.Length; ++i) {
162+
urs [i] = usafeCall (uh, uo, ut, args);
163+
}
164+
sw.Stop ();
165+
unsafeCallObjectMethodTime = sw.Elapsed;
166+
167+
sw.Restart ();
168+
for (int i = 0; i < urs.Length; ++i) {
169+
usafeDel (uh, urs [i]);
170+
}
171+
sw.Stop ();
172+
unsafeDeleteLocalRefTime = sw.Elapsed;
49173
}
50174
}
175+
176+
[Test]
177+
public void CompareJniInvocationTiming ()
178+
{
179+
var jiFullMethodCallTiming = GetJIMethodCallTiming ();
180+
var xaFullMethodCallTiming = GetXAMethodCallTiming ();
181+
182+
TimeSpan xaCallObjectMethodTime, xaDeleteLocalRefTime;
183+
GetXACallObjectMethodAndDeleteLocalRefTimings (out xaCallObjectMethodTime, out xaDeleteLocalRefTime);
184+
185+
TimeSpan callVirtualObjectMethodTiming, disposeTiming, safeCallTime, safeDelTime, unsafeCallTime, unsafeDelTime;
186+
GetJICallObjectMethodAndDeleteLocalRefTimings (out callVirtualObjectMethodTiming, out disposeTiming, out safeCallTime, out safeDelTime, out unsafeCallTime, out unsafeDelTime);
187+
188+
Console.WriteLine ("# \"Full\" Invocations: JNIEnv::CallObjectMethod() + JNIEnv::DeleteLocalRef() for {0} iterations", Unified_ToString_Iterations);
189+
Console.WriteLine (" Java.Interop Object.toString() Timing: {0}; {1,12} ms/iteration -- ~{2}x",
190+
jiFullMethodCallTiming,
191+
jiFullMethodCallTiming.TotalMilliseconds / Unified_ToString_Iterations,
192+
jiFullMethodCallTiming.TotalMilliseconds / xaFullMethodCallTiming.TotalMilliseconds);
193+
Console.WriteLine (" Xamarin.Android Object.toString() Timing: {0}; {1,12} ms/iteration",
194+
xaFullMethodCallTiming,
195+
xaFullMethodCallTiming.TotalMilliseconds / Unified_ToString_Iterations);
196+
197+
Console.WriteLine ("# JNIEnv::CallObjectMethod() for {0} iterations", MaxLocalRefs);
198+
Console.WriteLine (" Java.Interop Object.toString() Timing: {0}; {1,12} ms/CallVirtualObjectMethod() -- ~{2}x",
199+
callVirtualObjectMethodTiming,
200+
callVirtualObjectMethodTiming.TotalMilliseconds / MaxLocalRefs,
201+
callVirtualObjectMethodTiming.TotalMilliseconds / xaCallObjectMethodTime.TotalMilliseconds);
202+
Console.WriteLine (" Xamarin.Android CallObjectMethod() Timing: {0}; {1,12} ms/CallObjectMethod()",
203+
xaCallObjectMethodTime,
204+
xaCallObjectMethodTime.TotalMilliseconds / MaxLocalRefs);
205+
206+
Console.WriteLine ("# JNIEnv::DeleteLocalRef() for {0} iterations", MaxLocalRefs);
207+
Console.WriteLine (" Java.Interop JniLocalReference.Dispose() Timing: {0}; {1,12} ms/Dispose() -- ~{2}x",
208+
disposeTiming,
209+
disposeTiming.TotalMilliseconds / MaxLocalRefs,
210+
disposeTiming.TotalMilliseconds / xaDeleteLocalRefTime.TotalMilliseconds);
211+
Console.WriteLine (" Xamarin.Android DeleteLocalRef() Timing: {0}; {1,12} ms/DeleteLocalRef()",
212+
xaDeleteLocalRefTime,
213+
xaDeleteLocalRefTime.TotalMilliseconds / MaxLocalRefs);
214+
215+
Console.WriteLine ("## Breaking down the above Object.toString() + JniLocalReference.Dispose() timings, the JNI calls:");
216+
Console.WriteLine ("# JNIEnv::CallObjectMethod: SafeHandle vs. IntPtr");
217+
Console.WriteLine (" Java.Interop safeCall() Timing: {0}; {1,12} ms/SafeHandle JNIEnv::CallObjectMethodA() -- ~{2}x",
218+
safeCallTime,
219+
safeCallTime.TotalMilliseconds / MaxLocalRefs,
220+
safeCallTime.TotalMilliseconds / unsafeCallTime.TotalMilliseconds);
221+
Console.WriteLine (" Java.Interop unsafeCall() Timing: {0}; {1,12} ms/IntPtr JNIEnv::CallObjectMethodA()",
222+
unsafeCallTime,
223+
unsafeCallTime.TotalMilliseconds / MaxLocalRefs);
224+
Console.WriteLine ("# JNIEnv::DeleteLocalRef: SafeHandle vs. IntPtr");
225+
Console.WriteLine (" Java.Interop safeDel() Timing: {0}; {1,12} ms/SafeHandle JNIEnv::DeleteLocalRef() -- ~{2}x",
226+
safeDelTime,
227+
safeDelTime.TotalMilliseconds / MaxLocalRefs,
228+
safeDelTime.TotalMilliseconds / unsafeDelTime.TotalMilliseconds);
229+
Console.WriteLine (" Java.Interop unsafeDel() Timing: {0}; {1,12} ms/IntPtr JNIEnv::DeleteLocalRef",
230+
unsafeDelTime,
231+
unsafeDelTime.TotalMilliseconds / MaxLocalRefs);
232+
}
51233
}
52234
}
53235

0 commit comments

Comments
 (0)