Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

收集堆信息时,进程退出 #179

Closed
yunnysunny opened this issue May 17, 2022 · 25 comments
Closed

收集堆信息时,进程退出 #179

yunnysunny opened this issue May 17, 2022 · 25 comments
Labels
question Further information is requested

Comments

@yunnysunny
Copy link

yunnysunny commented May 17, 2022

在管理后台点击生成堆快照,然后应用进程就退出了,进程退出返回码 3221225477
xprofiler 用的最新的 1.4.0 版本,node 用的 14.19.1,操作系统是 win 10

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

v1.4x 的 v8 确实存在 bug:

function that() {
  const p = new Promise(resolve => {
    setTimeout(resolve, 1);
  });
  Promise.all([p]); // <= 关键问题点,创建了一个 PromiseAllResolveElementContext
}
that();

const v8 = require('v8');
const fs = require('fs');
const stream = fs.createWriteStream('./node.heapsnapshot');
v8.getHeapSnapshot().pipe(stream);

这种 Promise.all 会导致调用 v8 提供的快照 api crash,这个问题在 v16.x 以及 v14.x 的最新版本中已经修复,可以升级下解决,比如升级到 v14.19.2


另一种可能就是你抓取的时候堆使用率过高,导致序列化快照的时候 OOM

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

具体的上游 issue 修复可以参见:nodejs/node#42558

@hyj1991 hyj1991 added the question Further information is requested label May 17, 2022
@yunnysunny
Copy link
Author

应用刚启动的时候收集的,堆空间只有100MB,所以不是 OOM 的问题。那看起来就是这个node 14.9.1 的bug 了。我尝试升级一下node版本。

@yunnysunny
Copy link
Author

我看官方在 14.19.2 版本修复了这个bug nodejs/node#42637 ,所以我装了这个版本,然后重新在管理后台生成堆快照,现在应用进程不退出了,但是会弹窗报 Inner server error,同时留意到应用程序标准输出中有如下日志:

[2022-05-17 10:42:34] [1.5.0] [error] [25468] checkActionFile failed: Unexpected end of JSON input

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

你有没有自己改过代码?

@yunnysunny
Copy link
Author

你有没有自己改过代码?

没有改过

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

https://github.com/X-Profiler/xtransit/blob/master/lib/handler.js#L34

看下进了这个 if 判断后这里的 options 和 stdout 输出了啥,正常不会有 parse 的问题

@yunnysunny
Copy link
Author

https://github.com/X-Profiler/xtransit/blob/master/lib/handler.js#L34

看下进了这个 if 判断后这里的 options 和 stdout 输出了啥,正常不会有 parse 的问题

options 是 {} ,stdout 没有数据,是空字符串

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

看下 xtransit 的版本,然后增加一个配置 logLevel: 3,再完整抓一次堆快照,把 xtransit 的 debug 日志贴出来看下

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

