Merge pull request #1254 from microsoft/littleaj/perfcounterlogging

Improve logging/exception handling loading JNI perf counter lib

Author: trask

CHANGELOG.md

@@ -1,5 +1,8 @@
 # CHANGELOG
 
+# Version 2.6.2
+* Added additional error logging for troubleshooting issues loading JNI performance counter library. 
+
 # Version 2.6.1
 * Fix shutdown issue due to non-daemon thread
   ([#1245](https://github.com/microsoft/ApplicationInsights-Java/pull/1245))
@@ -359,4 +362,3 @@ Livemetrics UX.
 - Support collecting performance counters from 32-bit Windows machines.
 - Support manual tracking of dependencies using a new ```trackDependency``` method API.
 - Ability to tag a telemetry item as synthetic, by adding a ```SyntheticSource``` property to the reported item.
-

core/native.gradle

@@ -20,6 +20,7 @@
  */
 
 apply plugin: 'cpp'
+apply plugin: 'idea'
 
 buildscript {
     repositories {
@@ -46,6 +47,12 @@ if (System.env.APPINSIGHTS_VS_PATH) {
     println "Using custom Visual Studio Tools path: $vsToolsDir"
 }
 
+idea {
+    module {
+        sourceDirs += file("$projectDir/src/windows/cpp")
+    }
+}
+
 // region Native binary definition and configuration
 model {
     toolChains {

core/src/main/java/com/microsoft/applicationinsights/internal/perfcounter/JniPCConnector.java

@@ -29,6 +29,7 @@
 import org.apache.commons.io.FileUtils;
 import org.apache.commons.io.IOUtils;
 import org.apache.commons.lang3.StringUtils;
+import org.apache.commons.lang3.exception.ExceptionUtils;
 
 import java.io.File;
 import java.io.IOException;
@@ -75,11 +76,15 @@ public static boolean initialize() {
             loadNativeLibrary();
         } catch (ThreadDeath td) {
             throw td;
+        } catch (JNIPerformanceCounterConnectorException e) {
+            if (InternalLogger.INSTANCE.isErrorEnabled()) {
+                InternalLogger.INSTANCE.error("Error initializing JNI Performance Counter library. Windows performance counters will not be used.: "+ ExceptionUtils.getStackTrace(e));
+            }
         } catch (Throwable e) {
             try {
-                InternalLogger.INSTANCE.error(
-                    "Failed to load native dll, Windows performance counters will not be used. " +
-                "Please make sure that Visual C++ Redistributable is properly installed: %s.", e.toString());
+                if (InternalLogger.INSTANCE.isErrorEnabled()) {
+                    InternalLogger.INSTANCE.error("Unexpected error initializing JNI Performance Counter library. Windows performance counters will not be used: "+ExceptionUtils.getStackTrace(e));
+                }
 
                 return false;
             } catch (ThreadDeath td) {
@@ -150,14 +155,26 @@ public static double getValueOfPerformanceCounter(String name) {
         return getPerformanceCounterValue(name);
     }
 
+    /**
+     * Performance Counters identify a process by "Instance Name."
+     * This will be the executable name without the extension, e.g. a process running java.exe will have an instance name "java".
+     * If there are multiple instances of the same executable, an additional identifier is appended. By default this looks like "java#1", "java#2".
+     * For some reason, the instance name can change after the process starts with the default naming scheme.
+     *
+     * To workaround this, add a DWORD registry value named 'ProcessNameFormat' set to the value '2' to the key
+     * 'HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\PerfProc\Performance'.
+     * This changes the naming scheme from "java#2" to "java_PID" where PID is the current process id. It also makes the name constant for the life of the process.
+     *
+     * @throws NumberFormatException if pid cannot be parsed.
+     */
     private static void initNativeCode() {
         int processId = Integer.parseInt(SystemInformation.INSTANCE.getProcessId());
 
         currentInstanceName = getInstanceName(processId);
         if (StringUtils.isEmpty(currentInstanceName)) {
             InternalLogger.INSTANCE.error("Failed to fetch current process instance name, process counters for for the process level will not be activated.");
         } else {
-            InternalLogger.INSTANCE.trace("Java process name is set to '%s'", currentInstanceName);
+            InternalLogger.INSTANCE.info("Java process instance name is set to '%s'", currentInstanceName);
         }
     }
 
@@ -173,21 +190,39 @@ private static void initNativeCode() {
      * @throws IOException If there are errors in opening/writing/reading/closing etc.
      *         Note that the method might throw RuntimeExceptions due to critical issues
      */
-    private static void loadNativeLibrary() throws IOException {
-        String model = System.getProperty("sun.arch.data.model");
-        String libraryToLoad = BITS_MODEL_64.equals(model) ? NATIVE_LIBRARY_64 : NATIVE_LIBRARY_32;
+    private static void loadNativeLibrary() throws JNIPerformanceCounterConnectorException {
+        final File dllOnDisk;
+        final String libraryToLoad;
+        try {
+            String model = System.getProperty("sun.arch.data.model");
+            libraryToLoad = BITS_MODEL_64.equals(model) ? NATIVE_LIBRARY_64 : NATIVE_LIBRARY_32;
 
-        File dllPath = buildDllLocalPath();
+            File dllPath = buildDllLocalPath();
 
-        File dllOnDisk = new File(dllPath, libraryToLoad);
+            dllOnDisk = new File(dllPath, libraryToLoad);
 
-        if (!dllOnDisk.exists()) {
-            extractToLocalFolder(dllOnDisk, libraryToLoad);
+            if (!dllOnDisk.exists()) {
+                extractToLocalFolder(dllOnDisk, libraryToLoad);
+            } else if (InternalLogger.INSTANCE.isTraceEnabled()) {
+                InternalLogger.INSTANCE.trace("Found existing DLL: " + dllOnDisk.getAbsolutePath());
+            }
+        } catch (Exception e) {
+            throw new JNIPerformanceCounterConnectorException("Error extracting DLL to disk", e);
         }
 
-        System.load(dllOnDisk.toString());
+        try {
+            System.load(dllOnDisk.toString());
+        } catch (Exception e) {
+            throw new JNIPerformanceCounterConnectorException("Error loading DLL. Please make sure that Visual C++ 2015 Redistributable is properly installed", e);
+        }
 
-        initNativeCode();
+        try {
+            initNativeCode();
+        } catch (NumberFormatException e) {
+            throw new JNIPerformanceCounterConnectorException("Could not parse PID as int", e);
+        } catch (Exception e) {
+            throw new JNIPerformanceCounterConnectorException("Unexpected error initializing performance counter DLL library", e);
+        }
 
         InternalLogger.INSTANCE.trace("Successfully loaded library '%s'", libraryToLoad);
     }
@@ -243,4 +278,14 @@ private static File buildDllLocalPath() {
 
         return dllPath;
     }
-}
+
+    private static class JNIPerformanceCounterConnectorException extends Exception {
+        public JNIPerformanceCounterConnectorException(String s) {
+            super(s);
+        }
+
+        public JNIPerformanceCounterConnectorException(String s, Throwable throwable) {
+            super(s, throwable);
+        }
+    }
+}

core/src/main/java/com/microsoft/applicationinsights/internal/system/SystemInformation.java

@@ -50,6 +50,9 @@ public boolean isUnix() {
         return SystemUtils.IS_OS_UNIX;
     }
 
+    /**
+     * JVMs are not required to publish this value/bean and some processes may not have permission to access it.
+     */
     private String initializeProcessId() {
         String rawName = ManagementFactory.getRuntimeMXBean().getName();
         if (!Strings.isNullOrEmpty(rawName)) {
@@ -58,13 +61,14 @@ private String initializeProcessId() {
                 String processIdAsString = rawName.substring(0, i);
                 try {
                     Integer.parseInt(processIdAsString);
+                    InternalLogger.INSTANCE.info("Current PID: "+processIdAsString);
                     return processIdAsString;
                 } catch (Exception e) {
-                    InternalLogger.INSTANCE.error("Failed to fetch process id: '%s'", e.toString());
+                    InternalLogger.INSTANCE.error("Failed to parse PID as number: '%s'", e.toString());
                 }
             }
         }
-
+        InternalLogger.INSTANCE.error("Could not extract PID from runtime name: '"+rawName+"'");
         // Default
         return DEFAULT_PROCESS_NAME;
     }

gradle.properties

@@ -1,4 +1,4 @@
 // Project properties
-version=2.6.1
+version=2.6.2
 group=com.microsoft.azure