标签归档:strace

作业控制与前台进程组

这篇文章是对之前的SIGTTIN信号量的疑惑?的解答,对于为何会有这种奇怪的用法,在另一篇shell下精确的定位一个命令 也介绍过了,这里想讨论的重点不在于怎么变通解决那个问题,而是导致SIGTTIN发生的机制是怎么引起的。我的同事对这个问题也产生了好奇,在stackoverflow上发帖,有人给出了解释,解答的人直接给出了bash的源码jobs.c里的initialize_job_control方法片段,指出SIGTTIN正是那里面的逻辑。不过如果你跟我一样对shell和linux系统调用都懂得很肤浅的话,这段代码并不容易懂,所以在这里更详细的解释一下这个问题的来龙去脉。

刚开始碰到这个问题的时候,通过strace看到了是SIGTTIN信号量所致,因为这个信号量默认的行为是让进程STOP(暂停),即通过ps观察到的状态为T。对于SIGTTIN信号量《Linux/UNIX系统编程手册》上是这么说的:

只有前台作业中的进程才能够从控制终端读取输入。这个限制条件避免了多个作业竞争读取终端输入。如果后台作业尝试从终端读取输入,就会接收到一个SIGTTIN信号。SIGTTIN信号的默认处理动作是停止作业。

但我们的脚本里并没有后台进程,那两个进程也没有读取终端,跟上面的解释对不上。也没有在网上搜到其它引发SIGTTIN信号的情况,在这里困惑了很久。不过凭直觉知道这个问题应该跟作业控制有关,在脚本里显式的开启作业控制,是能够正常运行的:

$ cat sleep.sh
#!/bin/bash
set -m
bash -ic 'sleep 3'
bash -ic 'sleep 2'

所以一定是在进程某个状态上的不一致导致的。上周末的时候阅读了一下strace的log,对出问题的脚本:

#!/bin/bash
bash -ic 'sleep 3'
bash -ic 'sleep 2'

使用strace -f -e verbose=all -t ./sleep.sh 2>log 得到更详细的日志

...
03:39:06 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f997f03ca10) = 9897
...
[pid  9897] 03:39:06 execve("/usr/bin/bash", ["bash", "-ic", "sleep 3"], [/* 30 vars */]) = 0
...
[pid  9897] 03:39:06 open("/dev/tty", O_RDWR|O_NONBLOCK) = 3
[pid  9897] 03:39:06 getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=4*1024}) = 0
[pid  9897] 03:39:06 fcntl(255, F_GETFD) = -1 EBADF (Bad file descriptor)
[pid  9897] 03:39:06 dup2(3, 255)       = 255
[pid  9897] 03:39:06 close(3)           = 0
[pid  9897] 03:39:06 ioctl(255, TIOCGPGRP, [9891]) = 0
[pid  9897] 03:39:06 setpgid(0, 9897)   = 0 //第一个子进程更改了它的进程组ID
...
03:39:09 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f997f03ca10) = 9922
...
[pid  9922] 03:39:09 execve("/usr/bin/bash", ["bash", "-ic", "sleep 2"], [/* 30 vars */]) = 0
...
[pid  9922] 03:39:09 access("/usr/bin/bash", R_OK) = 0
[pid  9922] 03:39:09 getpgrp()          = 9891
[pid  9922] 03:39:09 ioctl(2, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7ffd356e49c0) = -1 ENOTTY (Inappropriate ioctl for device)
[pid  9922] 03:39:09 open("/dev/tty", O_RDWR|O_NONBLOCK) = 3
[pid  9922] 03:39:09 getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=4*1024}) = 0
[pid  9922] 03:39:09 fcntl(255, F_GETFD) = -1 EBADF (Bad file descriptor)
[pid  9922] 03:39:09 dup2(3, 255)       = 255
[pid  9922] 03:39:09 close(3)           = 0
[pid  9922] 03:39:09 ioctl(255, TIOCGPGRP, [9897]) = 0
[pid  9922] 03:39:09 rt_sigaction(SIGTTIN, {SIG_DFL, [], SA_RESTORER, 0x7f912a22b650}, {SIG_IGN, [], SA_RESTORER, 0x7f912a22b650}, 8) = 0
[pid  9922] 03:39:09 kill(0, SIGTTIN)   = 0
[pid  9896] 03:39:09 <... wait4 resumed> 0x7ffc5b5e6800, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid  9922] 03:39:09 --- SIGTTIN {si_signo=SIGTTIN, si_code=SI_USER, si_pid=9922, si_uid=1000} ---
[pid  9896] 03:39:09 --- SIGTTIN {si_signo=SIGTTIN, si_code=SI_USER, si_pid=9922, si_uid=1000} ---
[pid  9922] 03:39:09 --- stopped by SIGTTIN ---
[pid  9896] 03:39:09 --- stopped by SIGTTIN ---

