[PATCH] speed up miniperl @INC searching, buildcustomize

[p5pRT]

Migrated from rt.perl.org#121119 (status was 'resolved')

Searchable as RT121119$

[p5pRT]

From @bulk88

Created by @bulk88

See attached patch. Each dir being searched that fails on Win32 results
in 10 I/O sys calls which I counted at 17 ms wall time, times 16 build
customize dirs that didn't match is an extra 272 ms of wall time dealing
with the not found dirs during an @​INC search. Also as the build
progresses, more and more things will be found on the 1st try in /lib,
and I presume buildcustomize dirs become totally unused once XS module
start being built since everything needed for XS building (which is a PP
process) will be in /lib and found on 1st try.

regular build
-----------------------------------------------------------------
  if exist ..\x2p\a2p.exe.manifest mt -nologo -manifest
..\x2p\a2p.exe.man
ifest -outputresource​:..\x2p\a2p.exe;1 && if exist
..\x2p\a2p.exe.manifest del
..\x2p\a2p.exe.manifest
Everything is up to date. 'nmake test' to run test suite.
timethis 1​: 1656 wallclock secs ( 0.00 usr + 0.00 sys = 0.00 CPU)
  (warning​: too few iterations for a reliable count)

C​:\p519\src\win32>perl -MBenchmark -e" timethis(1, 'system(\'nmake\')')"
-----------------------------------------------------------------
build with this patch
-----------------------------------------------------------------
  if exist ..\x2p\a2p.exe.manifest mt -nologo -manifest
..\x2p\a2p.exe.man
ifest -outputresource​:..\x2p\a2p.exe;1 && if exist
..\x2p\a2p.exe.manifest del
..\x2p\a2p.exe.manifest
Everything is up to date. 'nmake test' to run test suite.
timethis 1​: 1137 wallclock secs ( 0.00 usr + 0.00 sys = 0.00 CPU)
  (warning​: too few iterations for a reliable count)

C​:\p519\srcnew\win32>perl -MBenchmark -e" timethis(1, 'system(\'nmake\')')"
-----------------------------------------------------------------

(1656 - 1137) / 60 = 8.65 mins

(the following number is a flaky statistic)
(1656 - 1137) / .272 ms= 1908.08824 runs of miniperl???

I've attached a procmon log of miniperl uselessly searching a large num
of @​INC dirs every time a use/require is done. The log is of the "before".

I left the original comment in place for historical reasons. The comment
might be from something that happened in a Module​::Build module back
when M​::B was in core.

Perl Info

Flags:
           category=core
           severity=low

Site configuration information for perl 5.19.7:

Configured by Owner at Thu Nov 28 02:32:44 2013.

Summary of my perl5 (revision 5 version 19 subversion 7) configuration:
         Derived from: 8f47723e28b75530b743941cdd8b07f849ec48e2
         Ancestor: 1061065f7a09399eefb50e9a035502621722bcc0
         Platform:
           osname=MSWin32, osvers=5.1, archname=MSWin32-x86-multi-thread
           uname=''
           config_args='undef'
           hint=recommended, useposix=true, d_sigaction=undef
           useithreads=define, usemultiplicity=define
           useperlio=define, d_sfio=undef, uselargefiles=define,
usesocks=undef
           use64bitint=undef, use64bitall=undef, uselongdouble=undef
           usemymalloc=n, bincompat5005=undef
         Compiler:
           cc='cl', ccflags ='-nologo -GF -W3 -O1 -MD -Zi -DNDEBUG -G7 -GL
-DWIN32 -D_CONSOLE -DNO_STRICT  -DPERL_TEXTMODE_SCRIPTS
-DPERL_HASH_FUNC_ONE_AT_A_TIME -DPERL_IMPLICIT_CONTEXT
-DPERL_IMPLICIT_SYS -DUSE_PERLIO -D_USE_32BIT_TIME_T',
           optimize='-O1 -MD -Zi -DNDEBUG -G7 -GL',
           cppflags='-DWIN32'
           ccversion='13.10.6030', gccversion='', gccosandvers=''
           intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234
           d_longlong=undef, longlongsize=8, d_longdbl=define, longdblsize=8
           ivtype='long', ivsize=4, nvtype='double', nvsize=8,
Off_t='__int64',
lseeksize=8
           alignbytes=8, prototype=define
         Linker and Libraries:
           ld='link', ldflags ='-nologo -nodefaultlib -debug -opt:ref,icf
-ltcg  -libpath:"c:\perl519\lib\CORE"  -machine:x86'
           libpth="C:\Program Files\Microsoft Visual Studio .NET
2003\VC7\lib"
           libs=oldnames.lib kernel32.lib user32.lib gdi32.lib winspool.lib
comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib
netapi32.lib uuid.lib ws2_32.lib mpr.lib winmm.lib  version.lib
odbc32.lib odbccp32.lib comctl32.lib msvcrt.lib
           perllibs=oldnames.lib kernel32.lib user32.lib gdi32.lib
winspool.lib  comdlg32.lib advapi32.lib shell32.lib ole32.lib
oleaut32.lib  netapi32.lib uuid.lib ws2_32.lib mpr.lib winmm.lib
version.lib odbc32.lib odbccp32.lib comctl32.lib msvcrt.lib
           libc=msvcrt.lib, so=dll, useshrplib=true, libperl=perl519.lib
           gnulibc_version=''
         Dynamic Linking:
           dlsrc=dl_win32.xs, dlext=dll, d_dlsymun=undef, ccdlflags=' '
           cccdlflags=' ', lddlflags='-dll -nologo -nodefaultlib -debug
-opt:ref,icf -ltcg  -libpath:"c:\perl519\lib\CORE"  -machine:x86'

Locally applied patches:
           uncommitted-changes
           8f47723e28b75530b743941cdd8b07f849ec48e2


@INC for perl 5.19.7:
           C:/perl519/site/lib
           C:/perl519/lib
           .


Environment for perl 5.19.7:
           HOME (unset)
           LANG (unset)
           LANGUAGE (unset)
           LD_LIBRARY_PATH (unset)
           LOGDIR (unset)
           PATH=C:\perl519\bin;C:\Program Files\Microsoft Visual Studio .NET
