Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[PATCH] remove extra stat() call from .pm opening+remove extra safepath check #14991

Closed
p5pRT opened this issue Oct 16, 2015 · 8 comments
Closed
Labels

Comments

@p5pRT
Copy link

p5pRT commented Oct 16, 2015

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

Searchable as RT126377$

@p5pRT
Copy link
Author

p5pRT commented Oct 16, 2015

From @bulk88

See attached patch.

syscalls before (not the same processes, ignore the carp below)

1​:42​:26.8681992 PM perl.exe 5404 CreateFile C​:\p521\src\lib\strict.pmc NAME NOT FOUND Desired Access​: Read Attributes, Synchronize, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: n/a, ShareMode​: None, AllocationSize​: n/a
1​:42​:26.8683403 PM perl.exe 5404 CreateFile C​:\p521\src\lib SUCCESS Desired Access​: Read Data/List Directory, Synchronize, Disposition​: Open, Options​: Directory, Synchronous IO Non-Alert, Attributes​: n/a, ShareMode​: Read, Write, Delete, AllocationSize​: n/a, OpenResult​: Opened
1​:42​:26.8683649 PM perl.exe 5404 QueryDirectory C​:\p521\src\lib\strict.pmc NO SUCH FILE Filter​: strict.pmc
1​:42​:26.8683820 PM perl.exe 5404 CloseFile C​:\p521\src\lib SUCCESS
1​:42​:26.8685802 PM perl.exe 5404 CreateFile C​:\p521\src\lib\strict.pmc NAME NOT FOUND Desired Access​: Read Attributes, Disposition​: Open, Options​: Open Reparse Point, Attributes​: n/a, ShareMode​: Read, Write, Delete, AllocationSize​: n/a
1​:42​:26.8687024 PM perl.exe 5404 CreateFile C​:\p521\src\lib\strict.pm SUCCESS Desired Access​: Generic Read, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: N, ShareMode​: Read, Write, AllocationSize​: n/a, OpenResult​: Opened
1​:42​:26.8687340 PM perl.exe 5404 QueryInformationVolume C​:\p521\src\lib\strict.pm SUCCESS VolumeCreationTime​: 4/3/2015 7​:53​:02 AM, VolumeSerialNumber​: 50BE-6406, SupportsObjects​: True, VolumeLabel​:
1​:42​:26.8687454 PM perl.exe 5404 QueryAllInformationFile C​:\p521\src\lib\strict.pm BUFFER OVERFLOW CreationTime​: 4/6/2015 4​:28​:26 AM, LastAccessTime​: 4/6/2015 4​:28​:26 AM, LastWriteTime​: 4/6/2015 4​:28​:26 AM, ChangeTime​: 4/6/2015 4​:28​:26 AM, FileAttributes​: A, AllocationSize​: 8,192, EndOfFile​: 4,433, NumberOfLinks​: 1, DeletePending​: False, Directory​: False, IndexNumber​: 0x10000000221e4, EaSize​: 0, Access​: Generic Read, Position​: 0, Mode​: Synchronous IO Non-Alert, AlignmentRequirement​: Word
1​:42​:26.8688048 PM perl.exe 5404 ReadFile C​:\p521\src\lib\strict.pm SUCCESS Offset​: 0, Length​: 4,433, Priority​: Normal
1​:42​:26.8697895 PM perl.exe 5404 CloseFile C​:\p521\src\lib\strict.pm SUCCESS
1​:42​:26.8701209 PM perl.exe 5404 CreateFile C​:\p521\src\lib\warnings.pmc NAME NOT FOUND Desired Access​: Read Attributes, Synchronize, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: n/a, ShareMode​: None, AllocationSize​: n/a
1​:42​:26.8702540 PM perl.exe 5404 CreateFile C​:\p521\src\lib SUCCESS Desired Access​: Read Data/List Directory, Synchronize, Disposition​: Open, Options​: Directory, Synchronous IO Non-Alert, Attributes​: n/a, ShareMode​: Read, Write, Delete, AllocationSize​: n/a, OpenResult​: Opened
1​:42​:26.8702786 PM perl.exe 5404 QueryDirectory C​:\p521\src\lib\warnings.pmc NO SUCH FILE Filter​: warnings.pmc
1​:42​:26.8702962 PM perl.exe 5404 CloseFile C​:\p521\src\lib SUCCESS
1​:42​:26.8704944 PM perl.exe 5404 CreateFile C​:\p521\src\lib\warnings.pmc NAME NOT FOUND Desired Access​: Read Attributes, Disposition​: Open, Options​: Open Reparse Point, Attributes​: n/a, ShareMode​: Read, Write, Delete, AllocationSize​: n/a
1​:42​:26.8706148 PM perl.exe 5404 CreateFile C​:\p521\src\lib\warnings.pm SUCCESS Desired Access​: Generic Read, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: N, ShareMode​: Read, Write, AllocationSize​: n/a, OpenResult​: Opened
1​:42​:26.8706460 PM perl.exe 5404 QueryInformationVolume C​:\p521\src\lib\warnings.pm SUCCESS VolumeCreationTime​: 4/3/2015 7​:53​:02 AM, VolumeSerialNumber​: 50BE-6406, SupportsObjects​: True, VolumeLabel​:
1​:42​:26.8706574 PM perl.exe 5404 QueryAllInformationFile C​:\p521\src\lib\warnings.pm BUFFER OVERFLOW CreationTime​: 4/6/2015 4​:28​:26 AM, LastAccessTime​: 10/14/2015 4​:47​:08 AM, LastWriteTime​: 10/14/2015 4​:47​:08 AM, ChangeTime​: 10/14/2015 4​:47​:08 AM, FileAttributes​: A, AllocationSize​: 45,056, EndOfFile​: 44,181, NumberOfLinks​: 1, DeletePending​: False, Directory​: False, IndexNumber​: 0x9000000021f6c, EaSize​: 0, Access​: Generic Read, Position​: 0, Mode​: Synchronous IO Non-Alert, AlignmentRequirement​: Word
1​:42​:26.8709734 PM perl.exe 5404 ReadFile C​:\p521\src\lib\warnings.pm SUCCESS Offset​: 0, Length​: 8,192, Priority​: Normal
1​:42​:26.8726811 PM perl.exe 5404 ReadFile C​:\p521\src\lib\warnings.pm SUCCESS Offset​: 8,192, Length​: 8,192
1​:42​:26.8740025 PM perl.exe 5404 ReadFile C​:\p521\src\lib\warnings.pm SUCCESS Offset​: 16,384, Length​: 8,192
1​:42​:26.8773839 PM perl.exe 5404 CloseFile C​:\p521\src\lib\warnings.pm SUCCESS

