Re^4: threads on Windows

Sorry, this is a bit long, but this is the evidence on which I based my earlier remarks. If I have misinterpretted the evidence, then I shall be pleased to learn from my mistakes.

Further experiment shows that the effect I observed is associated only with <> input from the console -- following these remarks by BrowserUk.

I added stuff to the code to try to see what the exact sequence of operations was. Here's the code complete with instrumentation:

use strict;
use warnings;

use threads;
use threads::shared ;
use Thread::Queue;

#---------------------------------------------------------------------
+-------------------
# Options

my $YIELD       = 0 ;     # yield after async
my $CLOSE_STDIN = 0 ;     # close STDIN after dispatching Terminal Wat
+cher
my $INPUT_FILE  = 0 ;     # read from "file" not from STDIN

foreach my $arg (@ARGV) {
  if    ($arg =~ m/^y/i) { $YIELD        = 1 ; }
  elsif ($arg =~ m/^c/i) { $CLOSE_STDIN  = 1 ; }
  elsif ($arg =~ m/^f/i) { $INPUT_FILE   = 1 ; }
  else                   { die "don't recognise $arg" ; } ;
} ;

#---------------------------------------------------------------------
+-------------------
# Instrumentation

use IO::Handle ;

use Time::HiRes qw(time) ;
my $START = time() ;

my @trace : shared = () ;

sub trace {
  my ($s) = @_ ;

  my $when = time() - $START ;
  $s =~ s/\n/\\n/g ;

  { lock(@trace) ;

    push @trace, sprintf("%12.6f: (%2d) '%s'\n", $when, threads->tid()
+, $s) ;
  } ;
} ;

