X-Profiler · hyj1991 · Dec 22, 2019 · Dec 13, 2019 · Dec 15, 2019 · Dec 15, 2019
diff --git a/bin/xprofctl b/bin/xprofctl
@@ -36,15 +36,20 @@ const args = yargs
   .command('get_config', '获取 xprofiler 配置', normalYargs)
   .command('set_config', '设置 xprofiler 配置',
     yargs => yargs
-      .group(['enable_log_uv_handles', 'disable_log_uv_handles', 'log_level', 'log_type'], '配置项:')
+      .group(['enable_log_uv_handles', 'disable_log_uv_handles', 'log_level',
+        'log_type', 'enable_fatal_error_hook', 'disable_fatal_error_hook'], '配置项:')
       .describe('enable_log_uv_handles', '开启 libuv 句柄详情采集')
       .describe('disable_log_uv_handles', '关闭 libuv 句柄详情采集')
       .describe('log_level', '日志级别: info, error, debug')
       .describe('log_type', '日志输出未知: 文件, 控制台')
+      .describe('enable_fatal_error_hook', '开启 Fatal Error 钩子')
+      .describe('disable_fatal_error_hook', '关闭 Fatal Error 钩子')
       .boolean('enable_log_uv_handles')
       .boolean('disable_log_uv_handles')
       .choices('log_level', [0, 1, 2])
       .choices('log_type', [0, 1])
+      .boolean('enable_fatal_error_hook')
+      .boolean('disable_fatal_error_hook')
       .hide('v')
       .hide('h'))
   // pid

diff --git a/bin/xprofctl.json b/bin/xprofctl.json
@@ -19,7 +19,9 @@
       "disable_log_uv_handles": "boolean",
       "enable_log_uv_handles": "boolean",
       "log_level": "number",
-      "log_type": "number"
+      "log_type": "number",
+      "enable_fatal_error_hook": "boolean",
+      "disable_fatal_error_hook": "boolean"
     }
   }
 ]
diff --git a/binding.gyp b/binding.gyp
@@ -36,6 +36,8 @@
         "src/commands/report/heap_statistics.cc",
         "src/commands/report/uv_statistics.cc",
         "src/commands/report/system_statistics.cc",
+        "src/hooks/set_hooks.cc",
+        "src/hooks/fatal_error.cc",
       ],
       "include_dirs": [ '<!(node -e "require(\'nan\')")' ],
       'cflags_cc!': [ '-fno-exceptions' ],

diff --git a/lib/configure.js b/lib/configure.js
@@ -10,7 +10,8 @@ const defaultConfig = {
   enable_log_uv_handles: true,
   log_format_alinode: fal
EDBE
se,
   log_level: 1,
-  log_type: 0
+  log_type: 0,
+  enable_fatal_error_hook: true
 };
 
 function checkLogDirAccessiable(logdir) {

diff --git a/lib/utils.js b/lib/utils.js
@@ -43,7 +43,7 @@ function setLogDirToFile(logdir) {
       .readFileSync(dataFile, 'utf8')
       .split('\n')
       .filter(p => p && processAlive(p.split(SPLITTER)[0]))
-      .join('\n');
+      .join('\n') + '\n';
     fs.writeFileSync(dataFile, processes);
   }, parseInt(checkTime * 1000));
   timer.unref();