2003\Common7\IDE;C:\Program Files\Microsoft Visual Studio .NET
2003\VC7\BIN;C:\Program Files\Microsoft Visual Studio .NET
2003\Common7\Tools;C:\Program Files\Microsoft Visual Studio .NET
2003\Common7\Tools\bin\prerelease;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\system32\wbem;
           PERL_BADLANG (unset)
           SHELL (unset)

[p5pRT]

From @bulk88

bad_inc_procmon.txt

[p5pRT]

From @bulk88

0001-speed-up-miniperl-INC-searching-buildcustomize.patch

From 8af300d3dcbc3e6955a9f2b79fa73cbb323d6c1d Mon Sep 17 00:00:00 2001
From: Daniel Dragan <bulk88@hotmail.com>
Date: Thu, 30 Jan 2014 02:53:09 -0500
Subject: [PATCH] speed up miniperl @INC searching, buildcustomize

most modules are pre-installed in /lib. The buildcustomize modules are
more rarely used than warnings and strict for example. Previously /lib
was the last dir searched with ~1.5 dozen dirs uselessly searched first.
This commit reduced my build time by ~8-9 mins.
---
 write_buildcustomize.pl |    7 ++++++-
 1 files changed, 6 insertions(+), 1 deletions(-)

diff --git a/write_buildcustomize.pl b/write_buildcustomize.pl
index 64bf4ce..5309988 100644
--- a/write_buildcustomize.pl
+++ b/write_buildcustomize.pl
@@ -48,13 +48,18 @@ push @toolchain, 'ext/VMS-Filespec/lib' if $^O eq 'VMS';
 unshift @INC, @toolchain;
 require File::Spec::Functions;
 
+# former comment
+#
 # lib must be last, as the toolchain modules write themselves into it
 # as they build, and it's important that @INC order ensures that the partially
 # written files are always masked by the complete versions.
 
 my $inc = join ",\n        ",
     map { "q\0$_\0" }
-    (map {File::Spec::Functions::rel2abs($_)} @toolchain, 'lib');
+# putting lib first shaves a couple minutes off the build time since the most
+# common modules like warnings and strict are in lib, and as extensions are
+# built the chances of the module being found in lib increases
+    (map {File::Spec::Functions::rel2abs($_)} 'lib', @toolchain);
 
 open my $fh, '>', $file
     or die "Can't open $file: $!";
-- 
1.7.9.msysgit.0

[p5pRT]

From @bulk88

On Thu Jan 30 00​:01​:05 2014, bulk88 wrote​:

This is a bug report for perl from bulk88@​hotmail.com,
generated with the help of perlbug 1.39 running under perl 5.19.7.

-----------------------------------------------------------------
[Please describe your issue here]

See attached patch. Each dir being searched that fails on Win32
results
in 10 I/O sys calls which I counted at 17 ms wall time, times 16 build
customize dirs that didn't match is an extra 272 ms of wall time
dealing
with the not found dirs during an @​INC search. Also as the build
progresses, more and more things will be found on the 1st try in /lib,
and I presume buildcustomize dirs become totally unused once XS module
start being built since everything needed for XS building (which is a
PP
process) will be in /lib and found on 1st try.

regular build
-----------------------------------------------------------------
if exist ..\x2p\a2p.exe.manifest mt -nologo -manifest
..\x2p\a2p.exe.man
ifest -outputresource​:..\x2p\a2p.exe;1 && if exist
..\x2p\a2p.exe.manifest del
..\x2p\a2p.exe.manifest
Everything is up to date. 'nmake test' to run test suite.
timethis 1​: 1656 wallclock secs ( 0.00 usr + 0.00 sys = 0.00 CPU)
(warning​: too few iterations for a reliable count)

C​:\p519\src\win32>perl -MBenchmark -e" timethis(1,
'system(\'nmake\')')"
-----------------------------------------------------------------
build with this patch
-----------------------------------------------------------------
if exist ..\x2p\a2p.exe.manifest mt -nologo -manifest
..\x2p\a2p.exe.man
ifest -outputresource​:..\x2p\a2p.exe;1 && if exist
..\x2p\a2p.exe.manifest del
..\x2p\a2p.exe.manifest
Everything is up to date. 'nmake test' to run test suite.
timethis 1​: 1137 wallclock secs ( 0.00 usr + 0.00 sys = 0.00 CPU)
(warning​: too few iterations for a reliable count)

C​:\p519\srcnew\win32>perl -MBenchmark -e" timethis(1,
'system(\'nmake\')')"
-----------------------------------------------------------------

(1656 - 1137) / 60 = 8.65 mins

(the following number is a flaky statistic)
(1656 - 1137) / .272 ms= 1908.08824 runs of miniperl???

I've attached a procmon log of miniperl uselessly searching a large
num
of @​INC dirs every time a use/require is done. The log is of the
"before".

I left the original comment in place for historical reasons. The
comment
might be from something that happened in a Module​::Build module back
when M​::B was in core.

[Please do not change anything below this line]
-----------------------------------------------------------------
---
Flags​:
category=core
severity=low
---
Site configuration information for perl 5.19.7​:

Configured by Owner at Thu Nov 28 02​:32​:44 2013.

