Bug 1145, Bug 1172: Add performance counter for native-jar lookup: Property 'jogamp.debug.JNILibLoader.Perf'

2 files changed, 29 insertions, 6 deletions

diff --git a/make/scripts/runtest.sh b/make/scripts/runtest.sh
index 2461771..8b7ed11 100755
--- a/make/scripts/runtest.sh
+++ b/make/scripts/runtest.sh
@@ -50,12 +50,13 @@ X_ARGS="-Drootrel.build=$ROOTREL_BUILD -Dgluegen.root=$GLUEGEN_ROOT"
 #D_ARGS="-Djogamp.debug.TempJarCache"
 #D_ARGS="-Djogamp.debug.TempFileCache"
 #D_ARGS="-Djogamp.debug.IOUtil -Djogamp.debug.JNILibLoader -Djogamp.debug.TempFileCache -Djogamp.debug.JarUtil -Djava.io.tmpdir=/run/tmp"
-D_ARGS="-Djogamp.debug.IOUtil -Djogamp.debug.JNILibLoader -Djogamp.debug.TempFileCache -Djogamp.debug.JarUtil -Djogamp.debug.TempJarCache"
+#D_ARGS="-Djogamp.debug.IOUtil -Djogamp.debug.JNILibLoader -Djogamp.debug.TempFileCache -Djogamp.debug.JarUtil -Djogamp.debug.TempJarCache"
 #D_ARGS="-Djogamp.debug.IOUtil -Djogamp.debug.JarUtil -Djogamp.debug.TempJarCache -Djogamp.debug.Uri -Djogamp.debug.Uri.ShowFix"
 #D_ARGS="-Djogamp.debug.Uri -Djogamp.debug.Uri.ShowFix"
 #D_ARGS="-Djogamp.debug.JNILibLoader -Djogamp.gluegen.UseTempJarCache=false"
 #D_ARGS="-Djogamp.debug.JNILibLoader -Djogamp.debug.TempJarCache"
 #D_ARGS="-Djogamp.debug.JNILibLoader"
+D_ARGS="-Djogamp.debug.JNILibLoader.Perf"
 #D_ARGS="-Djogamp.debug.Lock"
 #D_ARGS="-Djogamp.debug.Lock -Djogamp.debug.Lock.TraceLock"
 #D_ARGS="-Djogamp.debug.Lock.TraceLock"
@@ -86,7 +87,7 @@ function onetest() {
     echo
 }
 #
-#onetest com.jogamp.common.GlueGenVersion 2>&1 | tee -a $LOG
+onetest com.jogamp.common.GlueGenVersion 2>&1 | tee -a $LOG
 #onetest com.jogamp.common.util.TestSystemPropsAndEnvs 2>&1 | tee -a $LOG
 #onetest com.jogamp.common.util.TestVersionInfo 2>&1 | tee -a $LOG
 #onetest com.jogamp.common.util.TestVersionNumber 2>&1 | tee -a $LOG
@@ -144,7 +145,7 @@ function onetest() {
 #onetest com.jogamp.gluegen.jcpp.PreprocessorTest 2>&1 | tee -a $LOG
 
 #onetest com.jogamp.gluegen.test.junit.generation.Test1p1JavaEmitter 2>&1 | tee -a $LOG
-onetest com.jogamp.gluegen.test.junit.generation.Test1p2ProcAddressEmitter 2>&1 | tee -a $LOG
+#onetest com.jogamp.gluegen.test.junit.generation.Test1p2ProcAddressEmitter 2>&1 | tee -a $LOG
 #onetest com.jogamp.gluegen.test.junit.generation.Test1p2LoadJNIAndImplLib 2>&1 | tee -a $LOG
 #onetest com.jogamp.gluegen.test.junit.structgen.TestStructGen01 2>&1 | tee -a $LOG
 #onetest com.jogamp.gluegen.test.junit.structgen.TestStructGen02 2>&1 | tee -a $LOG
diff --git a/src/java/com/jogamp/common/jvm/JNILibLoaderBase.java b/src/java/com/jogamp/common/jvm/JNILibLoaderBase.java
index 9bf0617..3ba8dff 100644
--- a/src/java/com/jogamp/common/jvm/JNILibLoaderBase.java
+++ b/src/java/com/jogamp/common/jvm/JNILibLoaderBase.java
@@ -61,7 +61,18 @@ import jogamp.common.Debug;
 import jogamp.common.os.PlatformPropsImpl;
 
 public class JNILibLoaderBase {
-  public static final boolean DEBUG = Debug.debug("JNILibLoader");
+  public static final boolean DEBUG;
+  protected static final boolean PERF;
+
+  static {
+      Debug.initSingleton();
+      DEBUG = Debug.debug("JNILibLoader");
+      PERF = DEBUG || PropertyAccess.isPropertyDefined("jogamp.debug.JNILibLoader.Perf", true);
+  }
+
+  private static final Object perfSync = new Object();
+  private static long perfTotal = 0;
+  private static long perfCount = 0;
 
   public interface LoaderAction {
     /**
@@ -177,6 +188,7 @@ public class JNILibLoaderBase {
         msg.append(")");
         System.err.println(msg.toString());
     }
+    final long t0 = PERF ? System.currentTimeMillis() : 0; // 'Platform.currentTimeMillis()' not yet available!
 
     boolean ok = false;
 
@@ -271,8 +283,18 @@ public class JNILibLoaderBase {
         }
     }
 
-    if (DEBUG) {
-        System.err.printf("JNILibLoaderBase: addNativeJarLibsImpl: ok: %b%n", ok);
+    if (DEBUG || PERF) {
+        final long tNow = System.currentTimeMillis() - t0;
+        final long tTotal, tCount;
+        synchronized(perfSync) {
+            tCount = perfCount+1;
+            tTotal = perfTotal + tNow;
+            perfTotal = tTotal;
+            perfCount = tCount;
+        }
+        final double tAvrg = tTotal / (double)tCount;
+        System.err.printf("JNILibLoaderBase: addNativeJarLibsImpl.X: %s / %s -> ok: %b; duration: now %d ms, total %d ms (count %d, avrg %.3f ms)%n",
+                          jarBasename, nativeJarBasename, ok, tNow, tTotal, tCount, tAvrg);
     }
     return ok;
   }