src: record http status

PR-RUL: https://github.com/hyj1991/xprofiler/pull/44
Reviewed-BY: hyj1991 <yeekwanvong@gmail.com>

binding.gyp

@@ -17,6 +17,7 @@
         "src/logbypass/heap.cc",
         "src/logbypass/gc.cc",
         "src/logbypass/libuv.cc",
+        "src/logbypass/http.cc",
         "src/commands/listener.cc",
         "src/commands/send.cc",
         "src/commands/parser.cc",

lib/configure.js

@@ -11,7 +11,8 @@ const defaultConfig = {
   log_format_alinode: false,
   log_level: 1,
   log_type: 0,
-  enable_fatal_error_hook: true
+  enable_fatal_error_hook: true,
+  patch_http: false
 };
 
 function checkLogDirAccessiable(logdir) {

package.json

@@ -1,6 +1,6 @@
 {
   "name": "xprofiler",
-  "version": "1.0.0-prepare",
+  "version": "1.1.0-prepare",
   "description": "node.js addon to output runtime logs",
   "bin": {
     "xprofctl": "bin/xprofctl"
@@ -9,7 +9,7 @@
   "scripts": {
     "build": "npm run lint && node-gyp rebuild",
     "format": "clang-format -i --glob=\"src/**/!(report_win)[.h|.cc]\"",
-    "lint": "npm run format && eslint --fix xprofiler.js \"test/**/*.js\" lib/*.js bin/xprofctl scripts/**/*.js",
+    "lint": "npm run format && eslint --fix xprofiler.js \"test/**/*.js\" lib/*.js patch/*.js bin/xprofctl scripts/**/*.js",
     "test": "mocha -t 0 -R spec test/*.test.js",
     "test-single": "mocha -t 0 -R spec",
     "cov": "nyc --reporter=html --reporter=text --reporter=lcov mocha -R spec test/*.test.js  --timeout 0",
@@ -26,6 +26,7 @@
   "files": [
     "bin",
     "lib",
+    "patch",
     "src",
     "binding.gyp",
     "xprofiler.js",

patch/http.js

@@ -0,0 +1,47 @@
+'use strict';
+
+const shimmer = require('./shimmer');
+const http = require('http');
+const https = require('https');
+
+function requestListenerWrapper(original, addLiveRequest, addCloseRequest, addSentRequest) {
+  return function (req, res) {
+    addLiveRequest();
+    const start = Date.now();
+
+    res.on('finish', () => addSentRequest(Date.now() - start));
+
+    res.on('close', () => addCloseRequest());
+
+    // call origin function
+    const returned = original.apply(this, arguments);
+    return returned;
+  };
+}
+
+function serverWrapper(addLiveRequest, addCloseRequest, addSentRequest, original) {
+  return function (opts, requestListener) {
+    const args = Array.from(arguments);
+    let returned;
+
+    if (typeof opts === 'function') {
+      args.splice(0, 1, requestListenerWrapper(opts, addLiveRequest, addCloseRequest, addSentRequest));
+      returned = original.apply(this, args);
+    }
+    if (typeof requestListener === 'function') {
+      args.splice(1, 1, requestListenerWrapper(requestListener, addLiveRequest, addCloseRequest, addSentRequest));
+      returned = original.apply(this, args);
+    }
+
+    return returned;
+  };
+}
+
+function patchHttp(addLiveRequest, addCloseRequest, addSentRequest) {
+  // patch http server
+  shimmer.wrap(http, 'createServer', serverWrapper.bind(this, addLiveRequest, addCloseRequest, addSentRequest));
+  // patch https server
+  shimmer.wrap(https, 'createServer', serverWrapper.bind(this, addLiveRequest, addCloseRequest, addSentRequest));
+}
+
+module.exports = { patchHttp };

patch/index.js

@@ -0,0 +1,12 @@
+'use strict';
+
+const { patchHttp } = require('./http');
+
+function patch(config, methods) {
+  if (config.patch_http) {
+    const { addLiveRequest, addCloseRequest, addSentRequest } = methods;
+    patchHttp(addLiveRequest, addCloseRequest, addSentRequest);
+  }
+}
+
+module.exports = { patch };

patch/shimmer.js

@@ -0,0 +1,53 @@
+'use strict';
+
+function defineProperty(obj, name, value) {
+  const enumerable = !!obj[name] && obj.propertyIsEnumerable(name); // eslint-disable-line
+  Object.defineProperty(obj, name, {
+    configurable: true,
+    enumerable,
+    writable: true,
+    value: value
+  });
+}
+
+function isFunction(funktion) {
+  return typeof funktion === 'function';
+}
+
+function wrap(nodule, name, wrapper) {
+  if (
+    !nodule ||
+    !nodule[name] ||
+    !wrapper ||
+    !isFunction(nodule[name]) ||
+    !isFunction(wrapper)
+  ) {
+    return;
+  }
+
+  const original = nodule[name];
+  const wrapped = wrapper(original, name);
+
+  defineProperty(wrapped, '__original', original);
+  defineProperty(wrapped, '__wrapped', true);
+
+  defineProperty(nodule, name, wrapped);
+
+  defineProperty(wrapped, '__unwrap', function () {
+    if (nodule[name] === wrapped) { defineProperty(nodule, name, original); }
+  });
+  return wrapped;
+}
+
+function unwrap(nodule, name) {
+  if (
+    !nodule ||
+    !nodule[name] ||
+    !nodule[name].__unwrap) {
+    return;
+  }
+
+  return nodule[name].__unwrap();
+}
+
+module.exports = { wrap, unwrap };

src/commands/parser.cc

@@ -13,13 +13,12 @@ using nlohmann::json;
 using std::exception;
 using std::string;
 
-#define HANDLE_COMMANDS(cmd_str, handle)                              \
-  if (strcmp(cmd.c_str(), #cmd_str) == 0) {                           \
-    handle(                                                           \
-        parsed, FmtMessage,                                           \
-        [traceid](json data) { SuccessValue(traceid, data); },        \
-        [traceid](string message) { ErrorValue(traceid, message); }); \
-    handled = true;                                                   \
+#define HANDLE_COMMANDS(cmd_str, handle)                                 \
+  if (strcmp(cmd.c_str(), #cmd_str) == 0) {                              \
+    handle(parsed, FmtMessage,                                           \
+           [traceid](json data) { SuccessValue(traceid, data); },        \
+           [traceid](string message) { ErrorValue(traceid, message); }); \
+    handled = true;                                                      \
   }
 
 void ParseCmd(char *command) {

src/commands/simple/config.cc

@@ -29,6 +29,7 @@ COMMAND_CALLBACK(GetXprofilerConfig) {
   data["log_level"] = GetLogLevel();
   data["log_type"] = GetLogType();
   data["enable_fatal_error_hook"] = GetEnableFatalErrorHook();
+  data["patch_http"] = GetPatchHttp();
   success(data);
 }
 

src/configure.cc

@@ -23,6 +23,7 @@ static LOG_TYPE log_type = LOG_TO_FILE;
 static bool enable_log_uv_handles = true;
 static bool log_format_alinode = false;
 static bool enable_fatal_error_hook = true;
+static bool patch_http = false;
 
 void Configure(const FunctionCallbackInfo<Value> &info) {
   if (!info[0]->IsObject()) {
@@ -38,6 +39,7 @@ void Configure(const FunctionCallbackInfo<Value> &info) {
   CONVERT_BOOL(enable_log_uv_handles)
   CONVERT_BOOL(log_format_alinode)
   CONVERT_BOOL(enable_fatal_error_hook)
+  CONVERT_BOOL(patch_http)
 
   info.GetReturnValue().Set(New<Boolean>(true));
 }
@@ -52,6 +54,7 @@ void GetConfig(const FunctionCallbackInfo<Value> &info) {
   CONFIG_NATIVE_NUMBER(enable_log_uv_handles, Boolean)
   CONFIG_NATIVE_NUMBER(log_format_alinode, Boolean)
   CONFIG_NATIVE_NUMBER(enable_fatal_error_hook, Boolean)
+  CONFIG_NATIVE_NUMBER(patch_http, Boolean)
 
   info.GetReturnValue().Set(config);
 }
@@ -64,4 +67,5 @@ DEFINE_GET_SET_FUNCTION(LogType, LOG_TYPE, log_type)
 DEFINE_GET_SET_FUNCTION(FormatAsAlinode, bool, log_format_alinode)
 DEFINE_GET_SET_FUNCTION(EnableLogUvHandles, bool, enable_log_uv_handles)
 DEFINE_GET_SET_FUNCTION(EnableFatalErrorHook, bool, enable_fatal_error_hook)
+DEFINE_GET_SET_FUNCTION(PatchHttp, bool, patch_http)
 }  // namespace xprofiler

src/configure.h

@@ -62,6 +62,7 @@ DECLARE_GET_SET_FUNCTION(LogType, LOG_TYPE)
 DECLARE_GET_SET_FUNCTION(FormatAsAlinode, bool)
 DECLARE_GET_SET_FUNCTION(EnableLogUvHandles, bool)
 DECLARE_GET_SET_FUNCTION(EnableFatalErrorHook, bool)
+DECLARE_GET_SET_FUNCTION(PatchHttp, bool)
 
 // javascript accessible
 void Configure(const FunctionCallbackInfo<Value> &info);

src/logbypass/http.cc

@@ -0,0 +1,81 @@
+#include "uv.h"
+
+#include "../logger.h"
+#include "http.h"
+
+namespace xprofiler {
+using Nan::To;
+
+static uv_mutex_t http_mutex;
+
+static const char module_type[] = "http";
+
+// http server
+static unsigned int live_http_request = 0;
+static unsigned int http_response_close = 0;
+static unsigned int http_response_sent = 0;
+static unsigned int http_rt = 0;  // ms
+
+int InitHttpStatus() {
+  int rc = uv_mutex_init(&http_mutex);
+  return rc;
+}
+
+void AddLiveRequest(const FunctionCallbackInfo<Value> &info) {
+  uv_mutex_lock(&http_mutex);
+  live_http_request++;
+  uv_mutex_unlock(&http_mutex);
+}
+
+void AddCloseRequest(const FunctionCallbackInfo<Value> &info) {
+  uv_mutex_lock(&http_mutex);
+  http_response_close++;
+  uv_mutex_unlock(&http_mutex);
+}
+
+void AddSentRequest(const FunctionCallbackInfo<Value> &info) {
+  if (!info[0]->IsNumber()) {
+    Error(module_type, "request cost must be number!");
+    return;
+  }
+
+  unsigned int cost = To<uint32_t>(info[0]).ToChecked();
+
+  uv_mutex_lock(&http_mutex);
+  http_response_sent++;
+  http_rt += cost;
+  uv_mutex_unlock(&http_mutex);
+}
+
+void WriteHttpStatus(bool log_format_alinode) {
+  uv_mutex_lock(&http_mutex);
+
+  double rt = 0.00;
+  if (http_response_sent != 0) {
+    rt = http_rt * 1.00 / http_response_sent;
+  }
+
+  if (log_format_alinode)
+    Info("http",
+         "live_http_request: %d, "
+         "http_request_handled: %d, "
+         "http_response_sent: %d, "
+         "http_rt: %.2lf",
+         live_http_request, http_response_sent, http_response_sent, rt);
+  else
+    Info("http",
+         "live_http_request: %d, "
+         "http_response_close: %d, "
+         "http_response_sent: %d, "
+         "http_rt: %.2lf",
+         live_http_request, http_response_close, http_response_sent, rt);
+
+  // reset
+  live_http_request = 0;
+  http_response_sent = 0;
+  http_response_close = 0;
+  http_rt = 0;
+
+  uv_mutex_unlock(&http_mutex);
+}
+}  // namespace xprofiler

src/logbypass/http.h

@@ -0,0 +1,19 @@
+#ifndef _SRC_LOGBYPASS_HTTP_H
+#define _SRC_LOGBYPASS_HTTP_H
+
+#include "nan.h"
+
+namespace xprofiler {
+using Nan::FunctionCallbackInfo;
+using v8::Value;
+
+int InitHttpStatus();
+void WriteHttpStatus(bool log_format_alinode);
+
+// javascript-accessible
+void AddLiveRequest(const FunctionCallbackInfo<Value> &info);
+void AddCloseRequest(const FunctionCallbackInfo<Value> &info);
+void AddSentRequest(const FunctionCallbackInfo<Value> &info);
+}  // namespace xprofiler
+
+#endif

src/logbypass/log.cc

@@ -4,6 +4,7 @@
 #include "cpu.h"
 #include "gc.h"
 #include "heap.h"
+#include "http.h"
 #include "libuv.h"
 #include "uv.h"
 
@@ -48,6 +49,9 @@ static void CreateLogThread(void *unused) {
 
       // write libuv handle info
       WriteLibuvHandleInfoToLog(log_format_alinode);
+
+      // write http status
+      WriteHttpStatus(log_format_alinode);
     }
   }
 }
@@ -78,6 +82,10 @@ void RunLogBypass(const FunctionCallbackInfo<Value> &info) {
   CHECK(InitGcStatusHooks, "init gc hooks failed!")
   Info("init", "logbypass: gc hooks setted.");
 
+  // init http status
+  CHECK(InitHttpStatus, "init http status failed!")
+  Info("init", "logbypass: http status inited.");
+
   // init log thread
   rc = uv_thread_create(&uv_log_thread, CreateLogThread, nullptr);
   if (rc != 0) {

src/xprofiler.cc

@@ -2,6 +2,7 @@
 #include "configure.h"
 #include "hooks/set_hooks.h"
 #include "library/common.h"
+#include "logbypass/http.h"
 #include "logbypass/log.h"
 #include "logger.h"
 #include "nan.h"
@@ -42,6 +43,11 @@ NAN_MODULE_INIT(Initialize) {
 
   // set hooks
   CREATE_JS_BINDING(setHooks, SetHooks)
+
+  // http status
+  CREATE_JS_BINDING(addLiveRequest, AddLiveRequest)
+  CREATE_JS_BINDING(addCloseRequest, AddCloseRequest)
+  CREATE_JS_BINDING(addSentRequest, AddSentRequest)
 }
 
 NODE_MODULE(xprofiler, Initialize)