A better/more accurate callstack for Server_PreFork.t hang.
first thread
----------------------------------------------------------------------
ntdll.dll!_KiFastSystemCallRet@0()
ntdll.dll!_NtReadFile@36() + 0xc
kernel32.dll!_ReadFile@20() + 0x67
msvcr71.dll!_read_lk(int fh=3, void * buf=0x00e5815c, unsigned int cnt=8192) Line 154 + 0x15 C
msvcr71.dll!_read(int fh=3, void * buf=0x00e5815c, unsigned int cnt=8192) Line 75 + 0xc C
perl523.dll!PerlLIORead(IPerlLIO * piPerl=0x003664a4, int handle=3, void * buffer=0x00e5815c, unsigned int count=8192) Line 1029 + 0x12 C
perl523.dll!PerlIOUnix_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x00e8ef84, void * vbuf=0x00e5815c, unsigned int count=8192) Line 2730 + 0x14 C
perl523.dll!Perl_PerlIO_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x00e8ef84, void * vbuf=0x00e5815c, unsigned int count=8192) Line 1591 + 0x27 C
perl523.dll!PerlIOBuf_fill(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74) Line 4032 + 0xb C
perl523.dll!Perl_PerlIO_fill(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74) Line 1686 + 0x23 C
perl523.dll!PerlIOBase_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74, void * vbuf=0x0140e624, unsigned int count=1) Line 2082 + 0xb C
perl523.dll!PerlIOBuf_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74, void * vbuf=0x0140e624, unsigned int count=1) Line 4056 + 0xf C
perl523.dll!Perl_PerlIO_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74, void * vbuf=0x0140e624, unsigned int count=1) Line 1591 + 0x27 C
perl523.dll!Perl_pp_sysread(interpreter * my_perl=0x01000000) Line 1819 + 0xd C
perl523.dll!Perl_runops_standard(interpreter * my_perl=0x003642d4) Line 41 + 0x4 C
perl523.dll!S_run_body(interpreter * my_perl=0x00000724, long oldscope=1) Line 2448 + 0xa C
perl523.dll!perl_run(interpreter * my_perl=0x003642d4) Line 2371 + 0x8 C
perl523.dll!RunPerl(int argc=2, char * * argv=0x01362cf0, char * * env=0x003632a8) Line 258 + 0x6 C
perl.exe!mainCRTStartup() Line 398 + 0xe C
kernel32.dll!_BaseProcessStart@4() + 0x23
----------------------------------------------------------------------
curcop is
----------------------------------------------------------------------
warn "# Checking pipe serialization\n" if debug;
pipe(NST_READ, NST_WRITE);
NST_READ->autoflush(1);
NST_WRITE->autoflush(1);
print NST_WRITE "22";
is(read(NST_READ, my $buf, 2), 2, "Pipe works") || do { SKIP: { skip ("Couldn't use working pipe", $N - 3) }; exit };
warn "# Checked pipe serialization\n" if debug;
$env{'block_until_ready_to_test'} = sub { read(NST_READ, my $buf, 1) };<<<<<<<<<<<<<<<<<<<<<<<<<<<<<HERE
$env{'signal_ready_to_test'} = sub { print NST_WRITE "1"; NST_WRITE->flush; };
return \%env;
}
----------------------------------------------------------------------
2nd thread
----------------------------------------------------------------------
ntdll.dll!_KiFastSystemCallRet@0()
ntdll.dll!_ZwWaitForSingleObject@12() + 0xc
ntdll.dll!_RtlpWaitForCriticalSection@4() + 0x8c
ntdll.dll!_RtlEnterCriticalSection@4() + 0x46
msvcr71.dll!_lock_fhandle(int fh=3) Line 453 C
msvcr71.dll!_fstati64(int fildes=3, _stati64 * buf=0x01bdfdcc) Line 86 + 0x6 C
perl523.dll!PerlLIOFileStat(IPerlLIO * piPerl=0x00ed2e9c, int handle=3, _stati64 * buffer=0x01bdfdcc) Line 968 + 0xe C
perl523.dll!PerlIOUnix_setfd(interpreter * my_perl=0x00000401, _PerlIO * * f=0x00070023, int fd=29228120, int imode=0) Line 2579 + 0x12 C
perl523.dll!PerlIOUnix_dup(interpreter * my_perl=0x00f18a64, _PerlIO * * f=0x00f1d974, _PerlIO * * o=0x00edd0d4, clone_params * param=0x01bdfeb4, int flags=1) Line 2705 + 0xc C
perl523.dll!PerlIOBase_dup(interpreter * my_perl=0x00f18a64, _PerlIO * * f=0x00f1d974, _PerlIO * * o=0x00e27094, clone_params * param=0x01bdfeb4, int flags=1) Line 2205 C
perl523.dll!PerlIO_fdupopen(interpreter * my_perl=0x01bdfc58, _PerlIO * * f=0x00070023, clone_params * param=0x01bdfeb4, int flags=1) Line 505 + 0x13 C
perl523.dll!Perl_fp_dup(interpreter * my_perl=0x00f18a64, _PerlIO * * const fp=0x00e27094, const char type=0, clone_params * const param=0x01bdfeb4) Line 12904 + 0xb C
perl523.dll!PerlIO_clone(interpreter * my_perl=0x00000000, interpreter * proto=0x00000401, clone_params * param=0x01bdfeb4) Line 618 + 0xc C
perl523.dll!perl_clone_using(interpreter * proto_perl=0x00e1bc9c, unsigned long flags=1, IPerlMem * ipM=0x00000001, IPerlMem * ipMS=0x00ed2d90, IPerlMem * ipMP=0x00ed2dac, IPerlEnv * ipE=0x00ed2dc8, IPerlStdIO * ipStd=0x00ed2e00, IPerlLIO * ipLIO=0x00ed2e9c, IPerlDir * ipD=0x00ed2f04, IPerlSock * ipS=0x00ed2f30, IPerlProc * ipP=0x00ed2fe0) Line 14770 C
perl523.dll!PerlProcFork(IPerlProc * piPerl=0x00a50300) Line 1831 + 0x3e C
perl523.dll!Perl_pp_fork(interpreter * my_perl=0x00e1bc9c) Line 4173 + 0xa C
perl523.dll!Perl_runops_standard(interpreter * my_perl=0x00e1bc9c) Line 41 + 0x4 C
perl523.dll!win32_start_child(void * arg=0x00e1bc9c) Line 1744 C
kernel32.dll!_BaseThreadStart@8() + 0x37
----------------------------------------------------------------------
sub run_n_children {
my ($self, $n) = @_;
my $prop = $self->{'server'};
return unless $n > 0;
$self->run_n_children_hook($n);
my ($parentsock, $childsock);
$self->log(3, "Starting \"$n\" children");
$prop->{'last_start'} = time();
for (1 .. $n) {
if ($prop->{'child_communication'}) {
require IO::Socket::UNIX;
($parentsock, $childsock) = IO::Socket::UNIX->socketpair(IO::Socket::AF_UNIX, IO::Socket::SOCK_STREAM, IO::Socket::PF_UNSPEC);
}
$self->pre_fork_hook;
local $!;
my $pid = fork;<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<HERE
if (! defined $pid) {
if ($prop->{'child_communication'}) {
$parentsock->close();
$childsock->close();
}
----------------------------------------------------------------------
The Critical section mutex dumped,
- (CRITICAL_SECTION*)0x00361fa0 0x00361fa0 {DebugInfo=0x00154c60 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x00361fa0 {DebugInfo=0x00154c60 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x00361fa0 ...} LockCount=1 RecursionCount=1 ...} ...} LockCount=1 RecursionCount=1 ...} _RTL_CRITICAL_SECTION *
+ DebugInfo 0x00154c60 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x00361fa0 {DebugInfo=0x00154c60 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x00361fa0 {DebugInfo=0x00154c60 LockCount=1 RecursionCount=1 ...} ...} LockCount=1 RecursionCount=1 ...} ...} _RTL_CRITICAL_SECTION_DEBUG *
LockCount 1 long
RecursionCount 1 long
OwningThread 0x00001564 void *
LockSemaphore 0x000006e4 void *
SpinCount 4000 unsigned long
Thread 0x00001564 is the thread blocking in the read call
---------------------------------------------------------------------------
ntdll.dll!_KiFastSystemCallRet@0()
ntdll.dll!_NtReadFile@36() + 0xc
kernel32.dll!_ReadFile@20() + 0x67
msvcr71.dll!_read_lk(int fh=3, void * buf=0x00e5815c, unsigned int cnt=8192) Line 154 + 0x15 C
msvcr71.dll!_read(int fh=3, void * buf=0x00e5815c, unsigned int cnt=8192) Line 75 + 0xc C
perl523.dll!PerlLIORead(IPerlLIO * piPerl=0x003664a4, int handle=3, void * buffer=0x00e5815c, unsigned int count=8192) Line 1029 + 0x12 C
perl523.dll!PerlIOUnix_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x00e8ef84, void * vbuf=0x00e5815c, unsigned int count=8192) Line 2730 + 0x14 C
perl523.dll!Perl_PerlIO_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x00e8ef84, void * vbuf=0x00e5815c, unsigned int count=8192) Line 1591 + 0x27 C
perl523.dll!PerlIOBuf_fill(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74) Line 4032 + 0xb C
perl523.dll!Perl_PerlIO_fill(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74) Line 1686 + 0x23 C
perl523.dll!PerlIOBase_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74, void * vbuf=0x0140e624, unsigned int count=1) Line 2082 + 0xb C
perl523.dll!PerlIOBuf_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74, void * vbuf=0x0140e624, unsigned int count=1) Line 4056 + 0xf C
perl523.dll!Perl_PerlIO_read(interpreter * my_perl=0x003642d4, _PerlIO * * f=0x008f5c74, void * vbuf=0x0140e624, unsigned int count=1) Line 1591 + 0x27 C
perl523.dll!Perl_pp_sysread(interpreter * my_perl=0x01000000) Line 1819 + 0xd C
perl523.dll!Perl_runops_standard(interpreter * my_perl=0x003642d4) Line 41 + 0x4 C
perl523.dll!S_run_body(interpreter * my_perl=0x00000724, long oldscope=1) Line 2448 + 0xa C
perl523.dll!perl_run(interpreter * my_perl=0x003642d4) Line 2371 + 0x8 C
perl523.dll!RunPerl(int argc=2, char * * argv=0x01362cf0, char * * env=0x003632a8) Line 258 + 0x6 C
perl.exe!mainCRTStartup() Line 398 + 0xe C
kernel32.dll!_BaseProcessStart@4() + 0x23
---------------------------------------------------------------------------
So the psuedofork is blocking on fd 3 becoming unlocked, while the parent thread/psuedoproc is waiting for its pipe lock to be unblocked. The easy fix is for the Perl code to use Win32::Mutex. This problem of _lock_fhandle is P5P bug
https://rt.perl.org/Ticket/Display.html?id=65136