Summary of my perl5 (revision 5 version 19 subversion 7)
configuration​:
Derived from​: 8f47723e28b75530b743941cdd8b07f849ec48e2
Ancestor​: 1061065
Platform​:
osname=MSWin32, osvers=5.1, archname=MSWin32-x86-multi-
thread
uname=''
config_args='undef'
hint=recommended, useposix=true, d_sigaction=undef
useithreads=define, usemultiplicity=define
useperlio=define, d_sfio=undef, uselargefiles=define,
usesocks=undef
use64bitint=undef, use64bitall=undef, uselongdouble=undef
usemymalloc=n, bincompat5005=undef
Compiler​:
cc='cl', ccflags ='-nologo -GF -W3 -O1 -MD -Zi -DNDEBUG -G7
-GL
-DWIN32 -D_CONSOLE -DNO_STRICT -DPERL_TEXTMODE_SCRIPTS
-DPERL_HASH_FUNC_ONE_AT_A_TIME -DPERL_IMPLICIT_CONTEXT
-DPERL_IMPLICIT_SYS -DUSE_PERLIO -D_USE_32BIT_TIME_T',
optimize='-O1 -MD -Zi -DNDEBUG -G7 -GL',
cppflags='-DWIN32'
ccversion='13.10.6030', gccversion='', gccosandvers=''
intsize=4, longsize=4, ptrsize=4, doublesize=8,
byteorder=1234
d_longlong=undef, longlongsize=8, d_longdbl=define,
longdblsize=8
ivtype='long', ivsize=4, nvtype='double', nvsize=8,
Off_t='__int64',
lseeksize=8
alignbytes=8, prototype=define
Linker and Libraries​:
ld='link', ldflags ='-nologo -nodefaultlib -debug
-opt​:ref,icf
-ltcg -libpath​:"c​:\perl519\lib\CORE" -machine​:x86'
libpth="C​:\Program Files\Microsoft Visual Studio .NET
2003\VC7\lib"
libs=oldnames.lib kernel32.lib user32.lib gdi32.lib
winspool.lib
comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib
netapi32.lib uuid.lib ws2_32.lib mpr.lib winmm.lib version.lib
odbc32.lib odbccp32.lib comctl32.lib msvcrt.lib
perllibs=oldnames.lib kernel32.lib user32.lib gdi32.lib
winspool.lib comdlg32.lib advapi32.lib shell32.lib ole32.lib
oleaut32.lib netapi32.lib uuid.lib ws2_32.lib mpr.lib winmm.lib
version.lib odbc32.lib odbccp32.lib comctl32.lib msvcrt.lib
libc=msvcrt.lib, so=dll, useshrplib=true,
libperl=perl519.lib
gnulibc_version=''
Dynamic Linking​:
dlsrc=dl_win32.xs, dlext=dll, d_dlsymun=undef, ccdlflags='
'
cccdlflags=' ', lddlflags='-dll -nologo -nodefaultlib
-debug
-opt​:ref,icf -ltcg -libpath​:"c​:\perl519\lib\CORE" -machine​:x86'

Locally applied patches​:
uncommitted-changes
8f47723e28b75530b743941cdd8b07f849ec48e2

---
@​INC for perl 5.19.7​:
C​:/perl519/site/lib
C​:/perl519/lib
.

---
Environment for perl 5.19.7​:
HOME (unset)
LANG (unset)
LANGUAGE (unset)
LD_LIBRARY_PATH (unset)
LOGDIR (unset)
PATH=C​:\perl519\bin;C​:\Program Files\Microsoft Visual
Studio .NET
2003\Common7\IDE;C​:\Program Files\Microsoft Visual Studio .NET
2003\VC7\BIN;C​:\Program Files\Microsoft Visual Studio .NET
2003\Common7\Tools;C​:\Program Files\Microsoft Visual Studio .NET
2003\Common7\Tools\bin\prerelease;C​:\WINDOWS\system32;C​:\WINDOWS;C​:\WINDOWS\system32\wbem;
PERL_BADLANG (unset)
SHELL (unset)

This was rejected from the P5P ML due to attachment size (250KB limit IIRC). Bumping.

--
bulk88 ~ bulk88 at hotmail.com

[p5pRT]

From @iabyn

On Thu, Jan 30, 2014 at 12​:13​:16AM -0800, bulk88 via RT wrote​:

See attached patch. Each dir being searched that fails on Win32
results
in 10 I/O sys calls which I counted at 17 ms wall time, times 16 build
customize dirs that didn't match is an extra 272 ms of wall time
dealing
with the not found dirs during an @​INC search. Also as the build
progresses, more and more things will be found on the 1st try in /lib,
and I presume buildcustomize dirs become totally unused once XS module
start being built since everything needed for XS building (which is a
PP
process) will be in /lib and found on 1st try.

[snip; this cuts the 'make' time by​: ]

(1656 - 1137) / 60 = 8.65 mins

[snip]

I left the original comment in place for historical reasons. The
comment
might be from something that happened in a Module​::Build module back
when M​::B was in core.

For the convenience of others, here is the original patch​:

Inline Patch

diff --git a/write_buildcustomize.pl b/write_buildcustomize.pl
index 64bf4ce..5309988 100644
--- a/write_buildcustomize.pl
+++ b/write_buildcustomize.pl
@@ -48,13 +48,18 @@ push @toolchain, 'ext/VMS-Filespec/lib' if $^O eq 'VMS';
 unshift @INC, @toolchain;
 require File::Spec::Functions;
 
+# former comment
+#
 # lib must be last, as the toolchain modules write themselves into it
 # as they build, and it's important that @INC order ensures that the partially
 # written files are always masked by the complete versions.
 
 my $inc = join ",\n        ",
     map { "q\0$_\0" }
-    (map {File::Spec::Functions::rel2abs($_)} @toolchain, 'lib');
+# putting lib first shaves a couple minutes off the build time since the most
+# common modules like warnings and strict are in lib, and as extensions are
+# built the chances of the module being found in lib increases
+    (map {File::Spec::Functions::rel2abs($_)} 'lib', @toolchain);

Before such a patch went in, I think we'd have to be sure that the reasons stated in the code for needing to put lib last don't still apply\. Although I'm not very familiar with lib/buildcustomize\.pl\, it seems to me that the reason still stands\. Especially on a parallel make\, I could see one instance of miniperl running while another instance is copying files from ext/Foo to lib\, thus allowing it to see empty or truncated files; or even if the installation of files into lib/ is atomic\, a mixture of files from the same distro\, some in lib\, some still under ext/ or whatever might be seem\, and might be harmful\.

So this doesn't seem safe to me.

--
More than any other time in history, mankind faces a crossroads. One path
leads to despair and utter hopelessness. The other, to total extinction.
Let us pray we have the wisdom to choose correctly.
  -- Woody Allen

[p5pRT]

The RT System itself - Status changed from 'new' to 'open'

[p5pRT]

From @nwc10

On Thu, Jan 30, 2014 at 11​:25​:28AM +0000, Dave Mitchell wrote​:

On Thu, Jan 30, 2014 at 12​:13​:16AM -0800, bulk88 via RT wrote​:

See attached patch. Each dir being searched that fails on Win32
results
in 10 I/O sys calls which I counted at 17 ms wall time, times 16 build
customize dirs that didn't match is an extra 272 ms of wall time
dealing
with the not found dirs during an @​INC search. Also as the build
progresses, more and more things will be found on the 1st try in /lib,
and I presume buildcustomize dirs become totally unused once XS module
start being built since everything needed for XS building (which is a
PP
process) will be in /lib and found on 1st try.

