ssh 执行远程命令的性能问题

今天遇到一个远程调用时执行效率低下的问题。具体症状是相同的命令在 bash 命令行下执行时,速度较快,大约 0.5s 左右返回结果。但是通过 web 页面调用时,速度很慢,需要 63.8s 左右才能返回结果,经多次测试发现,很稳定的比正常速度要慢 63s 左右。测试页面如下:

<?php
$start = microtime(true);
$command = system("ssh -t 10.3.50.2 /bin/date");
$end = microtime(true);
$spend = round($end - $start, 1);
echo "total $spend s.";
?>

首先分析一下思路,在命令行下正确,但 web 下异常,有可能是 apache 在某些情况下导致超时所致,先搜索了一遍 httpd.conf 以及 php.ini 中的配置,将其中配置为 30s、60s 的一些超时选项修改为 5s,执行后发现结果没啥变化。

网上根据 ssh 远程执行命令 等关键字搜索,找到的也是一堆不相干的结果。比如 usedns、GSSAPIAuthentication 等选项关闭这是提到最多的,可跟我的情况都不太一样,分别测试后也均无效。

打开 sshd 的日志,将其设置为 debug 级别,通过对比命令行下与 web 调用下的差异,发现有可能是 env 的问题。详见以下内容:
web 下调用日志(异常):

Jun 14 14:37:59 db sshd[69750]: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
Jun 14 14:37:59 db sshd[69750]: debug1: input_session_request
Jun 14 14:37:59 db sshd[69750]: debug1: channel 0: new [server-session]
Jun 14 14:37:59 db sshd[69750]: debug2: session_new: allocate (allocated 0 max 10)
Jun 14 14:37:59 db sshd[69750]: debug1: session_new: session 0
Jun 14 14:37:59 db sshd[69750]: debug1: session_open: channel 0
Jun 14 14:37:59 db sshd[69750]: debug1: session_open: session 0: link with channel 0
Jun 14 14:37:59 db sshd[69750]: debug1: server_input_channel_open: confirm session
Jun 14 14:37:59 db sshd[69750]: debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
Jun 14 14:37:59 db sshd[69750]: debug1: server_input_channel_req: channel 0 request env reply 0
Jun 14 14:37:59 db sshd[69750]: debug1: session_by_channel: session 0 channel 0
Jun 14 14:37:59 db sshd[69750]: debug1: session_input_channel_req: session 0 req env
Jun 14 14:37:59 db sshd[69750]: debug2: Setting env 0: LANG=C
Jun 14 14:37:59 db sshd[69750]: debug1: server_input_channel_req: channel 0 request exec reply 1
Jun 14 14:37:59 db sshd[69750]: debug1: session_by_channel: session 0 channel 0
Jun 14 14:37:59 db sshd[69750]: debug1: session_input_channel_req: session 0 req exec
Jun 14 14:37:59 db sshd[69747]: debug2: session_new: allocate (allocated 0 max 10)
Jun 14 14:37:59 db sshd[69747]: debug1: session_new: session 0
Jun 14 14:37:59 db sshd[69750]: debug2: fd 3 setting TCP_NODELAY
Jun 14 14:37:59 db sshd[69750]: debug2: fd 9 setting O_NONBLOCK
Jun 14 14:37:59 db sshd[69750]: debug2: fd 8 setting O_NONBLOCK
Jun 14 14:37:59 db sshd[69750]: debug2: fd 11 setting O_NONBLOCK
Jun 14 14:37:59 db sshd[69750]: debug2: channel 0: rcvd eof
Jun 14 14:37:59 db sshd[69750]: debug2: channel 0: output open -> drain
Jun 14 14:37:59 db sshd[69750]: debug2: channel 0: obuf empty
Jun 14 14:37:59 db sshd[69750]: debug2: channel 0: close_write
Jun 14 14:37:59 db sshd[69750]: debug2: channel 0: output drain -> closed
Jun 14 14:37:59 db sshd[69750]: debug2: notify_done: reading
Jun 14 14:37:59 db sshd[69750]: debug1: Received SIGCHLD.
Jun 14 14:37:59 db sshd[69750]: debug1: session_by_pid: pid 69751
Jun 14 14:37:59 db sshd[69750]: debug1: session_exit_message: session 0 channel 0 pid 69751
Jun 14 14:37:59 db sshd[69750]: debug2: channel 0: request exit-status confirm 0
Jun 14 14:37:59 db sshd[69750]: debug1: session_exit_message: release channel 0
Jun 14 14:37:59 db sshd[69750]: debug2: channel 0: read -1 from efd 11
Jun 14 14:37:59 db sshd[69750]: debug2: channel 0: closing read-efd 11
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: read<=0 rfd 9 len 0
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: read failed
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: close_read
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: input open -> drain
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: ibuf empty
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: send eof
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: input drain -> closed
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: send close
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: rcvd close
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: is dead
Jun 14 14:39:02 db sshd[69750]: debug2: channel 0: gc: notify user

命令行下调用日志(正常):

