Проблема с многопоточным скриптом Perl, запущенным через SSH в Linux

Question

Я не могу понять поведение следующего простого сценария Perl в случае, если я запускаю его удаленно через SSH.

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 (на том же локальном хосте, но это не имеет значения), я получаю очень странные результаты (внимательно присваивайте метки времени и идентификаторы потоков):

$ 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, и я заметил, что я начал видеть проблему с вводом / выводом сразу после создания первого потока.

Я смогвоспроизвести проблему с последней версией Perl-5.12 для Windows, поэтому я не думаю, что проблема связана с Perl / OS.

Может кто-нибудь объяснить, что здесь не так?

Answer 1

Действительно, похоже, что каждый поток 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
$ 

Становится ясно, чтокаждый поток помещает все данные в локальный буфер потока и только затем (в этом примере непосредственно перед завершением потока) вызывает системный вызов write для этого буфера.ИМХО, локальные выходные буферы - это очень плохая идея, потому что люди получают запутанные результаты, даже если вы явно указываете сериализацию вызовов "print".

Я нашел решение использовать явную сериализацию ивключите автозапуск на STDOUT, чтобы локальные буферы потока всегда были пустыми.

Answer 2

Я смог воспроизвести это сам.Однако при запуске из оболочки через ssh я получил ожидаемое поведение.Так в чем же разница?Псевдо-терминал!

Попробуйте:

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