确认这个SIGTTIN信号是第二个bash -ic 'sleep 2'进程发出的,kill(0, SIGTTIN)表示它把这个信号发送到自己所在的进程组,整个进程组的进程都接收到这个信号,所以它和它的父进程sleep.sh都变成了stop状态。

脚本里两次执行的bash -ic子进程也都是shell,它们在初始化的时候会有作业控制的逻辑,结合jobs.cinitialize_job_control方法里的代码(shell初始化时调用到这里):

/* We can only have job control if we are interactive. */
if (interactive == 0)
{
  job_control = 0;
  original_pgrp = NO_PID;
  shell_tty = fileno (stderr);
}
else
{
  shell_tty = -1;

  /* If forced_interactive is set, we skip the normal check that stderr
    is attached to a tty, so we need to check here.  If it's not, we
    need to see whether we have a controlling tty by opening /dev/tty,
    since trying to use job control tty pgrp manipulations on a non-tty
    is going to fail. */ 
    // bash "-i" 参数会启用 forced_interactive
  if (forced_interactive && isatty (fileno (stderr)) == 0)
    shell_tty = open ("/dev/tty", O_RDWR|O_NONBLOCK);

  /* Get our controlling terminal.  If job_control is set, or
    interactive is set, then this is an interactive shell no
     matter where fd 2 is directed. */
   if (shell_tty == -1)
    shell_tty = dup (fileno (stderr));/* fd 2 */

  shell_tty = move_to_high_fd (shell_tty, 1, -1);

  /* Compensate for a bug in systems that compiled the BSD
 rlogind with DEBUG defined, like NeXT and Alliant. */
  if (shell_pgrp == 0)
{
  shell_pgrp = getpid ();
  setpgid (0, shell_pgrp);
  tcsetpgrp (shell_tty, shell_pgrp);
}

  while ((terminal_pgrp = tcgetpgrp (shell_tty)) != -1)
{
  if (shell_pgrp != terminal_pgrp)
    {
      SigHandler *ottin;

      ottin = set_signal_handler(SIGTTIN, SIG_DFL);
      kill (0, SIGTTIN); // 第二次执行bash -ic时触发了这里
      set_signal_handler (SIGTTIN, ottin);
      continue;
    }
  break;
}
if (terminal_pgrp == -1)
t_errno = errno;

  /* Make sure that we are using the new line discipline. */
  if (set_new_line_discipline (shell_tty) < 0)
{
  sys_error (_("initialize_job_control: line discipline"));
  job_control = 0;
}
  else
{
  original_pgrp = shell_pgrp;
  shell_pgrp = getpid ();

  // 第一次bash -ic 'sleep 3'触发了这里的 setpgid 修改了当前进程组
  if ((original_pgrp != shell_pgrp) && (setpgid (0, shell_pgrp) < 0))
    {
      sys_error (_("initialize_job_control: setpgid"));
      shell_pgrp = original_pgrp;
    }

  job_control = 1;

  /* If (and only if) we just set our process group to our pid,
     thereby becoming a process group leader, and the terminal
     is not in the same process group as our (new) process group,
     then set the terminal's process group to our (new) process
     group.  If that fails, set our process group back to what it
     was originally (so we can still read from the terminal) and
     turn off job control.  */
  if (shell_pgrp != original_pgrp && shell_pgrp != terminal_pgrp)
    {
      if (give_terminal_to (shell_pgrp, 0) < 0)
    {
      t_errno = errno;
      setpgid (0, original_pgrp);
      shell_pgrp = original_pgrp;
      job_control = 0;
    }
   }
...

关键点就在于shell_pgrpterminal_pgrp这两个变量,shell_pgrp是当前进程组,而terminal_pgrp是占用当前控制终端的进程所在的进程组(前台进程组),这些状态都是可以通过ps观察到的,可以跟踪一下:

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12413 12410 12410 12410    -1 S    ?        sshd: hongjiang@pts/0
12414 12413 12414 12414 12580 Ss   pts/0     \_ -bash
12579 12414 12579 12414 12580 S    pts/0         \_ /bin/bash ./sleep.sh
12580 12579 12580 12414 12580 S+   pts/0             \_ sleep 3

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12413 12410 12410 12410    -1 S    ?        sshd: hongjiang@pts/0
12414 12413 12414 12414 12414 Ss+  pts/0     \_ -bash
12579 12414 12579 12414 12414 T    pts/0         \_ /bin/bash ./sleep.sh
12607 12579 12579 12414 12414 T    pts/0             \_ bash -ic sleep 2

在第一次执行bash -ic 'sleep 3'的时候,sleep.sh父进程先clone出bash子进程(pid 12580),因为-i参数强制这个bash子进程用交互式运行,它会加载$HOME下的.bashrc等文件,这个过程可能会fork/clone出若干子进程(所以会看到第二次bash -ic sleep 2进程的ID跟第一次不是连续的),等这些配置文件加载完之后,它并不是fork/clone的形式执行sleep 3而是使用当前进程(12580)执行的sleep 3,这里很关键的信息是"PGID"和"TPGID"都是本身进程ID,而非父进程ID,跟第二次的状态不一样。

因为脚本默认是关闭作业控制的,本来每个子进程并不会设置为独立的进程组,比如下面这个脚本:

$ cat a.sh
#!/bin/bash
/usr/bin/sleep 10

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12668 12665 12665 12665    -1 S    ?        sshd: hongjiang@pts/2
12669 12668 12669 12669 12736 Ss   pts/2     \_ -bash
12736 12669 12736 12669 12736 S+   pts/2         \_ /bin/bash ./a.sh
12737 12736 12736 12669 12736 S+   pts/2             \_ /usr/bin/sleep 10

上面脚本执行时sleep子进程"PGID"和"TPGID"都是进程父进程a.sh的,并没有被设置为一个独立的进程组。

sleep.sh脚本里之所以会对子进程设置一个独立的进程组,是因为"-i"参数使得bash -ic 'sleep 3'在非交互式脚本里运行时进程被强制设置成了独立的进程组(见initializejobcontroll里的setpgid),同时"TPGID"这个表示前台进程组的状态也被改为了bash -ic 'sleep 3'的进程组ID。

那为什么在接下来的bash -ic 'sleep 2'子进程执行时却不像前面的那样呢?这正是最诡异的地方。它们所在的sleep.sh脚本是非交互式运行的,它本来预期脚本执行过程不应该产生与脚本进程组不一致的前台进程组,所以前台子进程组结束的时候,不会去更新"TPGID",可以用下面脚本来验证:

$ cat wait.sh
#!/bin/bash
bash -ic 'sleep 5'
sleep 4
sleep 3 &  #不让wait.sh进程立即退出
wait

上面wait.sh脚本里第一个子进程强制修改了"TPGID",子进程退出,以及后续再执行前台进程都不会去更新这个状态

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/0/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
13867 13864 13864 13864    -1 S    ?        sshd: hongjiang@pts/0
13868 13867 13868 13868 14138 Ss   pts/0     \_ -bash
14137 13868 14137 13868 14138 S    pts/0         \_ /bin/bash ./wait.sh
14138 14137 14138 13868 14138 S+   pts/0             \_ sleep 5

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/0/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
13867 13864 13864 13864    -1 S    ?        sshd: hongjiang@pts/0
13868 13867 13868 13868 14138 Ss   pts/0     \_ -bash
14137 13868 14137 13868 14138 S    pts/0         \_ /bin/bash ./wait.sh
14165 14137 14137 13868 14138 S    pts/0             \_ sleep 4

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/0/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
13867 13864 13864 13864    -1 S    ?        sshd: hongjiang@pts/0
13868 13867 13868 13868 14138 Ss   pts/0     \_ -bash
14137 13868 14137 13868 14138 S    pts/0         \_ /bin/bash ./wait.sh
14168 14137 14137 13868 14138 S    pts/0             \_ sleep 3

回到sleep.sh脚本里,第二行bash -ic 'sleep 2'子进程初始化时,"TPGID"仍是上个进程bash -ic 'sleep 3'修改过的值。而bash -ic 'sleep 2'子进程也因为"-i"参数让自己以交互式运行,但是在还没有执行到setpgid之前,就先触发了SIGTTIN的逻辑:

if (shell_pgrp != terminal_pgrp)
{
    SigHandler *ottin;

    ottin = set_signal_handler(SIGTTIN, SIG_DFL);
    kill (0, SIGTTIN);
    set_signal_handler (SIGTTIN, ottin);
    continue;
}

因为这段代码会认为终端被其他前台进程占用,对当前进程组发出SIGTTIN信号。在这个场景里,这恰好是一种误会!

当我们显式的对sleep.sh脚本设置开启作业控制时:

$ cat sleep.sh
#!/bin/bash
set -m
bash -ic 'sleep 3'
bash -ic 'sleep 2'

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12668 12665 12665 12665    -1 S    ?        sshd: hongjiang@pts/2
12669 12668 12669 12669 12874 Ss   pts/2     \_ -bash
12873 12669 12873 12669 12874 S    pts/2         \_ /bin/bash ./sleep.sh
12874 12873 12874 12669 12874 S+   pts/2             \_ sleep 3

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12668 12665 12665 12665    -1 S    ?        sshd: hongjiang@pts/2
12669 12668 12669 12669 12901 Ss   pts/2     \_ -bash
12873 12669 12873 12669 12901 S    pts/2         \_ /bin/bash ./sleep.sh
12901 12873 12901 12669 12901 S+   pts/2             \_ sleep 2

它对每个子进程都设置为独立的进程组,并在每个进程(前台)结束的时候更新"TPGID"为父进程组ID,避免了initialize_job_controll里发送SIGTTIN的逻辑。

有很多shell的问题都是跟作业控制相关的,另一个例子参考tomcat进程意外退出的问题分析;作业控制可以玩出很多高阶花样,但它也大大增加了shell的复杂度,这个例子是一个典型的反面教材,最好不要在非交互式脚本里调用bash -ic来执行命令。

jstack不可用的原因

上午遇到的jstack没有输出的问题,印象里在阿里前几年也遇到过,不记得细节了;晚上查了一下,是jdk1.6的某些特定版本存在的bug,见这篇blog,简单的说就是本来hsperfdata_$user 这个目录一直约定是在系统的临时目录下的,对linux来说是”/tmp”

用 strace 来看一下正常版本启动jvm,hsperfdata_$user目录不受java.io.tmpdir变量影响

$ strace -ff -e trace=file  java -Djava.io.tmpdir=/data/test -version 2>&1 | perl -ne 's/^[^"]+"(([^\\"]|\\[\\"nt])*)".*/$1/ && print'  | grep hsperfdata

/tmp/hsperfdata_hongjiang
/tmp/hsperfdata_hongjiang/17019

而在 jdk1.6.0_21到24引入了bug,使用了jvm的环境变量-Djava.io.tmpdir做为了hsperfdata_$user的路径,正好一些应用比如tomcat是对这个变量设置了自己的路径的,比如”/server/tomcat/temp”,存在bug的这些版本把hsperfdata_$user目录也放到tomcat环境变量指定的目录下了,结果 jps, jstack, 之类工具都不能找到目标了。根据bug报告里给出的一种变通方式,在运行jstack时设置-J-Djava.io.tmpdir=$CATALINA_HOME/temp 也并未能工作。对于这个问题最佳的处理方式还是升级jdk版本。

补充:

虽然对jstack设置变量并不工作,但发现对jinfo设置该变量是有效的,比如:jinfo -J-Djava.io.tmpdir=/server/tomcat/temp -sysprops $pid 在jdk1.6.0_24下是可以工作的。

通过strace查看一个进程的标准输出内容

线上某个业务java进程出了一些麻烦,去诊断的时候发现jstack无法输出,可能是jdk或os版本的问题。这时还可以尝试一下kill -3,它默认会输出到进程的标准输出。如果不幸这个进程的标准输出被重定向到了 /dev/null 或者重定向到某个文件,但却因为很多其他日志也在大量的输出,导致日志文件过大,要从中找出线程栈相关的日志,还要耗点时间;这个时候,可以通过strace来跟踪一个进程的标准输入。

strace输出的信息需要一些处理,可以通过管道与其他命令组合(通过-o参数或-ff参数)

这里 -o 参数后边是一个字符串表示输出文件,如果字符串开头是一个"|"会被strace识别为管道

$ strace -f -e trace=write -e verbose=none -e write=1,2 -q -p $pid -o "| grep '^ |' | cut -c11-60 | sed -e 's/ //g' | xxd -r -p"

或者 -ff 参数,用管道与其他命令组合,注意strace的错误输出也要重定向

$ strace -ff -e trace=write -e write=1,2 -s 1024 -q -p $pid 2>&1 | cut -c11-60 | sed -e 's/ //g' | xxd -r -p

不过这两种方式都遇到一个问题,因为buffer的问题导致管道后边的命令没能完全处理strace跟踪到的数据(要等到后续的数据塞满buffer),有点像grep需要--line-buffer解决缓冲区问题,但不知道这里有什么方式,尝试过stdbuf也没有解决。最后只能分两步,先把strace的内容输出到文件,然后再对内容解析:

$ strace -f -e trace=write -e write=1,2 -q -p $pid  -o /tmp/slog

$ grep " |" /tmp/slog | cut -c11-60 | sed -e 's/ //g' | xxd -r -p

使用strace定位jvm退出的原因范围

今天遇到的一个tomcat启动过程中jvm退出的问题,不是jvm crash的情况,用户日志配置的不正确导致一些信息没有展现出来,只看到pandora执行了shutdownhook的信息。这可能是启动时的逻辑有触发System.exit,或被系统或人为kill掉了。

根据以往的经验,排除了oom killer或ulimit -t设置不当导致被内核给kill掉的情况,OS级别的signal通常不留机会给jvm执行shutdownhook的。如此一来singal的范围应该就是SIGTERM, SIGINT, SIGHUP这3种(参考这里)。

虽然singal范围缩小,但依然不能确定是因为代码里调用了System.exit还是人为(或被其他进程)kill引起的。直接上大招用systemtap需要安装kernal debuginfo,没有权限的话,还要找到对应的人去做;如果现象较容易重现的话,可以先通过strace命令进一步缩小问题的范围,究竟是因为jvm内部执行了System.exit还是外界的kill引起的。

这里通过启动一个scala的repl来模拟java进程,通过strace attach到jvm进程上,然后观察,如果是外界的kill所致,可以看到下面的信息:

$ sudo strace -p 1947
Process 1947 attached - interrupt to quit
futex(0x7fb7635959d0, FUTEX_WAIT, 1948, NULL) = ? ERESTARTSYS (To be restarted)
--- SIGTERM (Terminated) @ 0 (0) ---
futex(0x7fb762762360, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigreturn(0x7fb762762360)            = 202
futex(0x7fb7635959d0, FUTEX_WAIT, 1948, NULLPANIC: attached pid 1947 exited with 143
 <unfinished ... exit status 143>

里面的关键信息是SIGTERMexit status 143(即SIGTERM的code)

如果是kill -2或ctrl-c终止repl,可以看到有关SIGINT的信息

$ sudo strace -p 1813
Process 1813 attached - interrupt to quit
futex(0x7fb24d15a9d0, FUTEX_WAIT, 1814, NULL) = ? ERESTARTSYS (To be restarted)
--- SIGINT (Interrupt) @ 0 (0) ---
futex(0x7fb24c327360, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigreturn(0x7fb24c327360)            = 202
futex(0x7fb24d15a9d0, FUTEX_WAIT, 1814, NULLPANIC: attached pid 1813 exited with 130
 <unfinished ... exit status 130>

如果是jvm自身执行了System.exit比如:

scala> System.exit(0)

那么在跟踪的信息里,是看不到signal的:

$ sudo strace -p 2131
Process 2131 attached - interrupt to quit
futex(0x7fc14adb49d0, FUTEX_WAIT, 2132, NULLPANIC: attached pid 2131 exited with 0
 <unfinished ... exit status 0>

至此我们可以判断出到底是外部还是内部引起的了,如果是内部就不必麻烦Systemtap了,可以从源码去找。