after

3​:53​:21.5922283 PM perl.exe 1076 CreateFile C​:\p521\src\lib\strict.pmc NAME NOT FOUND Desired Access​: Generic Read, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: N, ShareMode​: Read, Write, AllocationSize​: n/a
3​:53​:21.5923575 PM perl.exe 1076 CreateFile C​:\p521\src\lib\strict.pm SUCCESS Desired Access​: Generic Read, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: N, ShareMode​: Read, Write, AllocationSize​: n/a, OpenResult​: Opened
3​:53​:21.5923918 PM perl.exe 1076 QueryInformationVolume C​:\p521\src\lib\strict.pm SUCCESS VolumeCreationTime​: 4/3/2015 7​:53​:02 AM, VolumeSerialNumber​: 50BE-6406, SupportsObjects​: True, VolumeLabel​:
3​:53​:21.5924032 PM perl.exe 1076 QueryAllInformationFile C​:\p521\src\lib\strict.pm BUFFER OVERFLOW CreationTime​: 4/6/2015 4​:28​:26 AM, LastAccessTime​: 4/6/2015 4​:28​:26 AM, LastWriteTime​: 4/6/2015 4​:28​:26 AM, ChangeTime​: 4/6/2015 4​:28​:26 AM, FileAttributes​: A, AllocationSize​: 8,192, EndOfFile​: 4,433, NumberOfLinks​: 1, DeletePending​: False, Directory​: False, IndexNumber​: 0x10000000221e4, EaSize​: 0, Access​: Generic Read, Position​: 0, Mode​: Synchronous IO Non-Alert, AlignmentRequirement​: Word
3​:53​:21.5933050 PM perl.exe 1076 ReadFile C​:\p521\src\lib\strict.pm SUCCESS Offset​: 0, Length​: 4,433, Priority​: Normal
3​:53​:21.5941975 PM perl.exe 1076 CloseFile C​:\p521\src\lib\strict.pm SUCCESS
3​:53​:21.5946167 PM perl.exe 1076 CreateFile C​:\p521\src\lib\Carp.pmc NAME NOT FOUND Desired Access​: Generic Read, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: N, ShareMode​: Read, Write, AllocationSize​: n/a
3​:53​:21.5947670 PM perl.exe 1076 CreateFile C​:\p521\src\lib\Carp.pm SUCCESS Desired Access​: Generic Read, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: N, ShareMode​: Read, Write, AllocationSize​: n/a, OpenResult​: Opened
3​:53​:21.5948039 PM perl.exe 1076 QueryInformationVolume C​:\p521\src\lib\Carp.pm SUCCESS VolumeCreationTime​: 4/3/2015 7​:53​:02 AM, VolumeSerialNumber​: 50BE-6406, SupportsObjects​: True, VolumeLabel​:
3​:53​:21.5948166 PM perl.exe 1076 QueryAllInformationFile C​:\p521\src\lib\Carp.pm BUFFER OVERFLOW CreationTime​: 10/16/2015 3​:19​:46 PM, LastAccessTime​: 10/14/2015 4​:47​:08 AM, LastWriteTime​: 10/14/2015 4​:47​:08 AM, ChangeTime​: 10/16/2015 3​:19​:46 PM, FileAttributes​: RA, AllocationSize​: 32,768, EndOfFile​: 30,415, NumberOfLinks​: 1, DeletePending​: False, Directory​: False, IndexNumber​: 0x300000004bbee, EaSize​: 0, Access​: Generic Read, Position​: 0, Mode​: Synchronous IO Non-Alert, AlignmentRequirement​: Word
3​:53​:21.5964716 PM perl.exe 1076 ReadFile C​:\p521\src\lib\Carp.pm SUCCESS Offset​: 0, Length​: 8,192, Priority​: Normal
3​:53​:21.5968780 PM perl.exe 1076 CreateFile C​:\p521\src\lib\warnings.pmc NAME NOT FOUND Desired Access​: Generic Read, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: N, ShareMode​: Read, Write, AllocationSize​: n/a
3​:53​:21.5970068 PM perl.exe 1076 CreateFile C​:\p521\src\lib\warnings.pm SUCCESS Desired Access​: Generic Read, Disposition​: Open, Options​: Synchronous IO Non-Alert, Non-Directory File, Attributes​: N, ShareMode​: Read, Write, AllocationSize​: n/a, OpenResult​: Opened
3​:53​:21.5970415 PM perl.exe 1076 QueryInformationVolume C​:\p521\src\lib\warnings.pm SUCCESS VolumeCreationTime​: 4/3/2015 7​:53​:02 AM, VolumeSerialNumber​: 50BE-6406, SupportsObjects​: True, VolumeLabel​:
3​:53​:21.5970534 PM perl.exe 1076 QueryAllInformationFile C​:\p521\src\lib\warnings.pm BUFFER OVERFLOW CreationTime​: 4/6/2015 4​:28​:26 AM, LastAccessTime​: 10/14/2015 4​:47​:08 AM, LastWriteTime​: 10/14/2015 4​:47​:08 AM, ChangeTime​: 10/14/2015 4​:47​:08 AM, FileAttributes​: A, AllocationSize​: 45,056, EndOfFile​: 44,181, NumberOfLinks​: 1, DeletePending​: False, Directory​: False, IndexNumber​: 0x9000000021f6c, EaSize​: 0, Access​: Generic Read, Position​: 0, Mode​: Synchronous IO Non-Alert, AlignmentRequirement​: Word
3​:53​:21.6022036 PM perl.exe 1076 ReadFile C​:\p521\src\lib\warnings.pm SUCCESS Offset​: 0, Length​: 8,192, Priority​: Normal
3​:53​:21.6042250 PM perl.exe 1076 ReadFile C​:\p521\src\lib\warnings.pm SUCCESS Offset​: 8,192, Length​: 8,192
3​:53​:21.6055179 PM perl.exe 1076 ReadFile C​:\p521\src\lib\warnings.pm SUCCESS Offset​: 16,384, Length​: 8,192
3​:53​:21.6089578 PM perl.exe 1076 CloseFile C​:\p521\src\lib\warnings.pm SUCCESS

 