sub stdin_state {
  my ($tag) = @_ ;

  my $state = "STDIN is: " .(defined(fileno(STDIN)) ? 'open' : 'closed
+'). " $tag" ;

  print "$state\n" ;
  trace("$state") ;
} ;

my $IN = "fred\n"
        ."bill\n"
        ."john\n"
        ."mary\n"
        ."quit\n" ;

if ($INPUT_FILE) {
  close STDIN ;
  open STDIN, "<", \$IN   or die "failed to reopen STDIN" ;
} ;

#---------------------------------------------------------------------
+-------------------
# The instrumented code

# Create terminal watcher

print "Create terminal watcher...\n";
my $Q_stdin = Thread::Queue->new;
async {
  trace("Terminal Watcher started") ;
  while (1) {
    trace("Waiting for STDIN") ;
    last if !defined($_ = <STDIN>) ;
    trace("Input: '$_'") ;
    $Q_stdin->enqueue($_) ;
  } ;
  trace("Terminal Watcher terminating") ;
}->detach;

threads->yield() if $YIELD ;

stdin_state("after Terminal Watcher dispatched") ;

if ($CLOSE_STDIN) {
  close STDIN ;
  stdin_state("after close") ;
} ;

my $Q_found = Thread::Queue->new;

my $cmd;
print "Awaiting commands...\n";
trace("Entering MAIN_LOOP") ;

MAIN_LOOP: while (not defined $cmd or $cmd !~ /^q/i) {
  trace("Top of MAIN_LOOP") ;
  sleep(1); # Reduce load

  # Process commands
  $cmd = $Q_stdin->dequeue_nb;

  if (defined $cmd) {
    trace("Dequeued '$cmd'") ;
    chomp $cmd;
    if ($cmd =~ /^q/i) {
      trace("'QUIT' command") ;
      print "Resolving open threads\n";
    }
    else {
      trace("About to start child thread") ;
      async {
        trace("Child started") ;
        $Q_found->enqueue( $cmd ) ;
        trace("Child enqueued '$cmd' & terminating") ;
      }->detach;

      threads->yield() if $YIELD ;
      trace("Dispatched child thread") ;
    }
  }
  else {
    trace("Nothing to dequeue") ;
  } ;

  # Print announcements
  while (defined(my $output = $Q_found->dequeue_nb)) {
    trace("Output: '$output'") ;
    print ">$output\n";
  }
}

trace("Left MAIN_LOOP") ;

#---------------------------------------------------------------------
+---------

print STDERR "-- with Yield after async\n"    if $YIELD ;
print STDERR "-- with Close STDIN\n"          if $CLOSE_STDIN ;
print STDERR "-- with Input from File"        if $INPUT_FILE ; 

print STDERR sort @trace ;
[download]

I tried to disturb the original code as little as possible.

Running this on my uni-processor, Windows XP, Perl 5.10.0, I get:

Z:\>perl threads.pl
Create terminal watcher...
STDIN is: open after Terminal Watcher dispatched
Awaiting commands...
fred
bill
john
>fred
mary
>bill
quit
>john
Resolving open threads
>mary

...so the instrumented code is doing what the original code did.

Looking at the trace, I see:

    0.010775: ( 0) 'STDIN is: open after Terminal Watcher dispatched'
    0.011655: ( 0) 'Entering MAIN_LOOP'
    0.011695: ( 0) 'Top of MAIN_LOOP'
    0.011784: ( 1) 'Terminal Watcher started'
    0.011820: ( 1) 'Waiting for STDIN'
    1.021469: ( 0) 'Nothing to dequeue'
    1.021611: ( 0) 'Top of MAIN_LOOP'
    2.022909: ( 0) 'Nothing to dequeue'
    2.023037: ( 0) 'Top of MAIN_LOOP'
    2.703888: ( 1) 'Input: 'fred\n''
    2.704107: ( 1) 'Waiting for STDIN'
    3.024349: ( 0) 'Dequeued 'fred\n''
    3.024471: ( 0) 'About to start child thread'         ###
   14.330606: ( 0) 'Dispatched child thread'
   14.330606: ( 1) 'Input: 'bill\n''
   14.330606: ( 2) 'Child started'
   14.330741: ( 2) 'Child enqueued 'fred' & terminating'
   14.330745: ( 1) 'Waiting for STDIN'
   14.330765: ( 0) 'Top of MAIN_LOOP'
   15.332046: ( 0) 'Dequeued 'bill\n''
   15.332174: ( 0) 'About to start child thread'
   17.485142: ( 0) 'Dispatched child thread'
   17.485142: ( 1) 'Input: 'john\n''
   17.485142: ( 3) 'Child started'
   17.485277: ( 0) 'Output: 'fred''
   17.485289: ( 3) 'Child enqueued 'bill' & terminating'
   17.485527: ( 1) 'Waiting for STDIN'
   17.485623: ( 0) 'Top of MAIN_LOOP'
   18.486582: ( 0) 'Dequeued 'john\n''
   18.486729: ( 0) 'About to start child thread'
   19.648253: ( 0) 'Dispatched child thread'
   19.648253: ( 1) 'Input: 'mary\n''
   19.648253: ( 4) 'Child started'
   19.648385: ( 4) 'Child enqueued 'john' & terminating'
   19.648389: ( 1) 'Waiting for STDIN'
   19.648404: ( 0) 'Output: 'bill''
   19.648753: ( 0) 'Top of MAIN_LOOP'
   20.649693: ( 0) 'Dequeued 'mary\n''
   20.649822: ( 0) 'About to start child thread'
   21.400773: ( 0) 'Dispatched child thread'
   21.400773: ( 1) 'Input: 'quit\n''
   21.400773: ( 5) 'Child started'
   21.400902: ( 5) 'Child enqueued 'mary' & terminating'
   21.400911: ( 1) 'Waiting for STDIN'
   21.400921: ( 0) 'Output: 'john''
   21.401273: ( 0) 'Top of MAIN_LOOP'
   22.402213: ( 0) 'Dequeued 'quit\n''
   22.402345: ( 0) ''QUIT' command'
   22.402832: ( 0) 'Output: 'mary''
   22.403074: ( 0) 'Left MAIN_LOOP'

The interesting thing is that at time 3.024471 -- marked ###, above -- the main thread is about to async a new child thread, but nothing happens until after the "Terminal Watcher" gets the next input line -- where there's a burst of apparently simultaneous activity.

Now, I don't know how a thread inherits file handles. But whatever the procedure is, it appears to be blocked here until <STDIN> returns the next line. Note that the child thread doesn't go near STDIN or STDOUT. The main thread does output to STDOUT, but isn't blocking there.

I note that when a thread is created, the creator may or may not continue to run -- so the new thread may or may not wait (on my uni-processor). Adding a yield after the async changes the order of events slightly -- but doesn't affect the apparent blocking at thread creation.

As previously advertised, closing STDIN in the main thread, before it creates any child threads, causes the code to run "as expected"

Z:\>perl threads.pl c
Create terminal watcher...
STDIN is: open after Terminal Watcher dispatched
STDIN is: closed after close
Awaiting commands...
fred
>fred
bill
>bill
john
>john
mary
>mary
quit
Resolving open threads

and the trace is:

-- with Close STDIN
    0.009832: ( 1) 'Terminal Watcher started'
    0.009940: ( 1) 'Waiting for STDIN'
    0.010435: ( 0) 'STDIN is: open after Terminal Watcher dispatched'
    0.010642: ( 0) 'STDIN is: closed after close'
    0.010927: ( 0) 'Entering MAIN_LOOP'
    0.010955: ( 0) 'Top of MAIN_LOOP'
    1.021469: ( 0) 'Nothing to dequeue'
    1.021572: ( 0) 'Top of MAIN_LOOP'
    2.022909: ( 0) 'Nothing to dequeue'
    2.023017: ( 0) 'Top of MAIN_LOOP'
    2.894161: ( 1) 'Input: 'fred\n''
    2.894298: ( 1) 'Waiting for STDIN'
    3.024349: ( 0) 'Dequeued 'fred\n''
    3.024478: ( 0) 'About to start child thread'
    3.047132: ( 2) 'Child started'
    3.047330: ( 2) 'Child enqueued 'fred' & terminating'
    3.076179: ( 0) 'Dispatched child thread'
    3.076338: ( 0) 'Output: 'fred''
    3.076676: ( 0) 'Top of MAIN_LOOP'
    4.085875: ( 0) 'Nothing to dequeue'
    4.086001: ( 0) 'Top of MAIN_LOOP'
    5.087315: ( 0) 'Nothing to dequeue'
    5.087388: ( 0) 'Top of MAIN_LOOP'
    5.588035: ( 1) 'Input: 'bill\n''
    5.588254: ( 1) 'Waiting for STDIN'
    6.088755: ( 0) 'Dequeued 'bill\n''
    6.088877: ( 0) 'About to start child thread'
    6.116493: ( 0) 'Dispatched child thread'
    6.116650: ( 0) 'Top of MAIN_LOOP'
    6.117257: ( 3) 'Child started'
    6.117413: ( 3) 'Child enqueued 'bill' & terminating'
    7.110224: ( 0) 'Nothing to dequeue'
    7.110354: ( 0) 'Output: 'bill''
    7.110874: ( 0) 'Top of MAIN_LOOP'
    8.111664: ( 0) 'Nothing to dequeue'
    8.111787: ( 0) 'Top of MAIN_LOOP'
    8.812672: ( 1) 'Input: 'john\n''
    8.812890: ( 1) 'Waiting for STDIN'
    9.113104: ( 0) 'Dequeued 'john\n''
    9.113239: ( 0) 'About to start child thread'
    9.134352: ( 0) 'Dispatched child thread'
    9.134506: ( 0) 'Top of MAIN_LOOP'
    9.135166: ( 4) 'Child started'
    9.135317: ( 4) 'Child enqueued 'john' & terminating'
   10.134573: ( 0) 'Nothing to dequeue'
   10.134705: ( 0) 'Output: 'john''
   10.135039: ( 0) 'Top of MAIN_LOOP'
   11.136013: ( 0) 'Nothing to dequeue'
   11.136139: ( 0) 'Top of MAIN_LOOP'
   11.666776: ( 1) 'Input: 'mary\n''
   11.666993: ( 1) 'Waiting for STDIN'
   12.137453: ( 0) 'Dequeued 'mary\n''
   12.137575: ( 0) 'About to start child thread'
   12.159439: ( 0) 'Dispatched child thread'
   12.159594: ( 0) 'Top of MAIN_LOOP'
   12.159905: ( 5) 'Child started'
   12.160045: ( 5) 'Child enqueued 'mary' & terminating'
   13.158921: ( 0) 'Nothing to dequeue'
   13.159051: ( 0) 'Output: 'mary''
   13.159388: ( 0) 'Top of MAIN_LOOP'
   14.160361: ( 0) 'Nothing to dequeue'
   14.160494: ( 0) 'Top of MAIN_LOOP'
   14.210433: ( 1) 'Input: 'quit\n''
   14.210596: ( 1) 'Waiting for STDIN'
   15.161801: ( 0) 'Dequeued 'quit\n''
   15.161932: ( 0) ''QUIT' command'
   15.162408: ( 0) 'Left MAIN_LOOP'

which clearly shows that the starting of the child thread is no longer delayed by the <STDIN>.

The OP reported that the close STDIN did not do the trick on a multi-processor. But it did with the addition of a semaphore that ensured that the main thread STDIN was closed before the Terminal Watcher reached the first <STDIN>.

I tried to simulate this on my uni-processor by yielding immediately after the creation of the Terminal Watcher. This doesn't cause it to fail -- I thought perhaps the file handle could not be closed once the <STDIN> was running... but that does not seem to be the case.

So this remains a puzzle. Which may be related to a misunderstanding of what's going on here. I look forward to enlightenment.

Comment on Re^4: threads on Windows Select or Download Code

Replies are listed 'Best First'.
Re^5: threads on Windows by BrowserUk (Patriarch) on Feb 21, 2009 at 01:23 UTC
Have you ever heard of the concept of a reduced testcase? Did you see my post where I mentioned that "the OS serialises read and write accesses to console devices."? Have you consider the effect of all your verbose logging, and tracing, and "determining the state of STDIN" is having upon the outcome you are seeking to establish? Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error. "Science is about questioning the status quo. Questioning authority". In the absence of evidence, opinion is indistinguishable from prejudice. "Too many [] have been sedated by an oppressive environment of political correctness and risk aversion."	[reply]
Re^6: threads on Windows by gone2015 (Deacon) on Feb 21, 2009 at 13:00 UTC
Have you ever heard of the concept of a reduced testcase? I'm sorry... when I did the work I was trying to find what was going "wrong" with the OP... so I aimed to disturb the underlying code as little as possible. But with a litle more time on my hands, it being Saturday... see below. Did you see my post where I mentioned that "the OS serialises read and write accesses to console devices."? I did, thank you. And, as I said, when I tried a file attached to STDIN the "problem" went away. So, yes, the effect appears to be peculiar to the console. However: the child thread doesn't attempt to read from or write to the console. the main thread doesn't read from, but does write to the console, but doesn't appear to block there. So... the serialization of console read and write access doesn't appear to be the issue. Have you consider the effect of all your verbose logging, and tracing, and "determining the state of STDIN" is having upon the outcome you are seeking to establish? I have. Which is why the trace is gathered in memory and not output until the end. It does introduce a small critical region in the trace gatherer... but that should only affect the progress of the threads (which is arbitrary in any case) when they are runnable. So if my means of observing the problem has affected it, I'm blessed if I can see how. I'm not sure what you mean by "determining the state of STDIN"... but if you mean the test to see if STDIN was open/closed after starting the "Terminal Watcher": then I can tell you that the main result is the same with or without that piece of code. Reduced test case code: use strict; use warnings; use threads; use Thread::Queue; use Time::HiRes qw(time) ; my $START = time() ; my @t = () ; push @t, [time(), "main thread start"] ; my $s_q = Thread::Queue->new ; async { $s_q->enqueue(time()) ; $_ = <STDIN> ; $s_q->enqueue(time()) ; }->detach() ; if (@ARGV) { # option to close STDIN close STDIN ; push @t, [time(), "closed STDIN"] ; } ; threads->yield() ; # make sure STDIN thread starts push @t, [time(), "about to start child thread"] ; my $c_q = Thread::Queue->new ; async { $c_q->enqueue(time()) ; }->detach() ; threads->yield() ; # make sure child thread starts push @t, [time(), "about to collect results"] ; push @t, [$s_q->dequeue(), "STDIN thread started"] ; push @t, [$s_q->dequeue(), "STDIN thread received input"] ; push @t, [$c_q->dequeue(), "child thread ran"] ; threads->yield() ; # give threads opportunity to complete push @t, [time(), "main thread completes"] ; foreach my $t (sort { $a->[0] <=> $b->[0] } @t) { printf "@ %9.6f: %s\n", $t->[0] - $START, $t->[1] ; } ; [download] which on my uni-processor, Windows XP, Perl 5.10.0, gives: Z:\>perl threads_r.pl 12345678901234567890 @ 0.000006: main thread start @ 0.014843: STDIN thread started @ 0.015520: about to start child thread @ 9.814112: STDIN thread received input @ 9.824127: child thread ran @ 9.834141: about to collect results @ 9.834517: main thread completes but if the main thread closes STDIN: Z:\>perl threads_r.pl close 12345678901234567890 @ 0.000004: main thread start @ 0.008159: closed STDIN @ 0.008267: STDIN thread started @ 0.008845: about to start child thread @ 0.017748: child thread ran @ 0.022810: about to collect results @ 10.725422: STDIN thread received input @ 10.735437: main thread completes (where the italics is me pecking at the keyboard to introduce a delay...) FWIW, here's what my Linux box (also uni-processor, Perl 5.10.0) does: [GMCH@hestia ~]$ perl threads_r.pl 012345678901234567890 @ 0.000012: main thread start @ 0.008300: STDIN thread started @ 0.008525: about to start child thread @ 0.024331: child thread ran @ 0.028648: about to collect results @ 11.298085: STDIN thread received input @ 11.298319: main thread completes and closing STDIN makes no difference. My hypothesis is: when creating the child thread the main thread is blocked because whatever "clones" STDIN cannot do so while some other thread is waiting on it -- where STDIN is attached to the console. I can see how that could be related to the serialisation of access to the console device. Nevertheless, it is a bit of a surprise. Happily, closing STDIN does not block and does close the handle -- so there is a work around.	[reply] [d/l]
Re^7: threads on Windows by kennethk (Abbot) on Feb 21, 2009 at 22:44 UTC
I'm glad to see continued discussion. I managed to create what I believe to be the simplest test case for this behavior: `use strict; use warnings; use threads; use Thread::Semaphore; my $gag = new Thread::Semaphore(0); async { $gag->down; while (<>) { print; } }->detach; #close STDIN; # Comment this line for race-condition behavior $gag->up; my $value = async { return 1; }->join;` [download] The proper behavior for this code should be to immediately return control to the OS. In its race-condition configuration under Win32, it will usually wait for one input and parrot it back and sometimes two inputs. Based on your earlier post, I assume your 5.10 can function w/o the use of semaphores. I'll play with it a bit more to see if the addition of instrumentation to an independent log file affects the buffering behavior, but it seems like waiting for input on a shared file handle is blocking thread creation, i.e. what you said.	[reply] [d/l]
Re^8: threads on Windows by BrowserUk (Patriarch) on Feb 22, 2009 at 06:27 UTC
Re^9: threads on Windows by ikegami (Patriarch) on Feb 22, 2009 at 06:36 UTC
Some notes below your chosen depth have not been shown here
Re^8: threads on Windows by gone2015 (Deacon) on Feb 24, 2009 at 13:03 UTC


No such thing as a small change
	PerlMonks