Add event loop thread cpu usage (#476)

* Add the percentage CPU time used by the event loop in the last
LOOP_INTERVAL so we can see if a Node.js process is CPU bound.

* Add thread cpu times for Mac.
Update README.md

README.md

@@ -247,12 +247,14 @@ Emitted when a garbage collection (GC) cycle occurs in the underlying V8 runtime
 Emitted when all possible environment variables have been collected. Use `appmetrics.monitor.getEnvironment()` to access the available environment variables.
 
 ### Event: 'loop'
-Emitted every 60 seconds, summarising event tick information in time interval
+Emitted every 5 seconds, summarising event tick information in time interval
 * `data` (Object) the data from the event loop sample:
     * `count` (Number) the number of event loop ticks in the last interval.
     * `minimum` (Number) the shortest (i.e. fastest) tick in milliseconds.
     * `maximum` (Number) the longest (slowest) tick in milliseconds.
     * `average` (Number) the average tick time in milliseconds.
+    * `cpu_user` (Number) the percentage of 1 CPU used by the event loop thread in user code the last interval. This is a value between 0.0 and 1.0.
+    * `cpu_system` (Number) the percentage of 1 CPU used by the event loop thread in system code in the last interval. This is a value between 0.0 and 1.0.
 
 ### Event: 'memory'
 Emitted when a memory monitoring sample is taken.

appmetrics-api.js

@@ -218,6 +218,8 @@ function API(agent, appmetrics) {
         maximum: parseFloat(values[2]),
         count: parseInt(values[3]),
         average: parseFloat(values[4]),
+        cpu_user: parseFloat(values[5]),
+        cpu_system: parseFloat(values[6]),
       };
       that.emit('loop', loop);
     });

src/plugins/node/loop/nodeloopplugin.cpp

@@ -25,6 +25,7 @@
 #include <ctime>
 #else
 #include <sys/time.h>
+#include <sys/resource.h>
 #endif
 
 #define DEFAULT_CAPACITY 10240
@@ -58,23 +59,66 @@ uint64_t max = 0;
 uint64_t num = 0;
 uint64_t sum = 0;
 
+uint64_t last_cpu_user = 0;
+uint64_t last_cpu_sys = 0;
+uint64_t last_cpu_ts = 0;
+
+void getThreadCPUTime(uint64_t* cpu_user, uint64_t* cpu_sys) {
+	// Get the CPU time for this thread
+#ifdef RUSAGE_THREAD
+	struct rusage stats;
+	if (getrusage(RUSAGE_THREAD, &stats) == 0) {
+#if defined(__APPLE__) || defined(_AIX)
+		*cpu_user = (uint64_t)(stats.ru_utime.tv_sec * 1000) + (uint64_t)(stats.ru_utime.tv_usec / 1000);
+		*cpu_sys = (uint64_t)(stats.ru_stime.tv_sec * 1000) + (uint64_t)(stats.ru_stime.tv_usec / 1000);
+#else
+		*cpu_user = (uint64_t)(stats.ru_utime.tv_sec * 1000) + (uint64_t)(stats.ru_utime.tv_usec / 1000);
+		*cpu_sys = (uint64_t)(stats.ru_stime.tv_sec * 1000) + (uint64_t)(stats.ru_stime.tv_usec / 1000);
+#endif
+	}
+#elif defined(__APPLE__)
+	mach_msg_type_number_t count = THREAD_BASIC_INFO_COUNT;
+	mach_port_t thread = pthread_mach_thread_np(pthread_self());
+	thread_basic_info thr_info;
+
+	kern_return_t rc = thread_info(thread, THREAD_BASIC_INFO,
+			(thread_info_t) &thr_info, &count);
+
+	if (rc == KERN_SUCCESS) {
+		*cpu_user = (thr_info.user_time.seconds * 1000) + (thr_info.user_time.microseconds / 1000);
+		*cpu_sys = (thr_info.system_time.seconds * 1000) + (thr_info.system_time.microseconds / 1000);
+	}
+#else
+	*cpu_user = 0;
+	*cpu_sys = 0;
+#endif
+}
 
 #if NODE_VERSION_AT_LEAST(0, 11, 0) // > v0.11+
 static void GetLoopInformation(uv_timer_s *data) {
 #else
 static void GetLoopInformation(uv_timer_s *data, int status) {
 #endif
 	if (num != 0) {
-          // Convert from nanoseconds to milliseconds.
+
+	  uint64_t cpu_user = 0;
+	  uint64_t cpu_sys = 0;
+	  uint64_t cpu_ts = uv_hrtime() / (1000*1000);
+	  getThreadCPUTime(&cpu_user, &cpu_sys);
+
+	  // Convert from nanoseconds to milliseconds.
 
 	  double mean = (sum / 1e6) / num;
+	  double cpu_duration = (double)(cpu_ts - last_cpu_ts);
 
 	  std::stringstream contentss;
 	  contentss << "NodeLoopData";
 	  contentss << "," << (min / 1e6);
 	  contentss << "," << (max / 1e6);
 	  contentss << "," << num;
 	  contentss << "," << mean;
+	  contentss << "," << (double)(((double)(cpu_user - last_cpu_user)) / cpu_duration);
+	  contentss << "," << (double)(((double)(cpu_sys - last_cpu_sys)) / cpu_duration);
 	  contentss << '\n';
 
 	  std::string content = contentss.str();
@@ -83,6 +127,9 @@ static void GetLoopInformation(uv_timer_s *data, int status) {
 	  max = 0;
 	  num = 0;
 	  sum = 0;
+	  last_cpu_user = cpu_user;
+	  last_cpu_sys = cpu_sys;
+	  last_cpu_ts = cpu_ts;
 
 
 	  // Send data
@@ -160,6 +207,9 @@ extern "C" {
 	NODELOOPPLUGIN_DECL int ibmras_monitoring_plugin_start() {
 		plugin::api.logMessage(fine, "[loop_node] Starting");
 
+		last_cpu_ts = uv_hrtime() / (1000*1000);
+		getThreadCPUTime(&last_cpu_user, &last_cpu_sys);
+
 		uv_prepare_start(&prepare_handle, OnPrepare);
 		uv_check_start(&check_handle, OnCheck);
 		uv_timer_start(plugin::timer, GetLoopInformation, LOOP_INTERVAL, LOOP_INTERVAL);