@p5pRT
Copy link
Author

p5pRT commented Oct 16, 2015

From @bulk88

0001-remove-extra-stat-call-from-.pm-opening-remove-extra.patch
From 20a88012e06e1e416b4a8de4f10a0c79ad603383 Mon Sep 17 00:00:00 2001
From: Daniel Dragan <bulk88@hotmail.com>
Date: Fri, 16 Oct 2015 17:40:38 -0400
Subject: [PATCH] remove extra stat() call from .pm opening+remove extra
 safepath check

Originally S_doopen_pm had 2 stat calls, one on the .pm path, and another
on the .pmc, to get mtimes of both. Commit a91233bf4c "Load .pmc always,
even if they are older than a matching .pm file." (see
http://www.nntp.perl.org/group/perl.perl5.porters/2006/03/msg110639.html )
got rid of one of the stat calls but the other was left in place, possibly
as an oversight. S_check_type_and_open itself does another stat call on
unix to check for bad kinds of FS entries (reading a dir as a file), so
assuming someone used .pmc files, a good .pmc would be stat, stat,
open instead of the ideal, stat, open. Remove the extra stat from
S_doopen_pm for efficiency. Since the timestamp compare was removed, the
role of S_doopen_pm has been to verify an attempted path is acceptable to
pass to the FS (no IO done), and generate a .pmc path (no IO done), the
IO side of thing is in S_check_type_and_open, it shouldn't be in
S_doopen_pm.

