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

p5pRT commented 8 years ago

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

Searchable as RT126377$

p5pRT commented 8 years ago

From @bulk88

See attached patch.

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

1:42:26.8681992 PM 1:42:26.8683403 PM 1:42:26.8683649 PM 1:42:26.8683820 PM 1:42:26.8685802 PM 1:42:26.8687024 PM 1:42:26.8687340 PM 1:42:26.8687454 PM 1:42:26.8688048 PM 1:42:26.8697895 PM 1:42:26.8701209 PM 1:42:26.8702540 PM 1:42:26.8702786 PM 1:42:26.8702962 PM 1:42:26.8704944 PM 1:42:26.8706148 PM 1:42:26.8706460 PM 1:42:26.8706574 PM 1:42:26.8709734 PM 1:42:26.8726811 PM 1:42:26.8740025 PM 1:42:26.8773839 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 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 perl.exe 5404 QueryDirectory C:\p521\src\lib\strict.pmc NO SUCH FILE Filter: strict.pmc perl.exe 5404 CloseFile C:\p521\src\lib SUCCESS
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 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 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: 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 perl.exe 5404 ReadFile C:\p521\src\lib\strict.pm SUCCESS Offset: 0\, Length: 4\,433\, Priority: Normal perl.exe 5404 CloseFile C:\p521\src\lib\strict.pm SUCCESS
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 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 perl.exe 5404 QueryDirectory C:\p521\src\lib\warnings.pmc NO SUCH FILE Filter: warnings.pmc perl.exe 5404 CloseFile C:\p521\src\lib SUCCESS
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 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 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: 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 perl.exe 5404 ReadFile C:\p521\src\lib\warnings.pm SUCCESS Offset: 0\, Length: 8\,192\, Priority: Normal perl.exe 5404 ReadFile C:\p521\src\lib\warnings.pm SUCCESS Offset: 8\,192\, Length: 8\,192 perl.exe 5404 ReadFile C:\p521\src\lib\warnings.pm SUCCESS Offset: 16\,384\, Length: 8\,192 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 commented 8 years ago

From @bulk88

0001-remove-extra-stat-call-from-.pm-opening-remove-extra.patch

```diff From 20a88012e06e1e416b4a8de4f10a0c79ad603383 Mon Sep 17 00:00:00 2001 From: Daniel Dragan 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 commented 8 years ago

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 commented 8 years ago

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

p5pRT commented 8 years ago

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 commented 8 years ago

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?

\

$ 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 commented 8 years ago

From @tonycoz

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

See attached patch.

Thanks\, applied as 1e777496fd51e7d05020c0f05a4f2e19f2a3148d.

Tony

p5pRT commented 8 years ago

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

Perl / perl5