diff --git a/package.json b/package.json
@@ -1,7 +1,7 @@
 {
   "name": "xprofiler",
   "version": "1.0.0-prepare",
-  "description": "",
+  "description": "node.js addon to output runtime logs",
   "bin": {
     "xprofctl": "bin/xprofctl"
   },
@@ -10,10 +10,10 @@
     "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",
-    "test": "mocha -t 15000 -R spec test/*.test.js",
-    "test-single": "mocha -t 15000 -R spec",
-    "cov": "nyc --reporter=html --reporter=text --reporter=lcov mocha -R spec test/*.test.js  --timeout 15000",
-    "cov-single": "nyc --reporter=html --reporter=text --reporter=lcov mocha --timeout 15000 -R spec",
+    "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",
+    "cov-single": "nyc --reporter=html --reporter=text --reporter=lcov mocha --timeout 0 -R spec",
     "upload": "node scripts/upload.js",
     "ci": "npm run lint && npm run cov && codecov && npm run upload",
     "dep": "npm run build && npm run cov"

diff --git a/src/commands/report/node_report.cc b/src/commands/report/node_report.cc
@@ -20,10 +20,13 @@ using std::ofstream;
 NodeReport::NodeReport() {}
 NodeReport::~NodeReport() {}
 
-static void WriteNodeReport(JSONWriter *writer) {
+static void WriteNodeReport(JSONWriter *writer, string location,
+                            string message) {
   writer->json_start();
 
   writer->json_keyvalue("pid", GetPid());
+  writer->json_keyvalue("location", location);
+  writer->json_keyvalue("message", message);
   writer->json_keyvalue("nodeVersion", GetGlobalNodeVersion());
   writer->json_keyvalue("loadTime", GetStartTime("%Y-%m-%d %H:%M:%S"));
   writer->json_keyvalue("dumpTime", ConvertTime("%Y-%m-%d %H:%M:%S"));
@@ -37,7 +40,8 @@ static void WriteNodeReport(JSONWriter *writer) {
   writer->json_end();
 }
 
-void NodeReport::GetNodeReport(string filepath) {
+void NodeReport::GetNodeReport(string filepath, string location,
+                               string message) {
   ofstream outfile;
   outfile.open(filepath, ios::out | ios::binary);
   if (!outfile.is_open()) {
@@ -46,7 +50,7 @@ void NodeReport::GetNodeReport(string filepath) {
     return;
   }
   JSONWriter writer(outfile);
-  WriteNodeReport(&writer);
+  WriteNodeReport(&writer, location, message);
   outfile.close();
 }
 }  // namespace xprofiler
diff --git a/src/commands/report/node_report.h b/src/commands/report/node_report.h
@@ -9,7 +9,8 @@ class NodeReport {
  public:
   NodeReport();
   virtual ~NodeReport();
-  static void GetNodeReport(string filepath);
+  static void GetNodeReport(string filepath, string location = "Active Dump",
+                            string message = "Active Dump");
 };
 }  // namespace xprofiler
 

diff --git a/src/commands/simple/config.cc b/src/commands/simple/config.cc
@@ -14,6 +14,7 @@ COMMAND_CALLBACK(GetXprofilerConfig) {
   data["log_format_alinode"] = GetFormatAsAlinode();
   data["log_level"] = GetLogLevel();
   data["log_type"] = GetLogType();
+  data["enable_fatal_error_hook"] = GetEnableFatalErrorHook();
   success(data);
 }
 
@@ -37,6 +38,7 @@ COMMAND_CALLBACK(SetXprofilerConfig) {
   V(bool, enable_log_uv_handles, EnableLogUvHandles)
   V(LOG_LEVEL, log_level, LogLevel)
   V(LOG_TYPE, log_type, LogType)
+  V(bool, enable_fatal_error_hook, EnableFatalErrorHook)
 #undef V
   if (!setted)
     error(format("not support setting config %s", options.dump().c_str()));

diff --git a/src/configure.cc b/src/configure.cc
@@ -23,6 +23,7 @@ static bool enable_log_uv_handles = true;
 static bool log_format_alinode = false;
 static LOG_LEVEL log_level = LOG_ERROR;
 static LOG_TYPE log_type = LOG_TO_FILE;
+static bool enable_fatal_error_hook = true;
 
 #define COVERT_STRING(key)                                                 \
   if (key##_value->IsString()) {                                           \
@@ -69,6 +70,9 @@ void Configure(const FunctionCallbackInfo<Value> &info) {
 
   // log type: 0 file, 1 ttl
   W(log_type, CONVERT_UINT32_V2, LOG_TYPE)
+
+  // enable fatal error hook
+  V(enable_fatal_error_hook, CONVERT_BOOL)
 #undef S
 #undef V
 #undef W
@@ -88,6 +92,7 @@ void GetConfig(const FunctionCallbackInfo<Value> &info) {
   W(log_format_alinode, Boolean)
   W(log_level, Number)
   W(log_type, Number)
+  W(enable_fatal_error_hook, Boolean)
 #undef V
 #undef W
   info.GetReturnValue().Set(config);
@@ -102,5 +107,6 @@ V(bool, FormatAsAlinode, log_format_alinode)
 V(bool, EnableLogUvHandles, enable_log_uv_handles)
 V(LOG_LEVEL, LogLevel, log_level)
 V(LOG_TYPE, LogType, log_type)
+V(bool, EnableFatalErrorHook, enable_fatal_error_hook)
 #undef V
 }  // namespace xprofiler
diff --git a/src/configure.h b/src/configure.h
@@ -20,6 +20,7 @@ V(bool, FormatAsAlinode)
 V(bool, EnableLogUvHandles)
 V(LOG_LEVEL, LogLevel)
 V(LOG_TYPE, LogType)
+V(bool, EnableFatalErrorHook)
 #undef V
 
 // javascript accessible

diff --git a/src/hooks/fatal_error.cc b/src/hooks/fatal_error.cc
@@ -0,0 +1,27 @@
+#include "../commands/report/node_report.h"
+#include "../configure.h"
+#include "../library/utils.h"
+#include "../logger.h"
+#include "../platform/platform.h"
+#include "nan.h"
+
+namespace xprofiler {
+using std::string;
+using std::to_string;
+using v8::Isolate;
+
+static const char module_type[] = "fatal_error";
+
+static void OnFatalError(const char* location, const char* message) {
+  string filepath = GetLogDir() + GetSep() + "x-fatal-error-" +
+                    to_string(GetPid()) + "-" + ConvertTime("%Y%m%d") + "-" +
+                    RandNum() + ".diag";
+  Info(module_type, "dump report to %s.", filepath.c_str());
+  NodeReport::GetNodeReport(filepath, location, message);
+}
+
+void SetFatalErrorHandler() {
+  Isolate* isolate = Isolate::GetCurrent();
+  isolate->SetFatalErrorHandler(OnFatalError);
+}
+}  // namespace xprofiler
diff --git a/src/hooks/fatal_error.h b/src/hooks/fatal_error.h
@@ -0,0 +1,8 @@
+#ifndef _SRC_HOOKS_FATAL_ERROR_H
+#define _SRC_HOOKS_FATAL_ERROR_H
+
+namespace xprofiler {
+void SetFatalErrorHandler();
+}
+
+#endif
diff --git a/src/hooks/set_hooks.cc b/src/hooks/set_hooks.cc
@@ -0,0 +1,13 @@
+#include "set_hooks.h"
+
+#include "../configure.h"
+#include "fatal_error.h"
+
+namespace xprofiler {
+void SetHooks(const FunctionCallbackInfo<Value> &info) {
+  // set fatal error hook
+  if (GetEnableFatalErrorHook()) {
+    SetFatalErrorHandler();
+  }
+}
+}  // namespace xprofiler
diff --git a/src/hooks/set_hooks.h b/src/hooks/set_hooks.h
@@ -0,0 +1,12 @@
+#ifndef _SRC_HOOKS_SET_HOOKS_H
+#define _SRC_HOOKS_SET_HOOKS_H
+
+#include "nan.h"
+
+namespace xprofiler {
+using Nan::FunctionCallbackInfo;
+using v8::Value;
+void SetHooks(const FunctionCallbackInfo<Value> &info);
+}  // namespace xprofiler
+
+#endif
diff --git a/src/xprofiler.cc b/src/xprofiler.cc
@@ -1,5 +1,6 @@
 #include "commands/listener.h"
 #include "configure.h"
+#include "hooks/set_hooks.h"
 #include "library/common.h"
 #include "logbypass/log.h"
 #include "logger.h"
@@ -33,6 +34,10 @@ NAN_MODULE_INIT(Initialize) {
 
   // commands listener
   V(runCommandsListener, RunCommandsListener)
+
+  // set hooks
+  V(setHooks, SetHooks)
+
 #undef V
 }
 

diff --git a/test/commands.test.js b/test/commands.test.js
@@ -13,9 +13,11 @@ const xprofctl = path.join(__dirname, '../bin/xprofctl');
 const xctl = require('../lib/xctl');
 const utils = require('./fixtures/utils');
 
+const commandTestFixture = require('./fixtures/command.test');
+const { checkProfile } = commandTestFixture;
 const logdir = utils.createLogDir('logdir_command');
 const tmphome = utils.createLogDir('tmphome_command');
-const testConfig = require('./fixtures/command.test')(logdir);
+const testConfig = commandTestFixture(logdir);
 const testFiles = [
   { jspath: path.join(__dirname, './fixtures/blocking.js'), desc: 'when js main thread blocking' },
   { jspath: path.join(__dirname, './fixtures/non-blocking.js'), desc: 'when js main thread non blocking' }
@@ -33,35 +35,6 @@ function convertOptions(options) {
   return extra;
 }
 
-function checkProfile(rules, obj) {
-  for (const [key, rule] of Object.entries(rules)) {
-    const value = obj[key];
-    if (rule instanceof RegExp) {
-      it(`${key}: ${value} shoule be ${rule}`, function () {
-        expect(rule.test(value)).to.be.ok();
-      });
-    } else if (Array.isArray(rule)) {
-      for (const v of value) {
-        checkProfile(rule[0], v);
-      }
-    } else if (typeof rule === 'function') {
-      let label = value;
-      if (Array.isArray(value)) {
-        if (value.length < 10) {
-          label = `${JSON.stringify(value)} length: ${value.length}`;
-        } else {
-          label = `Array [${value[0]}, ${value[1]}, ${value[2]}, ...] length: ${value.length}`;
-        }
-      }
-      it(`${key}: ${label} shoule be ${rule}`, function () {
-        expect(rule(value)).to.be.ok();
-      });
-    } else if (typeof rule === 'object') {
-      checkProfile(rule, value);
-    }
-  }
-}
-
 for (let i = 0; i < testConfig.length; i++) {
   const { cmd, options = {}, profileRules, errored = false, xctlRules, xprofctlRules } = testConfig[i];
   for (let j = 0; j < testFiles.length; j++) {
@@ -90,13 +63,14 @@ for (let i = 0; i < testConfig.length; i++) {
         // send cmd with xprofctl (cli)
         const extra = convertOptions(options);
         const nodeExe = os.platform() === 'win32' ? 'node ' : '';
-        console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}`, 'send xprofctl cmd.');
+        console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, 'send xprofctl cmd.');
         resByXprofctl = await exec(`${nodeExe}${xprofctl} ${cmd} -p ${pid}${extra}`, {
           env: Object.assign({}, process.env, {
             XPROFILER_UNIT_TEST_TMP_HOMEDIR: tmphome
           })
         });
         resByXprofctl = resByXprofctl.stderr.trim() + resByXprofctl.stdout.trim();
+        console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, 'wait for child process done.');
         await new Promise(resolve => p.on('close', resolve));
       });
 

diff --git a/test/fixtures/blocking.js b/test/fixtures/blocking.js
@@ -3,7 +3,9 @@
 const os = require('os');
 const mm = require('mm');
 const moment = require('moment');
-console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, 'blocking start.');
+const uuid = require('uuid/v4');
+const traceid = uuid();
+console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, traceid, 'blocking start.');
 
 const xprofiler = require('../../');
 
@@ -14,14 +16,22 @@ if (process.env.XPROFILER_UNIT_TEST_TMP_HOMEDIR) {
 process.env.XPROFILER_UNIT_TEST_SINGLE_MODULE = 'YES';
 
 xprofiler();
+console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, traceid, 'blocking xprofiler() done.');
 
 // start log bypass
 xprofiler.runLogBypass();
 xprofiler.runLogBypass();
+console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, traceid, 'blocking xprofiler.runLogBypass() done.');
 
 // start commands listener
 xprofiler.runCommandsListener();
 xprofiler.runCommandsListener();
+console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, traceid, 'blocking xprofiler.runCommandsListener() done.');
+
+// set v8 hooks
+xprofiler.setHooks();
+xprofiler.setHooks();
+console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, traceid, 'blocking xprofiler.setHooks() done.');
 
 /*eslint no-empty: "off"*/
 const start = Date.now();
@@ -30,5 +40,5 @@ while (Date.now() - start < 8000) {
 }
 
 mm.restore();
-console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, 'blocking done.');
+console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, traceid, 'blocking done.');
 process.exit(0);