在 Linux 上通过 SSH 运行多线程 Perl 脚本的问题

Question

如果我通过 SSH 远程运行以下简单 Perl 脚本，我将无法理解它的行为。

use strict;
use warnings;
use threads;
use threads::shared;
use POSIX;

my $print_mutex : shared;

################################################################################

sub _print($)
{
    my $str = shift;
    lock($print_mutex);
    my $id = threads->tid();
    my $time = strftime('%H:%M:%S', localtime time);
    print "$time [$id] $str";
    return;
}

################################################################################

sub run()
{
    for my $i (1 .. 3)
      {
        _print("Begin $i\n");
        sleep 1;
        _print("End $i\n");
      }
    return threads->tid();
}

################################################################################

_print "Starting test.\n";
my @threads;
for my $thr_num (1 .. 2)
  {
    my $thr = threads->create('run');
    push @threads, $thr;
    _print "Thread created.\n";
  }
foreach (@threads)
  {
    my $id = $_->join;
    _print "Thread '$id' finished.\n";
  }
_print "Test finished.\n";

################################################################################

当我在 Linux 机器上使用 Perl-5.10.0 正常运行它时，我得到了预期的结果：

$ perl /tmp/a.pl
14:25:54 [0] Starting test.
14:25:54 [0] Thread created.
14:25:54 [1] Begin 1
14:25:54 [0] Thread created.
14:25:54 [2] Begin 1
14:25:55 [1] End 1
14:25:55 [1] Begin 2
14:25:55 [2] End 1
14:25:55 [2] Begin 2
14:25:56 [1] End 2
14:25:56 [1] Begin 3
14:25:56 [2] End 2
14:25:56 [2] Begin 3
14:25:57 [1] End 3
14:25:57 [0] Thread '1' finished.
14:25:57 [2] End 3
14:25:57 [0] Thread '2' finished.
14:25:57 [0] Test finished.
$

然而，当我通过 SSH 运行它时（在同一本地主机上，但这并不重要），我得到了非常奇怪的结果（仔细查看时间戳和线程 ID）：

$ ssh localhost 'perl /tmp/a.pl'
14:26:11 [0] Starting test.
14:26:11 [0] Thread created.
14:26:11 [1] Begin 1
14:26:12 [1] End 1
14:26:12 [1] Begin 2
14:26:13 [1] End 2
14:26:13 [1] Begin 3
14:26:14 [1] End 3
14:26:11 [2] Begin 1
14:26:12 [2] End 1
14:26:12 [2] Begin 2
14:26:13 [2] End 2
14:26:13 [2] Begin 3
14:26:14 [2] End 3
14:26:11 [0] Thread created.
14:26:14 [0] Thread '1' finished.
14:26:14 [0] Thread '2' finished.
14:26:14 [0] Test finished.
$

我从未在单线程 Perl 脚本中看到过这种情况，并且我注意到在创建第一个线程后我就开始看到 I/O 问题。

我能够在 Windows 上使用最新的 Perl-5.12 重现该问题，因此我认为该问题不是 Perl/OS 特定的。

有人可以解释一下这里出了什么问题吗？

Answer 1

我自己能够重现这一点。然而，当通过 ssh 从 shell 运行它时，我得到了预期的行为。那么有什么区别呢？一个伪终端！

试试这个：

ssh -t localhost 'perl /tmp/a.pl'

Answer 2

事实上，看起来每个 Perl 线程都有它自己的输出缓冲区。
我已将输出重定向到文件（与通过 SSH 运行脚本相同，因为它只是禁用行缓冲）并在 strace 下运行脚本：

$ strace -fF -tt -s200 bash -c "perl /tmp/a.pl > OUT" 2>&1 | grep write
[pid   359] 12:12:24.674142 write(1, "12:12:24 [0] Starting test.\n"..., 28) = 28
[pid   359] 12:12:24.687319 write(1, "12:12:24 [0] Thread created.\n"..., 29) = 29
[pid   360] 12:12:27.693225 write(1, "12:12:24 [1] Begin 1\n12:12:25 [1] End 1\n12:12:25 [1] Begin 2\n12:12:26 [1] End 2\n12:12:26 [1] Begin 3\n12:12:27 [1] End 3\n"..., 120) = 120
[pid   361] 12:12:27.706137 write(1, "12:12:24 [2] Begin 1\n12:12:25 [2] End 1\n12:12:25 [2] Begin 2\n12:12:26 [2] End 2\n12:12:26 [2] Begin 3\n12:12:27 [2] End 3\n"..., 120) = 120
[pid   359] 12:12:27.711343 write(1, "12:12:24 [0] Thread created.\n12:12:27 [0] Thread '1' finished.\n12:12:27 [0] Thread '2' finished.\n12:12:27 [0] Test finished.\n"..., 125) = 125
$ 

很明显，每个线程都将所有数据放入线程本地缓冲区，然后（在本示例中，就在线程终止之前）在该缓冲区上调用“写入”系统调用。
恕我直言，线程本地输出缓冲区是非常坏主意，因为即使人们显式序列化“打印”调用，也会得到令人困惑的结果。

我找到的解决方案是使用显式序列化并在 STDOUT 上启用自动刷新，以便线程本地缓冲区始终为空。