【问题标题】:Problem with multi-threaded Perl script run via SSH on Linux在 Linux 上通过 SSH 运行多线程 Perl 脚本的问题
【发布时间】:2011-05-03 10:47:41
【问题描述】:

如果我通过 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";

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

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

$ perl /tmp/a.pl 14:25:54 [0] 开始测试。 14:25:54 [0] 线程已创建。 14:25:54 [1] 开始 1 14:25:54 [0] 线程已创建。 14:25:54 [2] 开始 1 14:25:55 [1] 结束 1 14:25:55 [1] 开始 2 14:25:55 [2] 结束 1 14:25:55 [2] 开始 2 14:25:56 [1] 结束 2 14:25:56 [1] 开始 3 14:25:56 [2] 结束 2 14:25:56 [2] 开始 3 14:25:57 [1] 结束 3 14:25:57 [0] 线程 '1' 完成。 14:25:57 [2] 结束 3 14:25:57 [0] 线程 '2' 完成。 14:25:57 [0] 测试完成。 $

但是,当我通过 SSH(在同一本地主机上,但没关系)运行它时,我得到了非常奇怪的结果(仔细查看时间戳和线程 ID):

$ ssh localhost 'perl /tmp/a.pl' 14:26:11 [0] 开始测试。 14:26:11 [0] 线程已创建。 14:26:11 [1] 开始 1 14:26:12 [1] 结束 1 14:26:12 [1] 开始 2 14:26:13 [1] 结束 2 14:26:13 [1] 开始 3 14:26:14 [1] 结束 3 14:26:11 [2] 开始 1 14:26:12 [2] 结束 1 14:26:12 [2] 开始 2 14:26:13 [2] 结束 2 14:26:13 [2] 开始 3 14:26:14 [2] 结束 3 14:26:11 [0] 线程已创建。 14:26:14 [0] 线程 '1' 完成。 14:26:14 [0] 线程“2”完成。 14:26:14 [0] 测试完成。 $

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

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

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

【问题讨论】:

    标签: multithreading perl ssh io


    【解决方案1】:

    我能够自己复制这个。但是,当通过 ssh 从 shell 运行它时,我得到了预期的行为。那么有什么区别呢?一个伪终端!

    试试这个:

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

    【讨论】:

    • 嗯..在这种情况下似乎启用了行缓冲模式。如果您删除所有“\n”,那么即使使用“ssh -t”运行,您也会看到相同的行为。
    • 我最初的想法是缓冲问题,我正要建议添加\n,但我再次查看它们已经在那里。我想你也可以尝试关闭 IO 缓冲,但它默认打开是有原因的......
    • 我认为这与缓冲模式无关。无论使用何种缓冲模式,输出中的时间都必须单调增加(但不会)。缓冲模式可能只影响调用 write 系统调用的时间和次数。我说的对吗?
    • 有人告诉我,在 Perl 中,每个线程都有线程本地输出缓冲区(不是一个全局输出缓冲区)。如果这是真的,那么写入顺序不会全局保留。虽然我还没有在 perldoc 中找到关于线程本地缓冲区的任何信息。
    • 那么...为什么不直接使用 ssh -t 呢?
    【解决方案2】:

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

    $ strace -fF -tt -s200 bash -c "p​​erl /tmp/a.pl > OUT" 2>&1 | grep 写 [pid 359] 12:12:24.674142 write(1, "12:12:24 [0] 开始测试。\n"..., 28) = 28 [pid 359] 12:12:24.687319 write(1, "12:12:24 [0] 线程创建。\n"..., 29) = 29 [pid 360] 12:12:27.693225 write(1, "12:12:24 [1] 开始 1\n12:12:25 [1] 结束 1\n12:12:25 [1] 开始 2\n12:12 :26 [1] 结束 2\n12:12:26 [1] 开始 3\n12:12:27 [1] 结束 3\n"..., 120) = 120 [pid 361] 12:12:27.706137 write(1, "12:12:24 [2] 开始 1\n12:12:25 [2] 结束 1\n12:12:25 [2] 开始 2\n12:12 :26 [2] 结束 2\n12:12:26 [2] 开始 3\n12:12:27 [2] 结束 3\n"..., 120) = 120 [pid 359] 12:12:27.711343 write(1, "12:12:24 [0] 线程已创建。\n12:12:27 [0] 线程 '1' 已完成。\n12:12:27 [0] 线程'2' 完成。\n12:12:27 [0] 测试完成。\n"..., 125) = 125 $

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

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

    【讨论】:

      猜你喜欢
      • 1970-01-01
      • 2014-08-27
      • 1970-01-01
      • 1970-01-01
      • 1970-01-01
      • 2014-12-29
      • 1970-01-01
      • 1970-01-01
      • 2016-08-16
      相关资源
      最近更新 更多