On Win32, on a no .pmc build, an open is directly done on the attempted
.pm path for efficiency, no stat is done normally (see commit d345f48775
"Win32: stat() only after a failed open() on a module"). Before this patch
the .pmc attempted path got a stat which on Win32 is more than 1 IO call,
compared to Win32 open which is 1 IO call. With this patch, the Win32
specific IO logic in S_check_type_and_open executes instead of a generic
Win32 stat so there is just 1 failing IO call for file not found (typical
case for .pmc) instead of multiple file not found IO calls. See ticket for
details.

When .pmc files are enabled (enabled is default), 2 checks for bad null
char paths were done, once in S_doopen_pm, then again in lower level
S_check_type_and_open. Do the check only once in the higher level call
(S_doopen_pm) for efficiency, there is no way for string "c" which is
catted on to contain a null. There was an existing comment refering to
the problem of a low level check for null returning a message about a
".pmc" instead of a ".pm", so that is another reason to do it at a higher
level. Note on no PMC builds, S_check_type_and_open replaces S_doopen_pm
and still must do the check.
---
 pp_ctl.c | 12 ++++++++----
 1 file changed, 8 insertions(+), 4 deletions(-)

diff --git a/pp_ctl.c b/pp_ctl.c
index 1333be8..cdbdbd0 100644
--- a/pp_ctl.c
+++ b/pp_ctl.c
@@ -3481,11 +3481,14 @@ S_check_type_and_open(pTHX_ SV *name)
     /* checking here captures a reasonable error message when
      * PERL_DISABLE_PMC is true, but when PMC checks are enabled, the
      * user gets a confusing message about looking for the .pmc file
-     * rather than for the .pm file.
+     * rather than for the .pm file so do the check in S_doopen_pm when
+     * PMC is on instead of here. S_doopen_pm calls this func.
      * This check prevents a \0 in @INC causing problems.
      */
+#ifdef PERL_DISABLE_PMC
     if (!IS_SAFE_PATHNAME(p, len, "require"))
         return NULL;