[snip; this cuts the 'make' time by​: ]

(1656 - 1137) / 60 = 8.65 mins

[snip]

I left the original comment in place for historical reasons. The
comment
might be from something that happened in a Module​::Build module back
when M​::B was in core.

For the convenience of others, here is the original patch​:

diff --git a/write_buildcustomize.pl b/write_buildcustomize.pl
index 64bf4ce..5309988 100644
--- a/write_buildcustomize.pl
+++ b/write_buildcustomize.pl
@​@​ -48,13 +48,18 @​@​ push @​toolchain, 'ext/VMS-Filespec/lib' if $^O eq 'VMS';
unshift @​INC, @​toolchain;
require File​::Spec​::Functions;

+# former comment
+#
# lib must be last, as the toolchain modules write themselves into it
# as they build, and it's important that @​INC order ensures that the partially
# written files are always masked by the complete versions.

my $inc = join ",\n ",
map { "q\0$_\0" }
- (map {File​::Spec​::Functions​::rel2abs($_)} @​toolchain, 'lib');
+# putting lib first shaves a couple minutes off the build time since the most
+# common modules like warnings and strict are in lib, and as extensions are
+# built the chances of the module being found in lib increases
+ (map {File​::Spec​::Functions​::rel2abs($_)} 'lib', @​toolchain);

Before such a patch went in, I think we'd have to be sure that the reasons
stated in the code for needing to put lib last don't still apply.
Although I'm not very familiar with lib/buildcustomize.pl, it seems to me
that the reason still stands. Especially on a parallel make, I could
see one instance of miniperl running while another instance is copying
files from ext/Foo to lib, thus allowing it to see empty or truncated
files; or even if the installation of files into lib/ is atomic, a mixture
of files from the same distro, some in lib, some still under ext/ or
whatever might be seem, and might be harmful.

So this doesn't seem safe to me.

Thanks for ensuring that the patch gets to the list.

No, specifically it's completely unsafe for a parallel make.

You end up with race conditions where the build fails because one process
process loads from lib/ a partially written module and aborts, because it
happens just as another process is copying that file there.
(And the rest of the time you don't have a problem because the file is either
not in lib, so loaded from the original dist/... etc, or it's fully copied to
lib, so loaded from there)

Which is exactly what the comment in the file tries to explain.

However, as Win32 doesn't have parallel makes *yet*, and this seems to be a
big speed hit on Win32, I think that it would be reasonable to do the
proposed re-ordering on Win32, with a comment that it needs to be rethought
once anyone starts getting parallel makes working on Win32.

Nicholas Clark

[p5pRT]

From @iabyn

On Thu, Jan 30, 2014 at 12​:13​:16AM -0800, bulk88 via RT wrote​:

See attached patch. Each dir being searched that fails on Win32
results
in 10 I/O sys calls which I counted at 17 ms wall time, times 16 build
customize dirs that didn't match is an extra 272 ms of wall time
dealing
with the not found dirs during an @​INC search.

That does sound extraordinarily slow. On my (admittedly fast) Linux laptop,
the following code takes approx 0.9 microsec per -f test​:

  my @​path = (
  "home/davem/perl5/git/bleed-davem/cpan/AutoLoader/lib",
  "home/davem/perl5/git/bleed-davem/dist/Carp/lib",
  "home/davem/perl5/git/bleed-davem/dist/PathTools",
  "home/davem/perl5/git/bleed-davem/dist/PathTools/lib",
  "home/davem/perl5/git/bleed-davem/dist/ExtUtils-Command/lib",
  "home/davem/perl5/git/bleed-davem/dist/ExtUtils-Install/lib",
  "home/davem/perl5/git/bleed-davem/cpan/ExtUtils-MakeMaker/lib",
  "home/davem/perl5/git/bleed-davem/dist/ExtUtils-Manifest/lib",
  "home/davem/perl5/git/bleed-davem/cpan/File-Path/lib",
  "home/davem/perl5/git/bleed-davem/ext/re",
  "home/davem/perl5/git/bleed-davem/dist/Term-ReadLine/lib",
  "home/davem/perl5/git/bleed-davem/dist/Exporter/lib",
  "home/davem/perl5/git/bleed-davem/ext/File-Find/lib",
  "home/davem/perl5/git/bleed-davem/cpan/Text-Tabs/lib",
  "home/davem/perl5/git/bleed-davem/dist/constant/lib",
  "home/davem/perl5/git/bleed-davem/lib",
  );

  my $i = 0;
  for my $file ("aaa" .."zzz") {
  for (@​path) {
  $i++;
  next unless -f "$_/NoSuchFile-$file.pmc" or -f "$_/NoSuchFile-$file.pm";
  }
  }
  print "i=$i\n";

Perhaps this implies that's there's something sub-optimal in the way perl
does its @​INC scanning under Win32?

--
Fire extinguisher (n) a device for holding open fire doors.

[p5pRT]

From @bulk88

On Thu Jan 30 05​:30​:31 2014, davem wrote​:

On Thu, Jan 30, 2014 at 12​:13​:16AM -0800, bulk88 via RT wrote​:

See attached patch. Each dir being searched that fails on Win32
results
in 10 I/O sys calls which I counted at 17 ms wall time, times 16
build
customize dirs that didn't match is an extra 272 ms of wall time
dealing
with the not found dirs during an @​INC search.

That does sound extraordinarily slow. On my (admittedly fast) Linux
laptop,
the following code takes approx 0.9 microsec per -f test​:

my @​path = (
"home/davem/perl5/git/bleed-davem/cpan/AutoLoader/lib",
"home/davem/perl5/git/bleed-davem/dist/Carp/lib",
"home/davem/perl5/git/bleed-davem/dist/PathTools",
"home/davem/perl5/git/bleed-davem/dist/PathTools/lib",
"home/davem/perl5/git/bleed-davem/dist/ExtUtils-Command/lib",
"home/davem/perl5/git/bleed-davem/dist/ExtUtils-Install/lib",
"home/davem/perl5/git/bleed-davem/cpan/ExtUtils-MakeMaker/lib",
"home/davem/perl5/git/bleed-davem/dist/ExtUtils-Manifest/lib",
"home/davem/perl5/git/bleed-davem/cpan/File-Path/lib",
"home/davem/perl5/git/bleed-davem/ext/re",
"home/davem/perl5/git/bleed-davem/dist/Term-ReadLine/lib",
"home/davem/perl5/git/bleed-davem/dist/Exporter/lib",
"home/davem/perl5/git/bleed-davem/ext/File-Find/lib",
"home/davem/perl5/git/bleed-davem/cpan/Text-Tabs/lib",
"home/davem/perl5/git/bleed-davem/dist/constant/lib",
"home/davem/perl5/git/bleed-davem/lib",
);

