排查 Node.js 耗時代碼的一種方案
我們知道 Node.js 是單線程應用，代碼都是按序執(zhí)行的，如果某段代碼非常耗時那么后面的代碼就會被一直堵住無法執(zhí)行。所以在寫 Node.js 應用時我們需要非常謹慎，避免出現這種情況。然而很多時候，問題還是無法避免，那么應該如何排查這種問題呢？我們都知道可以通過采集 CPU Profile 來分析代碼的執(zhí)行情況。但是在主線程被堵住的情況下，已經沒有機會開啟采集動作了，當然也有其他辦法，不過總的來說，CPU Profile 雖然方便排查問題，但是在實際環(huán)境中，如何采集 CPU Profile 是一個問題，這里不討論這個，只介紹一種輕量級的方案。
例子
先看一個例子。
while(1) {}執(zhí)行 node --trace-sigint demo.mjs，然后按下 ctrl+c，會看到如下輸入。
KEYBOARD_INTERRUPT: Script execution was interrupted by `SIGINT`
at /node/demo.mjs:1:1可以看到，盡管代碼陷入了死循環(huán)，但是這種方式仍然可以采集到當前的調用棧信息，這樣就可以知道是哪個代碼比較耗時了。這種方案的底層實現并不復雜，主要是依賴操作系統的信號機制，在收到信號時采集收集當前 JS 調用棧即可，因為信號有非常高的優(yōu)先級，所以盡管死循環(huán)也可以被處理。
實現原理
但是這種方式只能收集 JS 的調用棧，不能收集底層 C/C++ 代碼的調用棧，這個主要是因為在信號里收集 C/C++ 調用棧嚴重來說不是一個安全的操作，盡管這樣做很多時候也不會出現問題。所以只能在第三方的庫里實現這個能力，下面簡單介紹下實現并看一下效果。
首先提供一個 install 函數來開啟這個能力。
void Initialize( Local<Object> exports, Local<Value> module, Local<Context> context) {
NODE_SET_METHOD(exports, "install", Install);
}install 實現如下：
void Install(const FunctionCallbackInfo<Value>& args) {
// 創(chuàng)建線程
pthread_t thread;
int ret = pthread_create(&thread, nullptr, Worker, isolate);
// 注冊信號
struct sigaction sa;
memset(&sa, 0, sizeof(sa));
sa.sa_sigaction = handler;
sa.sa_flags = 0;
sigfillset(&sa.sa_mask);
sigaction(SIGINT, &sa, nullptr);
}install 就做了兩件事情，一個是創(chuàng)建一個子線程，一個是注冊信號。其原理也很簡單，在收到信號時，信號處理函數就會給子線程發(fā)送信號，子線程利用 V8 的 API 請求收集 JS 調用棧。接著看一下信號處理函數的實現。
void handler(int signum,
siginfo_t* info,
void* ucontext) {
int fd = open("./trace_cpp_call_stack.log", O_RDWR | O_TRUNC | O_CREAT, 0777);
void* buffer[256];
// 獲取 C/C++ 調用棧
const int size = backtrace(buffer, 256);
// 獲取代碼信息，demangle 后寫入文件
for (int i = 1; i < size; i++) {
void* frame = buffer[i];
std::string data = LookupSymbol(frame).Display() + "\n";
write(fd,data.c_str(),data.size());
}
close(fd);
// 通知子線程
uv_sem_post(&sem);
}信號處理函數首先收集了 C/C++ 代碼的調用棧，然后通知子線程收集 JS 調用棧，接著看一下子線程的實現。
void* Worker(void* arg) {
Isolate* isolate = static_cast<Isolate*>(arg);
do {
// 等待通知
uv_sem_wait(&sem);
// 請求 V8 執(zhí)行注冊的函數
isolate->RequestInterrupt(
[](v8::Isolate* isolate, void* data) {
// 收集 JS 調用棧
PrintStackTrace(isolate,
v8::StackTrace::CurrentStackTrace(
isolate, 10, v8::StackTrace::kDetailed));
},
isolate);
} while (1);
return nullptr;
}Worker 利用了 V8 RequestInterrupt 函數向 V8 請求執(zhí)行收集 JS 調用棧的任務。這里面還有一些細節(jié)就不一一介紹了，主要理解大致原理就行。
效果
JS 耗時代碼
接下來看下 JS 層代碼耗時時的分析效果。
const { install } = require('...');
install();
function a() {
b();
}
function b() {
c();
}
function c() {
for (let i = 0; i < 1000000000; i++) {
}
}
while(1) {
a();
}執(zhí)行上面的代碼按下 ctrl+c 會看到輸入當前的 JS 調用棧，這樣就可以知道是哪里的代碼有問題了。
at c (/code/nodejs/trace-call-stack/test/test_js/index.js:14:5)
at b (/code/nodejs/trace-call-stack/test/test_js/index.js:10:5)
at a (/code/nodejs/trace-call-stack/test/test_js/index.js:6:5)
at /code/nodejs/trace-call-stack/test/test_js/index.js:20:5
at Module._compile (node:internal/modules/cjs/loader:1529:14)
at Module._extensions..js (node:internal/modules/cjs/loader:1613:10)
at Module.load (node:internal/modules/cjs/loader:1275:32)
at Module._load (node:internal/modules/cjs/loader:1096:12)
at executeUserEntryPoint (node:internal/modules/run_main:164:12)
at node:internal/main/run_main_module:28:49C/C++ 耗時代碼
接下來看一下 C/C++ 代碼耗時時的效果。
Matrix multiply(const Matrix& a, const Matrix& b) {
int n = a.size();
int m = a[0].size();
int k = b[0].size();
Matrix c(n, std::vector<double>(k, 0.0));
for (int i = 0; i < n; ++i) {
for (int j = 0; j < k; ++j) {
for (int p = 0; p < m; ++p) {
c[i][j] += a[i][p] * b[p][j]; // 三重循環(huán)，計算量極大
}
}
}
return c;
}
void Compute(const FunctionCallbackInfo<Value>& args) {
Matrix a(1000, std::vector<double>(1000, 5.0));
Matrix b(1000, std::vector<double>(1000, 10.0));
auto c = multiply(a, b);
}上面是一個非常耗時的 C/C++ addon，通過在 JS 層執(zhí)行該函數，然后執(zhí)行 ctrl+c 可以看到 C/C++調用棧包含了 multiply 函數，說明可以正確采集到調用棧。
test::multiply(...) [/code/nodejs/trace-call-stack/test/test_cpu_addon/build/Release/test.node]
test::Compute(...) [/code/nodejs/trace-call-stack/test/test_cpu_addon/build/Release/test.node]C/C++ 代碼阻塞
接著再看一下 C/C++ 層阻塞到情況，比如加鎖失敗，主動睡眠等。
void Wait(const FunctionCallbackInfo<Value>& args) {
uv_sem_init(&sem, 0);
uv_sem_wait(&sem);
}在 addon 里執(zhí)行上面的代碼會導致線程進入睡眠狀態(tài)，這時候按 ctrl+c 可以看到輸出中包含 uv_sem_wait 函數。
uv_sem_wait [/node/v20.19.2/bin/node]總結
通過這個工具我們就可以方便收集各個語言層面的代碼調用棧，從而方便問題的排查，不過目前只是做了簡單的實現和驗證，后續(xù)有時間再優(yōu)化。另外我也嘗試提交了一個 PR 把 trace-sigint 作為運行時 API 暴露出來，方便用戶靈活調用，尤其是 APM 的開發(fā)者。
1. https://github.com/nodejs/node/pull/59040
2. https://github.com/theanarkh/trace-call-stack
