From: <mor...@us...> - 2004-10-18 09:37:37
|
Update of /cvsroot/wrapper/wrapper/src/c In directory sc8-pr-cvs1.sourceforge.net:/tmp/cvs-serv20273/c Modified Files: wrapper.c wrapper.h wrapper_unix.c wrapper_win.c wrappereventloop.c Log Message: Add the wrapper.cpu_output and wrapper.cpu_output.interval properties to make it possible to track CPU usage of the Wrapper and JVM over time. Index: wrapper.c =================================================================== RCS file: /cvsroot/wrapper/wrapper/src/c/wrapper.c,v retrieving revision 1.119 retrieving revision 1.120 diff -C2 -d -r1.119 -r1.120 *** wrapper.c 18 Oct 2004 05:43:45 -0000 1.119 --- wrapper.c 18 Oct 2004 09:37:22 -0000 1.120 *************** *** 43,46 **** --- 43,50 ---- * * $Log$ + * Revision 1.120 2004/10/18 09:37:22 mortenson + * Add the wrapper.cpu_output and wrapper.cpu_output.interval properties to + * make it possible to track CPU usage of the Wrapper and JVM over time. + * * Revision 1.119 2004/10/18 05:43:45 mortenson * Add the wrapper.memory_output and wrapper.memory_output.interval properties to *************** *** 2220,2226 **** wrapperData->isSleepOutputEnabled = getBooleanProperty(properties, "wrapper.sleep_output", FALSE); ! /* Get the memory debug output status. */ wrapperData->isMemoryOutputEnabled = getBooleanProperty(properties, "wrapper.memory_output", FALSE); wrapperData->memoryOutputInterval = getIntProperty(properties, "wrapper.memory_output.interval", 1); /* Get the shutdown hook status */ --- 2224,2234 ---- wrapperData->isSleepOutputEnabled = getBooleanProperty(properties, "wrapper.sleep_output", FALSE); ! /* Get the memory output status. */ wrapperData->isMemoryOutputEnabled = getBooleanProperty(properties, "wrapper.memory_output", FALSE); wrapperData->memoryOutputInterval = getIntProperty(properties, "wrapper.memory_output.interval", 1); + + /* Get the cpu output status. */ + wrapperData->isCPUOutputEnabled = getBooleanProperty(properties, "wrapper.cpu_output", FALSE); + wrapperData->cpuOutputInterval = getIntProperty(properties, "wrapper.cpu_output.interval", 1); /* Get the shutdown hook status */ Index: wrapper.h =================================================================== RCS file: /cvsroot/wrapper/wrapper/src/c/wrapper.h,v retrieving revision 1.57 retrieving revision 1.58 diff -C2 -d -r1.57 -r1.58 *** wrapper.h 18 Oct 2004 05:43:45 -0000 1.57 --- wrapper.h 18 Oct 2004 09:37:22 -0000 1.58 *************** *** 43,46 **** --- 43,50 ---- * * $Log$ + * Revision 1.58 2004/10/18 09:37:22 mortenson + * Add the wrapper.cpu_output and wrapper.cpu_output.interval properties to + * make it possible to track CPU usage of the Wrapper and JVM over time. + * * Revision 1.57 2004/10/18 05:43:45 mortenson * Add the wrapper.memory_output and wrapper.memory_output.interval properties to *************** *** 304,310 **** int isLoopOutputEnabled; /* TRUE if very detailed output from the main loop should be output. */ int isSleepOutputEnabled; /* TRUE if detailed sleep output should be included in debug output. */ ! int isMemoryOutputEnabled; /* TRUE if detailed memory output should be included in debug output. */ int memoryOutputInterval; /* Interval in seconds at which memory usage is logged. */ DWORD memoryOutputTimeoutTicks; /* Tick count at which memory will next be logged. */ int isShutdownHookDisabled; /* TRUE if set in the configuration file */ int startupDelayConsole; /* Delay in seconds before starting the first JVM in console mode. */ --- 308,317 ---- int isLoopOutputEnabled; /* TRUE if very detailed output from the main loop should be output. */ int isSleepOutputEnabled; /* TRUE if detailed sleep output should be included in debug output. */ ! int isMemoryOutputEnabled; /* TRUE if detailed memory output should be included in status output. */ int memoryOutputInterval; /* Interval in seconds at which memory usage is logged. */ DWORD memoryOutputTimeoutTicks; /* Tick count at which memory will next be logged. */ + int isCPUOutputEnabled; /* TRUE if detailed CPU output should be included in status output. */ + int cpuOutputInterval; /* Interval in seconds at which CPU usage is logged. */ + DWORD cpuOutputTimeoutTicks; /* Tick count at which CPU will next be logged. */ int isShutdownHookDisabled; /* TRUE if set in the configuration file */ int startupDelayConsole; /* Delay in seconds before starting the first JVM in console mode. */ *************** *** 496,499 **** --- 503,512 ---- extern void wrapperDumpMemory(); + /** + * Outputs a log entry at regular intervals to track the CPU usage over each + * interval for the Wrapper and its JVM. + */ + extern void wrapperDumpCPUUsage(); + /****************************************************************************** * Wrapper inner methods. Index: wrapper_unix.c =================================================================== RCS file: /cvsroot/wrapper/wrapper/src/c/wrapper_unix.c,v retrieving revision 1.91 retrieving revision 1.92 diff -C2 -d -r1.91 -r1.92 *** wrapper_unix.c 18 Oct 2004 05:43:45 -0000 1.91 --- wrapper_unix.c 18 Oct 2004 09:37:22 -0000 1.92 *************** *** 43,46 **** --- 43,50 ---- * * $Log$ + * Revision 1.92 2004/10/18 09:37:22 mortenson + * Add the wrapper.cpu_output and wrapper.cpu_output.interval properties to + * make it possible to track CPU usage of the Wrapper and JVM over time. + * * Revision 1.91 2004/10/18 05:43:45 mortenson * Add the wrapper.memory_output and wrapper.memory_output.interval properties to *************** *** 1058,1061 **** --- 1062,1073 ---- /** + * Outputs a log entry at regular intervals to track the CPU usage over each + * interval for the Wrapper and its JVM. + */ + void wrapperDumpCPUUsage() { + /* Not yet implemented on UNIX platforms. */ + } + + /** * Checks on the status of the JVM Process. * Returns WRAPPER_PROCESS_UP or WRAPPER_PROCESS_DOWN Index: wrapper_win.c =================================================================== RCS file: /cvsroot/wrapper/wrapper/src/c/wrapper_win.c,v retrieving revision 1.91 retrieving revision 1.92 diff -C2 -d -r1.91 -r1.92 *** wrapper_win.c 18 Oct 2004 05:43:45 -0000 1.91 --- wrapper_win.c 18 Oct 2004 09:37:23 -0000 1.92 *************** *** 43,46 **** --- 43,50 ---- * * $Log$ + * Revision 1.92 2004/10/18 09:37:23 mortenson + * Add the wrapper.cpu_output and wrapper.cpu_output.interval properties to + * make it possible to track CPU usage of the Wrapper and JVM over time. + * * Revision 1.91 2004/10/18 05:43:45 mortenson * Add the wrapper.memory_output and wrapper.memory_output.interval properties to *************** *** 384,387 **** --- 388,392 ---- /* Dynamically loaded functions. */ + FARPROC OptionalGetProcessTimes = NULL; FARPROC OptionalGetProcessMemoryInfo = NULL; *************** *** 390,395 **** --- 395,412 ---- ******************************************************************************/ void loadDLLProcs() { + HMODULE kernel32Mod; HMODULE psapiMod; + /* The PSAPI module was added in NT 3.5. */ + if ((kernel32Mod = GetModuleHandle("KERNEL32.DLL")) == NULL) { + log_printf(WRAPPER_SOURCE_WRAPPER, LEVEL_DEBUG, + "The KERNEL32.DLL was not found. Some functions will be disabled."); + } else { + if ((OptionalGetProcessTimes = GetProcAddress(kernel32Mod, "GetProcessTimes")) == NULL) { + log_printf(WRAPPER_SOURCE_WRAPPER, LEVEL_DEBUG, + "The GetProcessTimes is not available in this KERNEL32.DLL version. Some functions will be disabled."); + } + } + /* The PSAPI module was added in NT 4.0. */ if ((psapiMod = LoadLibrary("PSAPI.DLL")) == NULL) { *************** *** 544,547 **** --- 561,581 ---- } + int writePidFile(const char *filename, DWORD pid) { + FILE *pid_fp = NULL; + int old_umask; + + old_umask = _umask(022); + pid_fp = fopen(filename, "w"); + _umask(old_umask); + + if (pid_fp != NULL) { + fprintf(pid_fp, "%d\n", pid); + fclose(pid_fp); + } else { + return 1; + } + return 0; + } + /** * Initialize the pipe which will be used to capture the output from the child *************** *** 1472,1476 **** FILE *pid_fp = NULL; - int old_umask; /* Reset the exit code when we launch a new JVM. */ --- 1506,1509 ---- *************** *** 1726,1729 **** --- 1759,1890 ---- } + DWORD filetimeToMS(FILETIME* filetime) { + LARGE_INTEGER li; + + memcpy(&li, filetime, sizeof(li)); + li.QuadPart /= 10000; + + return li.LowPart; + } + + /** + * Outputs a log entry at regular intervals to track the CPU usage over each + * interval for the Wrapper and its JVM. + * + * In order to make sense of the timing values, it is also necessary to see how + * far the system performance counter has progressed. By carefully comparing + * these values, it is possible to very accurately calculate the CPU usage over + * any period of time. + */ + LONGLONG lastPerformanceCount = 0; + LONGLONG lastWrapperKernelTime = 0; + LONGLONG lastWrapperUserTime = 0; + LONGLONG lastJavaKernelTime = 0; + LONGLONG lastJavaUserTime = 0; + LONGLONG lastIdleKernelTime = 0; + LONGLONG lastIdleUserTime = 0; + void wrapperDumpCPUUsage() { + LARGE_INTEGER count; + LARGE_INTEGER frequency; + LARGE_INTEGER li; + LONGLONG performanceCount; + + FILETIME creationTime; + FILETIME exitTime; + FILETIME wKernelTime; + FILETIME wUserTime; + FILETIME jKernelTime; + FILETIME jUserTime; + + DWORD wKernelTimeMs; /* Will overflow in 49 days of usage. */ + DWORD wUserTimeMs; + DWORD wTimeMs; + DWORD jKernelTimeMs; + DWORD jUserTimeMs; + DWORD jTimeMs; + + double age; + double wKernelPercent; + double wUserPercent; + double wPercent; + double jKernelPercent; + double jUserPercent; + double jPercent; + + if (OptionalGetProcessTimes) { + if (!QueryPerformanceCounter(&count)) { + /* no high-resolution performance counter support. */ + return; + } + if (!QueryPerformanceFrequency(&frequency)) { + } + + performanceCount = count.QuadPart; + + /* Start with the Wrapper process. */ + if (!OptionalGetProcessTimes(wrapperProcess, &creationTime, &exitTime, &wKernelTime, &wUserTime)) { + log_printf(WRAPPER_SOURCE_WRAPPER, LEVEL_ERROR, + "Call to GetProcessTimes failed for Wrapper process %08x: %s", + wrapperProcessId, getLastErrorText()); + return; + } + + if (javaProcess != NULL) { + /* Next the Java process. */ + if (!OptionalGetProcessTimes(javaProcess, &creationTime, &exitTime, &jKernelTime, &jUserTime)) { + log_printf(WRAPPER_SOURCE_WRAPPER, LEVEL_ERROR, + "Call to GetProcessTimes failed for Java process %08x: %s", + javaProcessId, getLastErrorText()); + return; + } + } else { + memset(&jKernelTime, 0, sizeof(jKernelTime)); + memset(&jUserTime, 0, sizeof(jUserTime)); + lastJavaKernelTime = 0; + lastJavaUserTime = 0; + } + + + // Convert the times to ms. + wKernelTimeMs = filetimeToMS(&wKernelTime); + wUserTimeMs = filetimeToMS(&wUserTime); + wTimeMs = wKernelTimeMs + wUserTimeMs; + jKernelTimeMs = filetimeToMS(&jKernelTime); + jUserTimeMs = filetimeToMS(&jUserTime); + jTimeMs = jKernelTimeMs + jUserTimeMs; + + /* Calculate the number of seconds since the last call. */ + age = (double)(performanceCount - lastPerformanceCount) / frequency.QuadPart; + + /* Calculate usage percentages. */ + memcpy(&li, &wKernelTime, sizeof(li)); + wKernelPercent = 100.0 * ((li.QuadPart - lastWrapperKernelTime) / 10000000.0) / age; + lastWrapperKernelTime = li.QuadPart; + + memcpy(&li, &wUserTime, sizeof(li)); + wUserPercent = 100.0 * ((li.QuadPart - lastWrapperUserTime) / 10000000.0) / age; + lastWrapperUserTime = li.QuadPart; + + wPercent = wKernelPercent + wUserPercent; + + memcpy(&li, &jKernelTime, sizeof(li)); + jKernelPercent = 100.0 * ((li.QuadPart - lastJavaKernelTime) / 10000000.0) / age; + lastJavaKernelTime = li.QuadPart; + + memcpy(&li, &jUserTime, sizeof(li)); + jUserPercent = 100.0 * ((li.QuadPart - lastJavaUserTime) / 10000000.0) / age; + lastJavaUserTime = li.QuadPart; + + jPercent = jKernelPercent + jUserPercent; + + log_printf(WRAPPER_SOURCE_WRAPPER, LEVEL_STATUS, + "Wrapper CPU: kernel %ldms (%5.2f%%), user %ldms (%5.2f%%), total %ldms (%5.2f%%) Java CPU: kernel %ldms (%5.2f%%), user %ldms (%5.2f%%), total %ldms (%5.2f%%)", + wKernelTimeMs, wKernelPercent, wUserTimeMs, wUserPercent, wTimeMs, wPercent, + jKernelTimeMs, jKernelPercent, jUserTimeMs, jUserPercent, jTimeMs, jPercent); + + lastPerformanceCount = performanceCount; + } + } + /****************************************************************************** * NT Service Methods *************** *** 2545,2565 **** } - int writePidFile(const char *filename, DWORD pid) { - FILE *pid_fp = NULL; - int old_umask; - - old_umask = _umask(022); - pid_fp = fopen(filename, "w"); - _umask(old_umask); - - if (pid_fp != NULL) { - fprintf(pid_fp, "%d\n", pid); - fclose(pid_fp); - } else { - return 1; - } - return 0; - } - /****************************************************************************** * Main function --- 2706,2709 ---- Index: wrappereventloop.c =================================================================== RCS file: /cvsroot/wrapper/wrapper/src/c/wrappereventloop.c,v retrieving revision 1.13 retrieving revision 1.14 diff -C2 -d -r1.13 -r1.14 *** wrappereventloop.c 18 Oct 2004 05:43:45 -0000 1.13 --- wrappereventloop.c 18 Oct 2004 09:37:23 -0000 1.14 *************** *** 43,46 **** --- 43,50 ---- * * $Log$ + * Revision 1.14 2004/10/18 09:37:23 mortenson + * Add the wrapper.cpu_output and wrapper.cpu_output.interval properties to + * make it possible to track CPU usage of the Wrapper and JVM over time. + * * Revision 1.13 2004/10/18 05:43:45 mortenson * Add the wrapper.memory_output and wrapper.memory_output.interval properties to *************** *** 905,908 **** --- 909,913 ---- wrapperData->anchorTimeoutTicks = lastCycleTicks; wrapperData->memoryOutputTimeoutTicks = lastCycleTicks; + wrapperData->cpuOutputTimeoutTicks = lastCycleTicks; if (wrapperData->isTimerOutputEnabled) { *************** *** 978,981 **** --- 983,994 ---- } } + + /* Log CPU usage. */ + if (wrapperData->isCPUOutputEnabled) { + if (wrapperTickExpired(nowTicks, wrapperData->cpuOutputTimeoutTicks)) { + wrapperDumpCPUUsage(); + wrapperData->cpuOutputTimeoutTicks = wrapperAddToTicks(nowTicks, wrapperData->cpuOutputInterval); + } + } /* Has the process been getting CPU? This check will only detect a lag |