+#endif
 
     /* on Win32 stat is expensive (it does an open() and close() twice and
        a couple other IO calls), the open will fail with a dir on its own with
@@ -3541,13 +3544,14 @@ S_doopen_pm(pTHX_ SV *name)
 
     if (namelen > 3 && memEQs(p + namelen - 3, 3, ".pm")) {
 	SV *const pmcsv = sv_newmortal();
-	Stat_t pmcstat;
+	PerlIO * pmcio;
 
 	SvSetSV_nosteal(pmcsv,name);
 	sv_catpvs(pmcsv, "c");
 
-	if (PerlLIO_stat(SvPV_nolen_const(pmcsv), &pmcstat) >= 0)
-	    return check_type_and_open(pmcsv);
+	pmcio = check_type_and_open(pmcsv);
+	if (pmcio)
+	    return pmcio;
     }
     return check_type_and_open(name);
 }
-- 
1.9.5.msysgit.1

@p5pRT
Copy link
Author

p5pRT commented Oct 17, 2015

From @jkeenan

On Fri Oct 16 14​:51​:29 2015, bulk88 wrote​:

See attached patch.

1. Does no harm on Linux. Smoke-testing in smoke-me/jkeenan/bulk88/126377-remove-extra-stat-call.

2. bulk88, the performance data you present below is interesting but difficult to absorb quickly in an inline format which changes tabs to whitespace. Would it be possible for you to save the data to .tsv or .csv files and attach to the RT?

Thank you very much.
Jim Keenan

syscalls before (not the same processes, ignore the carp below)

1​:42​:26.8681992 PM perl.exe 5404 CreateFile
C​:\p521\src\lib\strict.pmc NAME NOT FOUND Desired Access​: Read
Attributes, Synchronize, Disposition​: Open, Options​: Synchronous IO
Non-Alert, Non-Directory File, Attributes​: n/a, ShareMode​: None,
AllocationSize​: n/a

[snip]

--
James E Keenan (jkeenan@​cpan.org)

@p5pRT
Copy link
Author

p5pRT commented Oct 17, 2015

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

@p5pRT
Copy link
Author

p5pRT commented Oct 17, 2015

From @bulk88

On Sat Oct 17 05​:09​:42 2015, jkeenan wrote​:

On Fri Oct 16 14​:51​:29 2015, bulk88 wrote​:

See attached patch.

1. Does no harm on Linux. Smoke-testing in smoke-
me/jkeenan/bulk88/126377-remove-extra-stat-call.

2. bulk88, the performance data you present below is interesting but
difficult to absorb quickly in an inline format which changes tabs to
whitespace. Would it be possible for you to save the data to .tsv or
.csv files and attach to the RT?

The original data is gone (closed the window).

The CSV looked more unreadable because the columns were not lined up than the format I pasted it in. It looked fine in my webmail editor (my normal email prog is down ATM). I can post CSV logs as separate files but I just think they are more unreadable. Any consensus on whether to post CSV or space/tab padded logs?

If you click on "Download (untitled)" next to "text/plain 9.5k" on the OP, whose link is https://rt-archive.perl.org/perl5/Ticket/Attachment/1371067/735368/ it is readable and sort of aligned, you might have to zoom out with your browser to decrease the line wrapping.

--
bulk88 ~ bulk88 at hotmail.com

@p5pRT
Copy link
Author

p5pRT commented Oct 18, 2015

From @Tux

On Sat, 17 Oct 2015 14​:02​:07 -0700, "bulk88 via RT"
<perlbug-followup@​perl.org> wrote​:

On Sat Oct 17 05​:09​:42 2015, jkeenan wrote​:

On Fri Oct 16 14​:51​:29 2015, bulk88 wrote​:

See attached patch.

2. bulk88, the performance data you present below is interesting but
difficult to absorb quickly in an inline format which changes tabs to
whitespace. Would it be possible for you to save the data to .tsv or
.csv files and attach to the RT?

The original data is gone (closed the window).

The CSV looked more unreadable because the columns were not lined up
than the format I pasted it in. It looked fine in my webmail editor
(my normal email prog is down ATM). I can post CSV logs as separate
files but I just think they are more unreadable. Any consensus on
whether to post CSV or space/tab padded logs?

<shameless plug>

$ cpan Text​::CSV_XS Spreadsheet​::Read
$ cat test.csv
id,count,desc,asc,row
1,2,foo,bar,10
$ xlscat -L test.csv
  5 x 2
id|count|desc|asc|row
1 |2 |foo |bar|10

</shameless plug>

if you have X and perl/Tk

$ csv2tk test.csv

If you click on "Download (untitled)" next to "text/plain 9.5k" on
the OP, whose link is
https://rt-archive.perl.org/perl5/Ticket/Attachment/1371067/735368/ it is readable
and sort of aligned, you might have to zoom out with your browser to
decrease the line wrapping.

--
H.Merijn Brand http​://tux.nl Perl Monger http​://amsterdam.pm.org/
using perl5.00307 .. 5.21 porting perl5 on HP-UX, AIX, and openSUSE
http​://mirrors.develooper.com/hpux/ http​://www.test-smoke.org/
http​://qa.perl.org http​://www.goldmark.org/jeff/stupid-disclaimers/

@p5pRT
Copy link
Author

p5pRT commented Oct 19, 2015

From @tonycoz

On Fri Oct 16 14​:51​:29 2015, bulk88 wrote​:

See attached patch.

Thanks, applied as 1e77749.

Tony

@p5pRT p5pRT closed this as completed Oct 19, 2015
@p5pRT
Copy link
Author

p5pRT commented Oct 19, 2015

@tonycoz - Status changed from 'open' to 'resolved'

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

1 participant