Jun 14 14:40:24 db sshd[69807]: debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
Jun 14 14:40:24 db sshd[69807]: debug1: input_session_request
Jun 14 14:40:24 db sshd[69807]: debug1: channel 0: new [server-session]
Jun 14 14:40:24 db sshd[69807]: debug2: session_new: allocate (allocated 0 max 10)
Jun 14 14:40:24 db sshd[69807]: debug1: session_new: session 0
Jun 14 14:40:24 db sshd[69807]: debug1: session_open: channel 0
Jun 14 14:40:24 db sshd[69807]: debug1: session_open: session 0: link with channel 0
Jun 14 14:40:24 db sshd[69807]: debug1: server_input_channel_open: confirm session
Jun 14 14:40:24 db sshd[69807]: debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
Jun 14 14:40:24 db sshd[69807]: debug1: server_input_channel_req: channel 0 request pty-req reply 1
Jun 14 14:40:24 db sshd[69807]: debug1: session_by_channel: session 0 channel 0
Jun 14 14:40:24 db sshd[69807]: debug1: session_input_channel_req: session 0 req pty-req
Jun 14 14:40:24 db sshd[69807]: debug1: Allocating pty.
Jun 14 14:40:24 db sshd[69804]: debug2: session_new: allocate (allocated 0 max 10)
Jun 14 14:40:24 db sshd[69804]: debug1: session_new: session 0
Jun 14 14:40:24 db sshd[69807]: debug1: session_pty_req: session 0 alloc /dev/pts/3
Jun 14 14:40:24 db sshd[69807]: debug1: server_input_channel_req: channel 0 request env reply 0
Jun 14 14:40:24 db sshd[69807]: debug1: session_by_channel: session 0 channel 0
Jun 14 14:40:24 db sshd[69807]: debug1: session_input_channel_req: session 0 req env
Jun 14 14:40:24 db sshd[69807]: debug2: Setting env 0: LANG=en_US.UTF-8
Jun 14 14:40:24 db sshd[69807]: debug1: server_input_channel_req: channel 0 request exec reply 1
Jun 14 14:40:24 db sshd[69807]: debug1: session_by_channel: session 0 channel 0
Jun 14 14:40:24 db sshd[69807]: debug1: session_input_channel_req: session 0 req exec
Jun 14 14:40:24 db sshd[69804]: debug2: session_new: allocate (allocated 1 max 10)
Jun 14 14:40:24 db sshd[69804]: debug1: session_new: session 1
Jun 14 14:40:24 db sshd[69807]: debug2: fd 3 setting TCP_NODELAY
Jun 14 14:40:24 db sshd[69807]: debug2: channel 0: rfd 9 isatty
Jun 14 14:40:24 db sshd[69807]: debug2: fd 9 setting O_NONBLOCK
Jun 14 14:40:24 db sshd[69808]: debug1: Setting controlling tty using TIOCSCTTY.
Jun 14 14:40:25 db sshd[69807]: debug1: Received SIGCHLD.
Jun 14 14:40:25 db sshd[69807]: debug1: session_by_pid: pid 69808
Jun 14 14:40:25 db sshd[69807]: debug1: session_exit_message: session 0 channel 0 pid 69808
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: request exit-status confirm 0
Jun 14 14:40:25 db sshd[69807]: debug1: session_exit_message: release channel 0
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: write failed
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: close_write
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: send eow
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: output open -> closed
Jun 14 14:40:25 db sshd[69807]: debug2: notify_done: reading
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: read<=0 rfd 9 len -1
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: read failed
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: close_read
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: input open -> drain
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: ibuf empty
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: send eof
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: input drain -> closed
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: send close
Jun 14 14:40:25 db sshd[69804]: debug1: session_by_tty: session 0 tty /dev/pts/3
Jun 14 14:40:25 db sshd[69804]: debug1: session_pty_cleanup: session 0 release /dev/pts/3
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: rcvd close
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: is dead
Jun 14 14:40:25 db sshd[69807]: debug2: channel 0: gc: notify user

在撞了无数次墙也未找到好的解决方案后,决定把重心转移到 ssh 上面,从头查看 ssh 的命令行参数,终于看到其中有这样一段提示信息,多个 -t 选项强制 tty 分配:

-t      Force pseudo-tty allocation.  This can be used to execute arbitrary screen-based programs on a remote machine, which can be very useful, e.g. when implementing menu services.  Multiple -t options force tty allocation, even if ssh has no local tty.

测试后发现,加入两个 -t 果然在 web 下能够快速的获得返回结果,问题解决。最终的执行命令修改如下:

$command = system("ssh -t -t 10.3.50.2 /bin/date");

1 thought on “ssh 执行远程命令的性能问题

  1. nowo 文章作者

    今天发现另一个很诡异的现象,就是如果远程要运行的命令是放在后台执行的话,会导致退出,哪怕用 nohup 命令都没用。最终经过各种测试,得出如下结论:
    如果远程命令要在前台运行,需要使用 ssh -t -t 的参数在 php 页面下调用。
    如果远程命令要在后台运行,需要使用 ssh 的参数在 php 页面下调用。不能使用 -t 的参数,一个都不可以。

    回复

发表评论

电子邮件地址不会被公开。 必填项已用*标注