diff --git a/src/commands/dump.cc b/src/commands/dump.cc index 5c17832..f4fa2af 100644 --- a/src/commands/dump.cc +++ b/src/commands/dump.cc @@ -135,16 +135,19 @@ void AfterDumpFile(Isolate* isolate, string& filepath, string notify_type, notify_type.c_str(), unique_key.c_str()); \ delete dump_data; -#define CHECK_ERR(func) \ - func; \ - if (err.Fail()) { \ - DebugT(module_type, env_data->thread_id(), "<%s> %s error: %s", \ - notify_type.c_str(), unique_key.c_str(), err.GetErrMessage()); \ - CLEAR_DATA; \ - return; \ +#define CHECK_ERR(func) \ + if (need_check) { \ + func; \ + if (err.Fail()) { \ + DebugT(module_type, env_data->thread_id(), "<%s> %s error: %s", \ + notify_type.c_str(), unique_key.c_str(), err.GetErrMessage()); \ + CLEAR_DATA; \ + return; \ + } \ } -void HandleAction(v8::Isolate* isolate, void* data, string notify_type) { +void HandleAction(v8::Isolate* isolate, void* data, string notify_type, + bool need_check = true) { BaseDumpData* dump_data = static_cast(data); string traceid = dump_data->traceid; DumpAction action = dump_data->action; @@ -253,12 +256,60 @@ void HandleAction(v8::Isolate* isolate, void* data, string notify_type) { if (dump_data->run_once) { CLEAR_DATA; } - return; } #undef CHECK_ERR #undef CLEAR_DATA +template +T* CreateFinishDumpData(EnvironmentData* env_data) { + T* data = new T; + data->traceid = "finish"; + data->thread_id = env_data->thread_id(); + data->action = action; + return data; +} + +void FinishSampling(Isolate* isolate, const char* reason) { + EnvironmentData* env_data = EnvironmentData::GetCurrent(isolate); + + DebugT(module_type, env_data->thread_id(), "finish sampling because: %s.", + reason); + + ActionMap current; + current.swap(*env_data->action_map()); + + void* data = nullptr; + + for (auto itor : current) { + switch (itor.first) { + case START_CPU_PROFILING: + data = static_cast( + CreateFinishDumpData( + env_data)); + break; + case START_SAMPLING_HEAP_PROFILING: + data = static_cast( + CreateFinishDumpData(env_data)); + break; + case START_GC_PROFILING: + data = static_cast( + CreateFinishDumpData( + env_data)); + break; + default: + break; + } + + if (data == nullptr) { + continue; + } + + HandleAction(isolate, data, reason, false); + } +} + static void WaitForProfile(uint64_t profiling_time) { uint64_t start = uv_hrtime(); while (uv_hrtime() - start < profiling_time * 10e5) { diff --git a/src/commands/dump.h b/src/commands/dump.h index 8975750..e51af5b 100644 --- a/src/commands/dump.h +++ b/src/commands/dump.h @@ -21,9 +21,9 @@ enum DumpAction { COREDUMP, }; -using ActionMap = std::unordered_map; -using ConflictMap = std::unordered_map>; -using DependentMap = std::unordered_map; +using ActionMap = std::unordered_map; +using ConflictMap = std::unordered_map>; +using DependentMap = std::unordered_map; struct BaseDumpData { std::string traceid; @@ -47,6 +47,8 @@ struct NodeReportDumpData : BaseDumpData {}; struct CoreDumpData : BaseDumpData {}; +void FinishSampling(v8::Isolate* isolate, const char* reason); + COMMAND_CALLBACK(StartCpuProfiling); COMMAND_CALLBACK(StopCpuProfiling); COMMAND_CALLBACK(Heapdump); diff --git a/src/environment_data.cc b/src/environment_data.cc index 087ab41..518ee6a 100644 --- a/src/environment_data.cc +++ b/src/environment_data.cc @@ -2,6 +2,7 @@ #include +#include "commands/dump.h" #include "logbypass/log.h" #include "process_data.h" #include "util-inl.h" @@ -68,6 +69,9 @@ void EnvironmentData::AtExit(void* arg) { EnvironmentRegistry::NoExitScope scope(registry); std::unique_ptr env_data = registry->Unregister(isolate); + // finish sampling + FinishSampling(isolate, "at_exit"); + for (auto callback : env_data->gc_epilogue_callbacks_) { Nan::RemoveGCEpilogueCallback(callback); } diff --git a/src/hooks/fatal_error.cc b/src/hooks/fatal_error.cc index f95f0f9..431fa59 100644 --- a/src/hooks/fatal_error.cc +++ b/src/hooks/fatal_error.cc @@ -1,4 +1,5 @@ #include "commands/coredumper/coredumper.h" +#include "commands/dump.h" #include "commands/report/node_report.h" #include "configure-inl.h" #include "environment_data.h" @@ -28,6 +29,11 @@ void DumpBeforeAbort(const char* location, const char* message) { EnvironmentData* env_data = EnvironmentData::GetCurrent(isolate); ThreadId thread_id = env_data->thread_id(); +#ifndef _WIN32 + // finish sampling + FinishSampling(isolate, "fatal_error"); +#endif + // generate report before abort if (GetEnableFatalErrorReport()) { string filepath = GetLogDir() + GetSep() + "x-fatal-error-" + diff --git a/test/commands.test.js b/test/commands.test.js index 94e1c30..a470cad 100644 --- a/test/commands.test.js +++ b/test/commands.test.js @@ -74,13 +74,16 @@ describe('commands', () => { }) }); pid = p.pid; + + // wait for xprofiler to start await new Promise(resolve => p.on('message', msg => msg.type === utils.clientConst.xprofilerDone && resolve())); - await utils.sleep(500); + // send cmd with xctl (function) console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, 'send xctl cmd.'); resByXctl = await xctl(pid, threadId, cmd, options); await utils.sleep(500); + // send cmd with xprofctl (cli) const extra = convertOptions(options); const nodeExe = currentPlatform === 'win32' ? 'node ' : ''; @@ -93,6 +96,8 @@ describe('commands', () => { }) }); resByXprofctl = resByXprofctl.stderr.trim() + resByXprofctl.stdout.trim(); + + // exit info console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, 'wait for child process done.'); exitInfo = await utils.getChildProcessExitInfo(p); }); diff --git a/test/fixtures/command.test.js b/test/fixtures/command.test.js index 4c9152c..e4af8f5 100644 --- a/test/fixtures/command.test.js +++ b/test/fixtures/command.test.js @@ -394,7 +394,7 @@ exports = module.exports = function (logdir) { return filterTestCaseByPlatform(list); }; -exports.profileRule = { diag }; +exports.profileRule = { diag, cpuprofile, heapprofile, gcprofile }; exports.checkProfile = checkProfile; diff --git a/test/fixtures/exit.js b/test/fixtures/exit.js new file mode 100644 index 0000000..b64550d --- /dev/null +++ b/test/fixtures/exit.js @@ -0,0 +1,18 @@ +'use strict'; + +const os = require('os'); +const mm = require('mm'); +const xprofiler = require('../../'); +const utils = require('./utils'); + +if (process.env.XPROFILER_UNIT_TEST_TMP_HOMEDIR) { + mm(os, 'homedir', () => process.env.XPROFILER_UNIT_TEST_TMP_HOMEDIR); +} + +xprofiler(); + +process.send({ type: utils.clientConst.xprofilerDone }); + +setTimeout(() => { + // empty exit +}, 2000); \ No newline at end of file diff --git a/test/fixtures/fatal-error.js b/test/fixtures/fatal-error.js index b9129d8..8a988e7 100644 --- a/test/fixtures/fatal-error.js +++ b/test/fixtures/fatal-error.js @@ -1,10 +1,21 @@ 'use strict'; +const os = require('os'); +const mm = require('mm'); const xprofiler = require('../../'); +const utils = require('./utils'); + +if (process.env.XPROFILER_UNIT_TEST_TMP_HOMEDIR) { + mm(os, 'homedir', () => process.env.XPROFILER_UNIT_TEST_TMP_HOMEDIR); +} + xprofiler(); +process.send({ type: utils.clientConst.xprofilerDone }); + const array = []; + setInterval(() => { array.push(new Array(10e6).fill('*')); console.log('now rss:', process.memoryUsage().rss / 1024 / 1024 + ' Mb'); -}, 1); \ No newline at end of file +}, Number(process.env.XPROFILER_FATAL_ERROR_INTERVAL) || 1); \ No newline at end of file diff --git a/test/fixtures/unfinished.test.js b/test/fixtures/unfinished.test.js new file mode 100644 index 0000000..faa60f5 --- /dev/null +++ b/test/fixtures/unfinished.test.js @@ -0,0 +1,125 @@ +'use strict'; + +const fs = require('fs'); +const path = require('path'); +const { profileRule: { cpuprofile, heapprofile, gcprofile }, checkProfile } = require('./command.test'); + +exports = module.exports = function () { + const list = [ + // fatal error + { + title: ' cpu profiling', + jspath: path.join(__dirname, 'fatal-error.js'), + tid: 0, + cmd: 'start_cpu_profiling', + options: { profiling_time: 5 * 60 * 1000 }, + checkExitInfo: false, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(cpuprofile, JSON.parse(content)); + } + }, + { + title: ' heap profiling', + jspath: path.join(__dirname, 'fatal-error.js'), + tid: 0, + cmd: 'start_heap_profiling', + options: { profiling_time: 5 * 60 * 1000 }, + checkExitInfo: false, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(heapprofile, JSON.parse(content)); + } + }, + { + title: ' gc profiling', + jspath: path.join(__dirname, 'fatal-error.js'), + tid: 0, + cmd: 'start_gc_profiling', + options: { profiling_time: 5 * 60 * 1000 }, + checkExitInfo: false, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(gcprofile, JSON.parse(content)); + } + }, + + // exit 0 with profiling time + { + title: ' cpu profiling', + jspath: path.join(__dirname, 'exit.js'), + tid: 0, + cmd: 'start_cpu_profiling', + options: { profiling_time: 5 * 60 * 1000 }, + checkExitInfo: true, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(cpuprofile, JSON.parse(content)); + } + }, + { + title: ' heap profiling', + jspath: path.join(__dirname, 'exit.js'), + tid: 0, + cmd: 'start_heap_profiling', + options: { profiling_time: 5 * 60 * 1000 }, + checkExitInfo: true, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(heapprofile, JSON.parse(content)); + } + }, + { + title: ' gc profiling', + jspath: path.join(__dirname, 'exit.js'), + tid: 0, + cmd: 'start_gc_profiling', + options: { profiling_time: 5 * 60 * 1000 }, + checkExitInfo: true, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(gcprofile, JSON.parse(content)); + } + }, + + // exit 0 with no profiling time + { + title: ' cpu profiling', + jspath: path.join(__dirname, 'exit.js'), + tid: 0, + cmd: 'start_cpu_profiling', + options: undefined, + checkExitInfo: true, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(cpuprofile, JSON.parse(content)); + } + }, + { + title: ' heap profiling', + jspath: path.join(__dirname, 'exit.js'), + tid: 0, + cmd: 'start_heap_profiling', + options: undefined, + checkExitInfo: true, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(heapprofile, JSON.parse(content)); + } + }, + { + title: ' gc profiling', + jspath: path.join(__dirname, 'exit.js'), + tid: 0, + cmd: 'start_gc_profiling', + options: undefined, + checkExitInfo: true, + check(file) { + const content = fs.readFileSync(file, 'utf8').trim(); + checkProfile(gcprofile, JSON.parse(content)); + } + }, + ]; + + return list; +}; \ No newline at end of file diff --git a/test/unfinished.test.js b/test/unfinished.test.js new file mode 100644 index 0000000..b7f1e38 --- /dev/null +++ b/test/unfinished.test.js @@ -0,0 +1,82 @@ +'use strict'; + +const os = require('os'); +const fs = require('fs'); +const cp = require('child_process'); +const mm = require('mm'); +const expect = require('expect.js'); +const moment = require('moment'); +const utils = require('./fixtures/utils'); +const xctl = require('../lib/xctl'); +const cases = require('./fixtures/unfinished.test')(); + +const casesLength = cases.length; + +const logdir = utils.createLogDir('logdir_sampling'); +const tmphome = utils.createLogDir('tmphome_sampling'); + + +describe('unfinished sampling before process exit', function () { + for (const cse of cases) { + describe(cse.title, function () { + let resByXctl = { ok: false }; + let exitInfo = { code: null, signal: null }; + + before(async function () { + mm(os, 'homedir', () => tmphome); + const p = cp.fork(cse.jspath, { + execArgv: ['--max-old-space-size=128'], + env: Object.assign({}, process.env, { + XPROFILER_LOG_DIR: logdir, + XPROFILER_UNIT_TEST_TMP_HOMEDIR: tmphome, + XPROFILER_LOG_LEVEL: 2, + XPROFILER_LOG_TYPE: 1, + XPROFILER_FATAL_ERROR_INTERVAL: 100, + }) + }); + + // wait for xprofiler to start + await new Promise(resolve => p.on('message', msg => + msg.type === utils.clientConst.xprofilerDone && resolve())); + + // send cmd + const pid = p.pid; + resByXctl = await xctl(pid, cse.tid, cse.cmd, cse.options); + + // process exit + exitInfo = await utils.getChildProcessExitInfo(p); + await utils.sleep(2000); + }); + + after(function () { + if (cse === cases[casesLength - 1]) { + mm.restore(); + utils.cleanDir(logdir); + utils.cleanDir(tmphome); + } + }); + + (cse.checkExitInfo ? it : it.skip)(`child process should be exited with code 0`, function () { + console.log(`[${moment().format('YYYY-MM-DD HH:mm:ss')}]`, `exit info: ${JSON.stringify(exitInfo)}`); + utils.checkChildProcessExitInfo(expect, exitInfo); + }); + + (cse.checkExitInfo ? it : it.skip)(`sampling file should be exists when process exit`, function () { + console.log('xtcl:', JSON.stringify(resByXctl)); + expect(resByXctl.ok); + const filepath = resByXctl.data.filepath; + expect(filepath); + expect(fs.existsSync(filepath)); + }); + + (cse.checkExitInfo ? it : it.skip)('value should be ok', async function () { + describe(`it has expected structure`, function () { + if (typeof cse.check !== 'function') { + return; + } + cse.check(resByXctl.data.filepath); + }); + }); + }); + } +}); \ No newline at end of file