my $i = 0;
for my $file ("aaa" .."zzz") {
for (@​path) {
$i++;
next unless -f "$_/NoSuchFile-$file.pmc" or -f
"$_/NoSuchFile-$file.pm";
}
}
print "i=$i\n";

Perhaps this implies that's there's something sub-optimal in the way
perl
does its @​INC scanning under Win32?

Go to the RT ticket through web interface, and look at the bad_inc_procmon.txt attachment, it contains strace like data with wall time on the very left. The calls are sniffed by a filter driver that gets first dibs on all I/O packets (since NT Kernel uses a packetized (or transactional) async I/O model) coming from user mode.

A failed @​INC test, per dir looks like this after hand trimming of the right side of each line (look at the raw data if you want to see a dump of the args to the syscalls). QueryDirectory is related to enumerating a dir. It requires a dir handle, hence the CreateFile on C​:\p519\src\cpan\Test-Harness. "QueryOpen" I'm not sure what C function generates it, or if its called internally by the FS driver, but it fetches this struct http​://msdn.microsoft.com/en-us/library/windows/hardware/ff545822%28v=vs.85%29.aspx (from later research it is GetFileAttributesA)

---

9​:08​:36.3922806 PM miniperl.exe 1208 CreateFile C​:\p519\src\cpan\Test-Harness\DynaLoader.pmc NAME NOT FOUND
9​:08​:36.3937813 PM miniperl.exe 1208 CreateFile C​:\p519\src\cpan\Test-Harness SUCCESS
9​:08​:36.3949223 PM miniperl.exe 1208 QueryDirectory C​:\p519\src\cpan\Test-Harness\DynaLoader.pmc NO SUCH FILE
9​:08​:36.3960337 PM miniperl.exe 1208 CloseFile C​:\p519\src\cpan\Test-Harness SUCCESS
9​:08​:36.3976316 PM miniperl.exe 1208 QueryOpen C​:\p519\src\cpan\Test-Harness\DynaLoader.pmc NAME NOT FOUND
9​:08​:36.3992307 PM miniperl.exe 1208 CreateFile C​:\p519\src\cpan\Test-Harness\DynaLoader.pm NAME NOT FOUND
9​:08​:36.4007414 PM miniperl.exe 1208 CreateFile C​:\p519\src\cpan\Test-Harness SUCCESS 9​:08​:36.4019127 PM miniperl.exe 1208 QueryDirectory C​:\p519\src\cpan\Test-Harness\DynaLoader.pm NO SUCH FILE
9​:08​:36.4030441 PM miniperl.exe 1208 CloseFile C​:\p519\src\cpan\Test-Harness SUCCESS
9​:08​:36.4046092 PM miniperl.exe 1208 QueryOpen C​:\p519\src\cpan\Test-Harness\DynaLoader.pm NAME NOT FOUND

---

By setting a BP at the enter kernel mode func, and doing "miniperl -Ilib -e "system('pause'); require FooLoader;"" I'll try to figure out what the syscall were. First one

from win32_stat path 0x00a0b660 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pmc" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_NtCreateFile@​44() + 0xc
  kernel32.dll!_CreateFileW@​28() + 0x1b6
  kernel32.dll!_CreateFileA@​28() + 0x2b
  miniperl.exe!win32_stat(const char * path=0x00100080, stat * sbuf=0x0012fe50) Line 1499 + 0xe C
  miniperl.exe!S_doopen_pm(sv * name=0x00070023) Line 3630 + 0x2a C
  miniperl.exe!Perl_pp_require() Line 4012 C
  miniperl.exe!Perl_runops_standard() Line 42 + 0x3 C
  miniperl.exe!S_run_body(long oldscope=0x00000001) Line 2448 C
  miniperl.exe!perl_run(interpreter * my_perl=0x0012ffc0) Line 2362 + 0x8 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x00912478, char * * env=0x00912c90) Line 118 + 0x5 C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

+ path 0x00a0b660 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pmc" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_ZwOpenFile@​24() + 0xc
  kernel32.dll!_FindFirstFileExW@​24() + 0x179
  kernel32.dll!_FindFirstFileA@​8() + 0x3e
  msvcr71.dll!_stati64(const char * name=0x0012f810, _stati64 * buf=0x00000000) Line 184 C
  miniperl.exe!win32_stat(const char * path=0x00a0b660, _stati64 * sbuf=0x0012fd48) Line 1510 + 0xe C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3630 + 0x43 C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

+ path 0x00a0b660 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pmc" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_ZwQueryDirectoryFile@​44() + 0xc
  kernel32.dll!_FindFirstFileExW@​24() + 0x245
  kernel32.dll!_FindFirstFileA@​8() + 0x3e
  msvcr71.dll!_stati64(const char * name=0x0012f810, _stati64 * buf=0x00000000) Line 184 C
  miniperl.exe!win32_stat(const char * path=0x00a0b660, _stati64 * sbuf=0x0012fd48) Line 1510 + 0xe C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3630 + 0x43 C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

+ path 0x00a0b660 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pmc" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_NtClose@​4() + 0xc
  kernel32.dll!_FindFirstFileExW@​24() + 0x497
  kernel32.dll!_FindFirstFileA@​8() + 0x3e
  msvcr71.dll!_stati64(const char * name=0x0012f810, _stati64 * buf=0x00000000) Line 184 C
  miniperl.exe!win32_stat(const char * path=0x00a0b660, _stati64 * sbuf=0x0012fd48) Line 1510 + 0xe C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3630 + 0x43 C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

+ path 0x00a0b660 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pmc" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_NtQueryAttributesFile@​8() + 0xc
  kernel32.dll!_GetFileAttributesW@​4() + 0x67
  kernel32.dll!_GetFileAttributesA@​4() + 0x1d
  miniperl.exe!win32_stat(const char * path=0x00a0b660, _stati64 * sbuf=0x0012fd48) Line 1521 + 0xa C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3630 + 0x43 C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