[from xtransit-server] >>>>>>>>>>>>>>>>>>> {"traceId":"aa9cfee6-ae05-43c9-9023-a616719ee2a7","type":"exec_command","data":{"command":"xprofctl 11532 heapdump {}","expiredTime":15000}}
[2022-05-17 11:20:41] [2.0.1] [debug] [11532] [execute command] C:\Program Files\nodejs\node.exe C:\Users\hyj1991\AppData\Roaming\nvm\v16.15.0\node_modules\xtransit\commands\xprofctl.js 11532 heapdump {}
[2022-05-17 11:20:43] [2.0.1] [debug] [11532] [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":1,"agentId":"GDP-WIN3","traceId":"aa9cfee6-ae05-43c9-9023-a616719ee2a7","clientId":"4e8c9e3a82065e047c9c81a8ddb39d4b","timestamp":1652757643005,"type":"response","data":{"ok":true,"data":{"stdout":"{\"filepath\":\"C:\\\\Users\\\\hyj1991\\\\AppData\\\\Local\\\\Temp\\\\x-heapdump-11532-20220517-0.heapsnapshot\"}\n","stderr":""}},"signature":"e84243c151449e0bf6da702a21b3e8c8803f29ef"}
[2022-05-17 11:20:47] [2.0.1] [debug] [11532] [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":1,"agentId":"GDP-WIN3","traceId":"54a540bd-08c2-4dff-bc7a-be94013f91d7","clientId":"4e8c9e3a82065e047c9c81a8ddb39d4b","timestamp":1652757647015,"type":"action","data":{"filePath":"C:\\Users\\hyj1991\\AppData\\Local\\Temp\\x-heapdump-11532-20220517-0.heapsnapshot"},"signature":"e7cb08446c73c2d2b99415d6a592087056b59c51"}

正常 win 下的一次快照 action 交互应该可以看到这样的 debug 日志。

@yunnysunny
Copy link
Author

xtransit用的最新的版本 1.5.0,我再抓下日志看看

@yunnysunny
Copy link
Author

[from xtransit-server] >>>>>>>>>>>>>>>>>>> {"traceId":"aa9cfee6-ae05-43c9-9023-a616719ee2a7","type":"exec_command","data":{"command":"xprofctl 11532 heapdump {}","expiredTime":15000}}
[2022-05-17 11:20:41] [2.0.1] [debug] [11532] [execute command] C:\Program Files\nodejs\node.exe C:\Users\hyj1991\AppData\Roaming\nvm\v16.15.0\node_modules\xtransit\commands\xprofctl.js 11532 heapdump {}
[2022-05-17 11:20:43] [2.0.1] [debug] [11532] [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":1,"agentId":"GDP-WIN3","traceId":"aa9cfee6-ae05-43c9-9023-a616719ee2a7","clientId":"4e8c9e3a82065e047c9c81a8ddb39d4b","timestamp":1652757643005,"type":"response","data":{"ok":true,"data":{"stdout":"{\"filepath\":\"C:\\\\Users\\\\hyj1991\\\\AppData\\\\Local\\\\Temp\\\\x-heapdump-11532-20220517-0.heapsnapshot\"}\n","stderr":""}},"signature":"e84243c151449e0bf6da702a21b3e8c8803f29ef"}
[2022-05-17 11:20:47] [2.0.1] [debug] [11532] [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":1,"agentId":"GDP-WIN3","traceId":"54a540bd-08c2-4dff-bc7a-be94013f91d7","clientId":"4e8c9e3a82065e047c9c81a8ddb39d4b","timestamp":1652757647015,"type":"action","data":{"filePath":"C:\\Users\\hyj1991\\AppData\\Local\\Temp\\x-heapdump-11532-20220517-0.heapsnapshot"},"signature":"e7cb08446c73c2d2b99415d6a592087056b59c51"}

正常 win 下的一次快照 action 交互应该可以看到这样的 debug 日志。

xtransit的logLevel由2改为了3,但是发现并没有上述日志

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

你是集成到你自己的应用启动的?如果是这样你要看下你应用实现的 debug logger 是否启用了。

我这里给出来的日志样例是全局启动的方式,用的是内置的 logger

@yunnysunny
Copy link
Author

yunnysunny commented May 17, 2022

[2022-05-17T12:12:36.300+0800] DEBUG default  [report_core] coredirs: 
[2022-05-17T12:12:36.544+0800] DEBUG default  [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":2,"agentId":"DESKTOP-188QF22","traceId":"c4af3757-1a26-41fe-a04d-f6429be6e5aa","clientId":"37629a0d751cd2574a9e89ed9b7a32c0","timestamp":1652760756544,"type":"log","data":{"type":"core_files","data":{"list":[]}},"signature":"a30537398fda3115d9d3ce7f1ccd5e2bfb05d8db"}
[2022-05-17T12:12:36.875+0800] DEBUG default  [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":2,"agentId":"DESKTOP-188QF22","traceId":"60891d0d-c8b0-4df2-bdfb-912348e1ba06","clientId":"37629a0d751cd2574a9e89ed9b7a32c0","timestamp":1652760756875,"type":"log","data":{"type":"system_log","data":{"cpu_count":8,"total_memory":17013510144,"uptime":132962,"log_time":"2022-05-17 12:12:35","log_timestamp":1652760755270,"version":"1.5.0","used_cpu":0.13440305921607587,"free_memory":1238106112,"load1":0,"load5":0,"load15":0,"disks":{},"node_count":29}},"signature":"24901fd2d05a98308d42aeb649c53503746cedfd"}
[2022-05-17T12:12:56.204+0800] DEBUG default  [from xtransit-server] >>>>>>>>>>>>>>>>>>> {"traceId":"2ee18e89-8863-493a-bfa7-f3b9eaa2e813","type":"exec_command","data":{"command":"xprofctl 24840 heapdump {}","expiredTime":15000}}
[2022-05-17T12:12:56.621+0800] DEBUG default  [execute command] d:\Program Files\nodejs\node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}
[2022-05-17T12:13:25.013+0800] ERROR default  checkActionFile failed: Unexpected end of JSON input
[2022-05-17T12:13:25.014+0800] DEBUG default  [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":2,"agentId":"DESKTOP-188QF22","traceId":"2ee18e89-8863-493a-bfa7-f3b9eaa2e813","clientId":"37629a0d751cd2574a9e89ed9b7a32c0","timestamp":1652760805014,"type":"response","data":{"ok":true,"data":{"stdout":"","stderr":""}},"signature":"3dccd5519d359b6bd81b398faab78f12a9b53586"}

同时留意到在系统temp目录中堆快照是生成成功的。

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

看起来是 node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {} 这个执行有点问题,stdout 和 stderr 都是空。

https://github.com/X-Profiler/xtransit/blob/v1.5.0/commands/xprofctl.js#L34

可以手动执行下这个文件,看看这里返回了什么信息,我本地的 windows 机器试了下没什么问题

@yunnysunny
Copy link
Author

改了一下源代码:

'use strict';

const fs = require('fs');
const os = require('os');
const path = require('path');
const { promisify } = require('util');
const exists = promisify(fs.exists);
const readFile = promisify(fs.readFile);

const [pid, command, options] = process.argv.slice(2);

async function takeAction() {
  const hiddenFile = path.join(os.homedir(), '.xprofiler');
  if (!await exists(hiddenFile)) {
    return console.error(`${hiddenFile} not exists`);
  }

  let result;
  const content = await readFile(hiddenFile, 'utf8');
  for (const proc of content.trim().split('\n')) {
    const [xpid, , , , , mod] = proc.split('\u0000');
    if (Number(pid) !== Number(xpid)) {
      continue;
    }

    // find xctl
    const xctl = path.join(mod, 'lib/xctl.js');
    if (!await exists(xctl)) {
      result = false;
      console.error(`${xctl} not exists`);
      break;
    }
    let _options = {};
    try {
        _options=JSON.parse(options);
    } catch (e) {
	console.error('invalid options',e);
	break;
    }
    const { ok, data, message } = await require(xctl)(pid, command, JSON.parse(options));
    if (!ok) {
      result = false;
      console.error(message);
      break;
    }

    result = true;
    console.log(JSON.stringify(data));
  }

  if (result === undefined) {
    console.error(`process <${pid}> not enable xprofiler`);
  }
}

takeAction().catch(err => console.error(err.message));

然后运行 node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {},结果输出

PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}
invalid options SyntaxError: Unexpected token e in JSON at position 1
    at JSON.parse (<anonymous>)
    at takeAction (E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js:35:17)
process <24840> not enable xprofiler

通过控制台看xprofile是没有问题的:
image

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

你手动执行的时候在命令行的 {} 参数要加引号,要不然当然会解析失败,通过控制台调用的时候有转义,其实已经是字符串了

@yunnysunny
Copy link
Author

加了引号确实正常输出了:

PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}
Unexpected token e in JSON at position 1
PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}
invalid options SyntaxError: Unexpected token e in JSON at position 1
    at JSON.parse (<anonymous>)
    at takeAction (E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js:35:17)