*************************now switch to checking .pm, not .pmc anymore****************************************************

+ path 0x00a0a388 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pm" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_NtCreateFile@​44() + 0xc
  kernel32.dll!_CreateFileW@​28() + 0x1b6
  kernel32.dll!_CreateFileA@​28() + 0x2b
  miniperl.exe!win32_stat(const char * path=0x00a0a388, _stati64 * sbuf=0x0012fce8) Line 1499 + 0x16 C
  miniperl.exe!S_check_type_and_open(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3594 + 0xd C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3633 + 0xd C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

+ path 0x00a0a388 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pm" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_ZwOpenFile@​24() + 0xc
  kernel32.dll!_FindFirstFileExW@​24() + 0x179
  kernel32.dll!_FindFirstFileA@​8() + 0x3e
  msvcr71.dll!_stati64(const char * name=0x7c927784, _stati64 * buf=0x00000000) Line 184 C
  miniperl.exe!win32_stat(const char * path=0x00a0a388, _stati64 * sbuf=0x0012fce8) Line 1510 + 0xe C
  miniperl.exe!S_check_type_and_open(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3594 + 0xd C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3633 + 0xd C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

+ path 0x00a0a388 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pm" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_ZwQueryDirectoryFile@​44() + 0xc
  kernel32.dll!_FindFirstFileExW@​24() + 0x245
  kernel32.dll!_FindFirstFileA@​8() + 0x3e
  msvcr71.dll!_stati64(const char * name=0x7c927784, _stati64 * buf=0x00000000) Line 184 C
  miniperl.exe!win32_stat(const char * path=0x00a0a388, _stati64 * sbuf=0x0012fce8) Line 1510 + 0xe C
  miniperl.exe!S_check_type_and_open(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3594 + 0xd C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3633 + 0xd C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

+ path 0x00a0a388 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pm" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_NtClose@​4() + 0xc
  kernel32.dll!_FindFirstFileExW@​24() + 0x497
  kernel32.dll!_FindFirstFileA@​8() + 0x3e
  msvcr71.dll!_stati64(const char * name=0x7c927784, _stati64 * buf=0x00000000) Line 184 C
  miniperl.exe!win32_stat(const char * path=0x00a0a388, _stati64 * sbuf=0x0012fce8) Line 1510 + 0xe C
  miniperl.exe!S_check_type_and_open(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3594 + 0xd C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3633 + 0xd C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

+ path 0x00a0a388 "C​:\perl519\src\cpan\AutoLoader\lib/FooLoader.pm" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_NtQueryAttributesFile@​8() + 0xc
  kernel32.dll!_GetFileAttributesW@​4() + 0x67
  kernel32.dll!_GetFileAttributesA@​4() + 0x1d
  miniperl.exe!win32_stat(const char * path=0x00a0a388, _stati64 * sbuf=0x0012fce8) Line 1521 + 0xa C
  miniperl.exe!S_check_type_and_open(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3594 + 0xd C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3633 + 0xd C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

*****************now on a different dir*************************************************
+ path 0x00a049e8 "C​:\perl519\src\dist\Carp\lib/FooLoader.pmc" const char *

---

  ntdll.dll!_KiFastSystemCall@​0() + 0x2
  ntdll.dll!_NtCreateFile@​44() + 0xc
  kernel32.dll!_CreateFileW@​28() + 0x1b6
  kernel32.dll!_CreateFileA@​28() + 0x2b
  miniperl.exe!win32_stat(const char * path=0x00a049e8, _stati64 * sbuf=0x0012fd48) Line 1499 + 0x16 C
  miniperl.exe!S_doopen_pm(interpreter * my_perl=0x009e3fb0, sv * name=0x009e7b30) Line 3630 + 0x43 C
  miniperl.exe!Perl_pp_require(interpreter * my_perl=0x009e3fb0) Line 4011 + 0xd C
  miniperl.exe!Perl_runops_standard(interpreter * my_perl=0x009e3fb0) Line 42 + 0xa C
  miniperl.exe!S_run_body(interpreter * my_perl=0x009e3fb0, long oldscope=0x00000001) Line 2446 + 0xd C
  miniperl.exe!perl_run(interpreter * my_perl=0x009e3fb0) Line 2365 C
  miniperl.exe!main(int argc=0x00000004, char * * argv=0x009e2478, char * * env=0x009e2c90) Line 118 + 0xb C
  miniperl.exe!mainCRTStartup() Line 398 + 0xe C
  kernel32.dll!_BaseProcessStart@​4() + 0x23

---

and the loop continues. Note that by calling all the "SomethingFileMoreSomethingA" function calls, each A call does a ASCII to UTF16 conversion. There goes a lil bit of CPU. Maybe win32_stat should do a utf16 conversion and use only kernel32W() and wclib() calls afterwards which dont convert.

On Thu Jan 30 03​:50​:16 2014, nicholas wrote​:

Thanks for ensuring that the patch gets to the list.

No, specifically it's completely unsafe for a parallel make.

You end up with race conditions where the build fails because one
process
process loads from lib/ a partially written module and aborts, because
it
happens just as another process is copying that file there.
(And the rest of the time you don't have a problem because the file is
either
not in lib, so loaded from the original dist/... etc, or it's fully
copied to
lib, so loaded from there)

Which is exactly what the comment in the file tries to explain.

make_ext has no provisions for parallel building. No select(), no open3. Can you explain?

However, as Win32 doesn't have parallel makes *yet*, and this seems to
be a
big speed hit on Win32, I think that it would be reasonable to do the
proposed re-ordering on Win32, with a comment that it needs to be
rethought
once anyone starts getting parallel makes working on Win32.

What would that process be?

--
bulk88 ~ bulk88 at hotmail.com

[p5pRT]

From @iabyn

On Thu, Jan 30, 2014 at 11​:49​:41AM -0800, bulk88 via RT wrote​:

On Thu Jan 30 05​:30​:31 2014, davem wrote​:

Perhaps this implies that's there's something sub-optimal in the way
perl
does its @​INC scanning under Win32?

Go to the RT ticket through web interface, and look at the
bad_inc_procmon.txt attachment, it contains strace like data with wall
time on the very left. The calls are sniffed by a filter driver that
gets first dibs on all I/O packets (since NT Kernel uses a packetized
(or transactional) async I/O model) coming from user mode.
[snip lots of trace output]
and the loop continues. Note that by calling all the
"SomethingFileMoreSomethingA" function calls, each A call does a ASCII
to UTF16 conversion. There goes a lil bit of CPU. Maybe win32_stat
should do a utf16 conversion and use only kernel32W() and wclib() calls
afterwards which dont convert.

Well, what's not clear to me is whether it's the windows system calls that
have the big overhead, or perl doing stuff like UTF16 conversions. I would
suspect the former.

Other than that, I'm really in a position to contribute further to to this
thread. I know almost zero about Windows APIs, so I have no way of knowing
whether perl is using those APIs inefficiently, or whether Windows is just
slow in this area. Or even whether you just have very slow hardware.

On Thu Jan 30 03​:50​:16 2014, nicholas wrote​:

Thanks for ensuring that the patch gets to the list.

No, specifically it's completely unsafe for a parallel make.

You end up with race conditions where the build fails because one
process
process loads from lib/ a partially written module and aborts, because
it
happens just as another process is copying that file there.
(And the rest of the time you don't have a problem because the file is
either
not in lib, so loaded from the original dist/... etc, or it's fully
copied to
lib, so loaded from there)

Which is exactly what the comment in the file tries to explain.

make_ext has no provisions for parallel building. No select(), no open3. Can you explain?

On UNIX, it is normal to run make with -j N, which will do a parallel
build, with make building up to N targets in parallel. So all the
parallelism is handled by make, not make_ext.

--
If life gives you lemons, you'll probably develop a citric acid allergy.

[p5pRT]

From @bulk88

According to TonyC, "[23​:18] <@​TonyC> bulk88​: WRT #121119 - I wonder if setting ${^WIN32_SLOPPY_STAT} in buildcustomize.pl would make a noticable difference". Note to self to investigate.
--
bulk88 ~ bulk88 at hotmail.com

[p5pRT]

From [Unknown Contact. See original ticket]

According to TonyC, "[23​:18] <@​TonyC> bulk88​: WRT #121119 - I wonder if setting ${^WIN32_SLOPPY_STAT} in buildcustomize.pl would make a noticable difference". Note to self to investigate.
--
bulk88 ~ bulk88 at hotmail.com

[p5pRT]

From @Hugmeir

On Thu, Jan 30, 2014 at 12​:49 PM, Nicholas Clark <nick@​ccl4.org> wrote​:

On Thu, Jan 30, 2014 at 11​:25​:28AM +0000, Dave Mitchell wrote​:

On Thu, Jan 30, 2014 at 12​:13​:16AM -0800, bulk88 via RT wrote​:

See attached patch. Each dir being searched that fails on Win32
results
in 10 I/O sys calls which I counted at 17 ms wall time, times 16
build
customize dirs that didn't match is an extra 272 ms of wall time
dealing
with the not found dirs during an @​INC search. Also as the build
progresses, more and more things will be found on the 1st try in
/lib,
and I presume buildcustomize dirs become totally unused once XS
module
start being built since everything needed for XS building (which is a
PP
process) will be in /lib and found on 1st try.

[snip; this cuts the 'make' time by​: ]

(1656 - 1137) / 60 = 8.65 mins

[snip]

I left the original comment in place for historical reasons. The
comment
might be from something that happened in a Module​::Build module back
when M​::B was in core.

For the convenience of others, here is the original patch​:

diff --git a/write_buildcustomize.pl b/write_buildcustomize.pl
index 64bf4ce..5309988 100644
--- a/write_buildcustomize.pl
+++ b/write_buildcustomize.pl
@​@​ -48,13 +48,18 @​@​ push @​toolchain, 'ext/VMS-Filespec/lib' if $^O eq
'VMS';
unshift @​INC, @​toolchain;
require File​::Spec​::Functions;

+# former comment
+#
# lib must be last, as the toolchain modules write themselves into it
# as they build, and it's important that @​INC order ensures that the
partially
# written files are always masked by the complete versions.

my $inc = join ",\n ",
map { "q\0$_\0" }
- (map {File​::Spec​::Functions​::rel2abs($_)} @​toolchain, 'lib');
+# putting lib first shaves a couple minutes off the build time since
the most
+# common modules like warnings and strict are in lib, and as extensions
are
+# built the chances of the module being found in lib increases
+ (map {File​::Spec​::Functions​::rel2abs($_)} 'lib', @​toolchain);

Before such a patch went in, I think we'd have to be sure that the
reasons
stated in the code for needing to put lib last don't still apply.
Although I'm not very familiar with lib/buildcustomize.pl, it seems to
me
that the reason still stands. Especially on a parallel make, I could
see one instance of miniperl running while another instance is copying
files from ext/Foo to lib, thus allowing it to see empty or truncated
files; or even if the installation of files into lib/ is atomic, a
mixture
of files from the same distro, some in lib, some still under ext/ or
whatever might be seem, and might be harmful.

So this doesn't seem safe to me.

Thanks for ensuring that the patch gets to the list.

No, specifically it's completely unsafe for a parallel make.

You end up with race conditions where the build fails because one process
process loads from lib/ a partially written module and aborts, because it
happens just as another process is copying that file there.
(And the rest of the time you don't have a problem because the file is
either
not in lib, so loaded from the original dist/... etc, or it's fully copied
to
lib, so loaded from there)

Which is exactly what the comment in the file tries to explain.

However, as Win32 doesn't have parallel makes *yet*,

Well, on a technicality, it does​:

http​://perl5.git.perl.org/perl.git/shortlog/refs/heads/hugmeir/cross-compile-win32

Although parallel make on that branch isn't quite functional yet either,
because of some interaction with create_perllibst_h.pl that I haven't
investigated yet, which causes make to abort if run in parallel before
perllib.o is compiled.

I'll be the first to admit that the branch is of dubious value, but if it's
possible not to break it further, that'd be swell.

[p5pRT]

From @Hugmeir

On Mon, Feb 3, 2014 at 5​:54 AM, Brian Fraser <fraserbn@​gmail.com> wrote​:

On Thu, Jan 30, 2014 at 12​:49 PM, Nicholas Clark <nick@​ccl4.org> wrote​:

On Thu, Jan 30, 2014 at 11​:25​:28AM +0000, Dave Mitchell wrote​:

On Thu, Jan 30, 2014 at 12​:13​:16AM -0800, bulk88 via RT wrote​:

See attached patch. Each dir being searched that fails on Win32
results
in 10 I/O sys calls which I counted at 17 ms wall time, times 16
build
customize dirs that didn't match is an extra 272 ms of wall time
dealing
with the not found dirs during an @​INC search. Also as the build
progresses, more and more things will be found on the 1st try in
/lib,
and I presume buildcustomize dirs become totally unused once XS
module
start being built since everything needed for XS building (which is
a
PP
process) will be in /lib and found on 1st try.

[snip; this cuts the 'make' time by​: ]

(1656 - 1137) / 60 = 8.65 mins

[snip]

I left the original comment in place for historical reasons. The
comment
might be from something that happened in a Module​::Build module back
when M​::B was in core.

For the convenience of others, here is the original patch​:

diff --git a/write_buildcustomize.pl b/write_buildcustomize.pl
index 64bf4ce..5309988 100644
--- a/write_buildcustomize.pl
+++ b/write_buildcustomize.pl
@​@​ -48,13 +48,18 @​@​ push @​toolchain, 'ext/VMS-Filespec/lib' if $^O eq
'VMS';
unshift @​INC, @​toolchain;
require File​::Spec​::Functions;

+# former comment
+#
# lib must be last, as the toolchain modules write themselves into it
# as they build, and it's important that @​INC order ensures that the
partially
# written files are always masked by the complete versions.

my $inc = join ",\n ",
map { "q\0$_\0" }
- (map {File​::Spec​::Functions​::rel2abs($_)} @​toolchain, 'lib');
+# putting lib first shaves a couple minutes off the build time since
the most
+# common modules like warnings and strict are in lib, and as
extensions are
+# built the chances of the module being found in lib increases
+ (map {File​::Spec​::Functions​::rel2abs($_)} 'lib', @​toolchain);

Before such a patch went in, I think we'd have to be sure that the
reasons
stated in the code for needing to put lib last don't still apply.
Although I'm not very familiar with lib/buildcustomize.pl, it seems to
me
that the reason still stands. Especially on a parallel make, I could
see one instance of miniperl running while another instance is copying
files from ext/Foo to lib, thus allowing it to see empty or truncated
files; or even if the installation of files into lib/ is atomic, a
mixture
of files from the same distro, some in lib, some still under ext/ or
whatever might be seem, and might be harmful.

So this doesn't seem safe to me.

Thanks for ensuring that the patch gets to the list.

No, specifically it's completely unsafe for a parallel make.

You end up with race conditions where the build fails because one process
process loads from lib/ a partially written module and aborts, because it
happens just as another process is copying that file there.
(And the rest of the time you don't have a problem because the file is
either
not in lib, so loaded from the original dist/... etc, or it's fully
copied to
lib, so loaded from there)

Which is exactly what the comment in the file tries to explain.

However, as Win32 doesn't have parallel makes *yet*,

Well, on a technicality, it does​:

http​://perl5.git.perl.org/perl.git/shortlog/refs/heads/hugmeir/cross-compile-win32

Although parallel make on that branch isn't quite functional yet either,
because of some interaction with create_perllibst_h.pl that I haven't
investigated yet, which causes make to abort if run in parallel before
perllib.o is compiled.

I'll be the first to admit that the branch is of dubious value, but if
it's possible not to break it further, that'd be swell.

Actually, on further thought, making the change only take effect for $^O eq
'MSWin32' would work -- at that point during cross-compilation, miniperl is
not yet pretending to be the target system, so it wouldn't kick in.
So nevermind part of my comment, the change would only affect native builds.

[p5pRT]

From @tonycoz

On Fri Jan 31 03​:31​:05 2014, davem wrote​:

On Thu, Jan 30, 2014 at 11​:49​:41AM -0800, bulk88 via RT wrote​:

On Thu Jan 30 05​:30​:31 2014, davem wrote​:

Perhaps this implies that's there's something sub-optimal in the
way
perl
does its @​INC scanning under Win32?

Go to the RT ticket through web interface, and look at the
bad_inc_procmon.txt attachment, it contains strace like data with
wall
time on the very left. The calls are sniffed by a filter driver that
gets first dibs on all I/O packets (since NT Kernel uses a packetized
(or transactional) async I/O model) coming from user mode.
[snip lots of trace output]
and the loop continues. Note that by calling all the
"SomethingFileMoreSomethingA" function calls, each A call does a
ASCII
to UTF16 conversion. There goes a lil bit of CPU. Maybe win32_stat
should do a utf16 conversion and use only kernel32W() and wclib()
calls
afterwards which dont convert.

Well, what's not clear to me is whether it's the windows system calls
that
have the big overhead, or perl doing stuff like UTF16 conversions. I
would
suspect the former.

win32_stat() does a fair bit to try and emulate a POSIX stat() - including checking for the number of links and making sure file attributes are properly updated for hard links. Unfortunately, setting ${^WIN32_SLOPPY_STAT} to 1 in buildcustomize.pl didn't make much a difference in a rough build benchmark (from 712 to 697 seconds, which is probably just noise, considering I used the machine as my desktop.)

Other than that, I'm really in a position to contribute further to to
this
thread. I know almost zero about Windows APIs, so I have no way of
knowing
whether perl is using those APIs inefficiently, or whether Windows is
just
slow in this area. Or even whether you just have very slow hardware.

I'm not sure why perl builds on Win32 are so slow - I get very fast builds in a VM on the same hardware (eg. a nmake on Win32 took 712 seconds, a Configure + non-parallel make on an Ubuntu VM took 335 seconds).

On UNIX, it is normal to run make with -j N, which will do a parallel
build, with make building up to N targets in parallel. So all the
parallelism is handled by make, not make_ext.

dmake (the tool, not our dmake makefile) supports parallel builds, but from discussing this on IRC, it's not practical since MSVC will attempt to lock the common PDB file and abort if it fails to do so.

Maybe a flag to skip checking for .pmc files would help, but I wouldn't expect require's .pmc checks to be a noticable timesink for typical usage.

Tony