process <24840> not enable xprofiler
PS C:\Users\lenovo> tasklist | findstr 24840
node.exe                     24840 Console                    3    133,828 K
PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump "{}"
{"filepath":"C:\\Users\\lenovo\\AppData\\Local\\Temp\\x-heapdump-24840-20220517-1.heapsnapshot"}

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump "{}"
{"filepath":"C:\\Users\\lenovo\\AppData\\Local\\Temp\\x-heapdump-24840-20220517-1.heapsnapshot"}

这个是正常的输出,stdout 是一个 json 字符串,parse 后里面有 filepath 属性

那么你在控制台调用的时候,看看这里会输出什么

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

由于 windows 下文件盘符是 \,我猜测还是处理转义的时候哪里出了问题导致 JSON 的 parse 挂了

@yunnysunny
Copy link
Author

由于 windows 下文件盘符是 \,我猜测还是处理转义的时候哪里出了问题导致 JSON 的 parse 挂了

既然你的windows下能用的话,感觉不像是一个必现的问题。

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

你可以调试下这个文件,看看在你的机器上这里通过控制台调用的时候输出了什么,如果 stdout 正常能拿到 filepath 的话,控制台调用就可以成功。

@yunnysunny
Copy link
Author

https://github.com/X-Profiler/xtransit/blob/master/lib/handler.js#L34

看下进了这个 if 判断后这里的 options 和 stdout 输出了啥,正常不会有 parse 的问题

我在这行打印了,stdout 是空 stderr 也是空

@hyj1991
Copy link
Member

hyj1991 commented May 17, 2022

你可以在本机 dbeug 下这段逻辑,我试了下无法复现,没法帮你看这个问题。

@hyj1991
Copy link
Member

hyj1991 commented May 21, 2022

没有更多反馈先关闭了

@hyj1991 hyj1991 closed this as completed May 21, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
question Further information is requested
Projects
None yet
Development

No branches or pull requests

2 participants