← Index
NYTProf Performance Profile   « line view »
For /Users/brian/bin/perls/cpan5.26.1
  Run on Sat Dec 30 01:41:10 2017
Reported on Sat Dec 30 01:44:15 2017

Filename/usr/local/perls/perl-5.26.1/lib/5.26.1/CPAN/CacheMgr.pm
StatementsExecuted 97164 statements in 800ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
134031223ms223msCPAN::CacheMgr::::CORE:ftfileCPAN::CacheMgr::CORE:ftfile (opcode)
1432231165ms258msCPAN::CacheMgr::::__ANON__[:136]CPAN::CacheMgr::__ANON__[:136]
143221184.0ms84.0msCPAN::CacheMgr::::CORE:ftlinkCPAN::CacheMgr::CORE:ftlink (opcode)
6121165.3ms54.2sCPAN::CacheMgr::::_clean_cacheCPAN::CacheMgr::_clean_cache
118721164.4ms64.4msCPAN::CacheMgr::::CORE:ftmtimeCPAN::CacheMgr::CORE:ftmtime (opcode)
11130.4ms94.8msCPAN::CacheMgr::::CORE:sortCPAN::CacheMgr::CORE:sort (opcode)
1141127.7ms27.7msCPAN::CacheMgr::::CORE:unlinkCPAN::CacheMgr::CORE:unlink (opcode)
7192126.5ms1.59sCPAN::CacheMgr::::disk_usageCPAN::CacheMgr::disk_usage
11119.5ms54.3sCPAN::CacheMgr::::tidyupCPAN::CacheMgr::tidyup
13312118.1ms18.1msCPAN::CacheMgr::::CORE:ftisCPAN::CacheMgr::CORE:ftis (opcode)
11112.9ms338msCPAN::CacheMgr::::entriesCPAN::CacheMgr::entries
15633417.91ms7.91msCPAN::CacheMgr::::CORE:ftdirCPAN::CacheMgr::CORE:ftdir (opcode)
2948215.62ms5.62msCPAN::CacheMgr::::CORE:fteexecCPAN::CacheMgr::CORE:fteexec (opcode)
1115.48ms56.2sCPAN::CacheMgr::::scan_cacheCPAN::CacheMgr::scan_cache
11965113.65ms3.65msCPAN::CacheMgr::::CORE:ftsizeCPAN::CacheMgr::CORE:ftsize (opcode)
499212.69ms2.69msCPAN::CacheMgr::::CORE:matchCPAN::CacheMgr::CORE:match (opcode)
11194µs56.2sCPAN::CacheMgr::::newCPAN::CacheMgr::new
1114µs4µsCPAN::CacheMgr::::dirCPAN::CacheMgr::dir
0000s0sCPAN::CacheMgr::::BEGINCPAN::CacheMgr::BEGIN
0000s0sCPAN::CacheMgr::::as_stringCPAN::CacheMgr::as_string
0000s0sCPAN::CacheMgr::::cachesizeCPAN::CacheMgr::cachesize
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
1# -*- Mode: cperl; coding: utf-8; cperl-indent-level: 4 -*-
2# vim: ts=4 sts=4 sw=4:
3package CPAN::CacheMgr;
4use strict;
5use CPAN::InfoObj;
6@CPAN::CacheMgr::ISA = qw(CPAN::InfoObj CPAN);
7use Cwd qw(chdir);
8use File::Find;
9
10use vars qw(
11 $VERSION
12);
13$VERSION = "5.5002";
14
15package CPAN::CacheMgr;
16use strict;
17
18#-> sub CPAN::CacheMgr::as_string ;
19sub as_string {
20 eval { require Data::Dumper };
21 if ($@) {
22 return shift->SUPER::as_string;
23 } else {
24 return Data::Dumper::Dumper(shift);
25 }
26}
27
28#-> sub CPAN::CacheMgr::cachesize ;
29sub cachesize {
30 shift->{DU};
31}
32
33#-> sub CPAN::CacheMgr::tidyup ;
34
# spent 54.3s (19.5ms+54.3) within CPAN::CacheMgr::tidyup which was called: # once (19.5ms+54.3s) by CPAN::CacheMgr::scan_cache at line 246
sub tidyup {
3510s my($self) = @_;
3612µs return unless $CPAN::META->{LOCK};
37127µs113µs return unless -d $self->{ID};
# spent 13µs making 1 call to CPAN::CacheMgr::CORE:ftdir
381478µs my @toremove = grep { $self->{SIZE}{$_}==0 } @{$self->{FIFO}};
39119µs for my $current (0..$#toremove) {
406121.02ms my $toremove = $toremove[$current];
4161211.2ms61273.4ms $CPAN::Frontend->myprint(sprintf(
# spent 73.4ms making 612 calls to App::Cpan::__ANON__[App/Cpan.pm:673], avg 120µs/call
42 "DEL(%d/%d): %s \n",
43 $current+1,
44 scalar @toremove,
45 $toremove,
46 )
47 );
48612289µs return if $CPAN::Signal;
496123.08ms61254.2s $self->_clean_cache($toremove);
# spent 54.2s making 612 calls to CPAN::CacheMgr::_clean_cache, avg 88.6ms/call
50612995µs return if $CPAN::Signal;
51 }
521585µs $self->{FIFO} = [];
53}
54
55#-> sub CPAN::CacheMgr::dir ;
56
# spent 4µs within CPAN::CacheMgr::dir which was called: # once (4µs+0s) by CPAN::Distribution::run_preps_on_packagedir at line 471 of CPAN/Distribution.pm
sub dir {
57141µs shift->{ID};
58}
59
60#-> sub CPAN::CacheMgr::entries ;
61
# spent 338ms (12.9+325) within CPAN::CacheMgr::entries which was called: # once (12.9ms+325ms) by CPAN::CacheMgr::scan_cache at line 227
sub entries {
6211µs my($self,$dir) = @_;
6310s return unless defined $dir;
6410s $self->debug("reading dir[$dir]") if $CPAN::DEBUG;
6511µs $dir ||= $self->{ID};
6616µs15.21ms my($cwd) = CPAN::anycwd();
# spent 5.21ms making 1 call to CPAN::anycwd
67111µs171µs chdir $dir or Carp::croak("Can't chdir to $dir: $!");
# spent 71µs making 1 call to Cwd::chdir
68135µs2181µs my $dh = DirHandle->new(File::Spec->curdir)
# spent 174µs making 1 call to DirHandle::new # spent 7µs making 1 call to File::Spec::Unix::curdir
69 or Carp::croak("Couldn't opendir $dir: $!");
7011µs my(@entries);
711161µs16.86ms for ($dh->read) {
# spent 6.86ms making 1 call to DirHandle::read
72721341µs next if $_ eq "." || $_ eq "..";
73719220ms1310211ms if (-f $_) {
# spent 210ms making 719 calls to CPAN::CacheMgr::CORE:ftfile, avg 293µs/call # spent 371µs making 591 calls to CPAN::CacheMgr::CORE:ftdir, avg 628ns/call
741282.43ms5122.94ms push @entries, File::Spec->catfile($dir,$_);
# spent 2.00ms making 128 calls to File::Spec::Unix::catfile, avg 16µs/call # spent 656µs making 128 calls to File::Spec::Unix::catdir, avg 5µs/call # spent 287µs making 256 calls to File::Spec::Unix::canonpath, avg 1µs/call
75 } elsif (-d _) {
765916.83ms11825.78ms push @entries, File::Spec->catdir($dir,$_);
# spent 4.94ms making 591 calls to File::Spec::Unix::catdir, avg 8µs/call # spent 849µs making 591 calls to File::Spec::Unix::canonpath, avg 1µs/call
77 } else {
78 $CPAN::Frontend->mywarn("Warning: weird direntry in $dir: $_\n");
79 }
80 }
8115µs156µs chdir $cwd or Carp::croak("Can't chdir to $cwd: $!");
# spent 56µs making 1 call to Cwd::chdir
82195.0ms11874159ms sort { -M $a <=> -M $b} @entries;
# spent 94.8ms making 1 call to CPAN::CacheMgr::CORE:sort # spent 64.4ms making 11872 calls to CPAN::CacheMgr::CORE:ftmtime, avg 5µs/call # spent 48µs making 1 call to DirHandle::DESTROY
83}
84
85#-> sub CPAN::CacheMgr::disk_usage ;
86
# spent 1.59s (26.5ms+1.56) within CPAN::CacheMgr::disk_usage which was called 719 times, avg 2.21ms/call: # 612 times (14.1ms+12.4ms) by CPAN::CacheMgr::scan_cache at line 234, avg 43µs/call # 107 times (12.3ms+1.55s) by CPAN::CacheMgr::scan_cache at line 236, avg 14.6ms/call
sub disk_usage {
87719498µs my($self,$dir,$fast) = @_;
88719445µs return if exists $self->{SIZE}{$dir};
89719100µs return if $CPAN::Signal;
90719213µs my($Du) = 0;
917198.28ms7196.08ms if (-e $dir) {
# spent 6.08ms making 719 calls to CPAN::CacheMgr::CORE:ftis, avg 8µs/call
9271915.3ms8474.94ms if (-d $dir) {
# spent 4.18ms making 719 calls to CPAN::CacheMgr::CORE:ftdir, avg 6µs/call # spent 757µs making 128 calls to CPAN::CacheMgr::CORE:ftfile, avg 6µs/call
935917.98ms5913.55ms unless (-x $dir) {
# spent 3.55ms making 591 calls to CPAN::CacheMgr::CORE:fteexec, avg 6µs/call
94 unless (chmod 0755, $dir) {
95 $CPAN::Frontend->mywarn("I have neither the -x permission nor the ".
96 "permission to change the permission; cannot ".
97 "estimate disk usage of '$dir'\n");
98 $CPAN::Frontend->mysleep(5);
99 return;
100 }
101 }
102 } elsif (-f $dir) {
103 # nothing to say, no matter what the permissions
104 }
105 } else {
106 $CPAN::Frontend->mywarn("File or directory '$dir' has gone, ignoring\n");
107 return;
108 }
109719968µs if ($fast) {
110 $Du = 0; # placeholder
111 } else {
112 find(
113
# spent 258ms (165+93.1) within CPAN::CacheMgr::__ANON__[/usr/local/perls/perl-5.26.1/lib/5.26.1/CPAN/CacheMgr.pm:136] which was called 14322 times, avg 18µs/call: # 11956 times (139ms+75.8ms) by File::Find::_find_dir at line 448 of File/Find.pm, avg 18µs/call # 2357 times (25.8ms+17.2ms) by File::Find::_find_dir at line 358 of File/Find.pm, avg 18µs/call # 9 times (72µs+66µs) by File::Find::_find_opt at line 270 of File/Find.pm, avg 15µs/call
sub {
114143221.98ms $File::Find::prune++ if $CPAN::Signal;
11514322128ms1432284.0ms return if -l $_;
# spent 84.0ms making 14322 calls to CPAN::CacheMgr::CORE:ftlink, avg 6µs/call
1161432267.0ms if ($^O eq 'MacOS') {
117 require Mac::Files;
118 my $cat = Mac::Files::FSpGetCatInfo($_);
119 $Du += $cat->ioFlLgLen() + $cat->ioFlRLgLen() if $cat;
120 } else {
1211432242.2ms143223.34ms if (-d _) {
# spent 3.34ms making 14322 calls to CPAN::CacheMgr::CORE:ftdir, avg 233ns/call
122235713.7ms23572.07ms unless (-x _) {
# spent 2.07ms making 2357 calls to CPAN::CacheMgr::CORE:fteexec, avg 880ns/call
123 unless (chmod 0755, $_) {
124 $CPAN::Frontend->mywarn("I have neither the -x permission nor ".
125 "the permission to change the permission; ".
126 "can only partially estimate disk usage ".
127 "of '$_'\n");
128 $CPAN::Frontend->mysleep(5);
129 return;
130 }
131 }
132 } else {
1331196535.7ms119653.65ms $Du += (-s _);
# spent 3.65ms making 11965 calls to CPAN::CacheMgr::CORE:ftsize, avg 305ns/call
134 }
135 }
136 },
137107850µs1071.55s $dir
# spent 1.55s making 107 calls to File::Find::find, avg 14.5ms/call
138 );
139 }
140719106µs return if $CPAN::Signal;
1417193.37ms $self->{SIZE}{$dir} = $Du/1024/1024;
1427191.08ms unshift @{$self->{FIFO}}, $dir;
143719124µs $self->debug("measured $dir is $Du") if $CPAN::DEBUG;
144719456µs $self->{DU} += $Du/1024/1024;
1457192.02ms $self->{DU};
146}
147
148#-> sub CPAN::CacheMgr::_clean_cache ;
149
# spent 54.2s (65.3ms+54.1) within CPAN::CacheMgr::_clean_cache which was called 612 times, avg 88.6ms/call: # 612 times (65.3ms+54.1s) by CPAN::CacheMgr::tidyup at line 49, avg 88.6ms/call
sub _clean_cache {
150612787µs my($self,$dir) = @_;
15161226.7ms61212.0ms return unless -e $dir;
# spent 12.0ms making 612 calls to CPAN::CacheMgr::CORE:ftis, avg 20µs/call
15249826.4ms149454.4ms unless (File::Spec->canonpath(File::Basename::dirname($dir))
# spent 51.7ms making 498 calls to File::Basename::dirname, avg 104µs/call # spent 2.66ms making 996 calls to File::Spec::Unix::canonpath, avg 3µs/call
153 eq File::Spec->canonpath($CPAN::Config->{build_dir})) {
154 $CPAN::Frontend->mywarn("Directory '$dir' not below $CPAN::Config->{build_dir}, ".
155 "will not remove\n");
156 $CPAN::Frontend->mysleep(5);
157 return;
158 }
159498324µs $self->debug("have to rmtree $dir, will free $self->{SIZE}{$dir}")
160 if $CPAN::DEBUG;
1614982.33ms49854.0s File::Path::rmtree($dir);
# spent 54.0s making 498 calls to File::Path::rmtree, avg 108ms/call
162498447µs my $id_deleted = 0;
16349827.9ms99114.5ms if ($dir !~ /\.yml$/ && -f "$dir.yml") {
# spent 11.8ms making 493 calls to CPAN::CacheMgr::CORE:ftfile, avg 24µs/call # spent 2.68ms making 498 calls to CPAN::CacheMgr::CORE:match, avg 5µs/call
164114652µs11419.2ms my $yaml_module = CPAN::_yaml_module();
# spent 19.2ms making 114 calls to CPAN::_yaml_module, avg 169µs/call
165114380µs1149.57ms if ($CPAN::META->has_inst($yaml_module)) {
# spent 9.57ms making 114 calls to CPAN::has_inst, avg 84µs/call
166 my($peek_yaml) = eval { CPAN->_yaml_loadfile("$dir.yml"); };
167 if ($@) {
168 $CPAN::Frontend->mywarn("(parse error on '$dir.yml' removing anyway)");
169 unlink "$dir.yml" or
170 $CPAN::Frontend->mywarn("(Could not unlink '$dir.yml': $!)");
171 return;
172 } elsif (my $id = $peek_yaml->[0]{distribution}{ID}) {
173 $CPAN::META->delete("CPAN::Distribution", $id);
174
175 # XXX we should restore the state NOW, otherwise this
176 # distro does not exist until we read an index. BUG ALERT(?)
177
178 # $CPAN::Frontend->mywarn (" +++\n");
179 $id_deleted++;
180 }
181 }
18211428.7ms11427.7ms unlink "$dir.yml"; # may fail
# spent 27.7ms making 114 calls to CPAN::CacheMgr::CORE:unlink, avg 243µs/call
1831141.46ms11415.7ms unless ($id_deleted) {
# spent 15.7ms making 114 calls to CPAN::Debug::debug, avg 137µs/call
184 CPAN->debug("no distro found associated with '$dir'");
185 }
186 }
1874981.75ms $self->{DU} -= $self->{SIZE}{$dir};
1884985.08ms delete $self->{SIZE}{$dir};
189}
190
191#-> sub CPAN::CacheMgr::new ;
192
# spent 56.2s (94µs+56.2) within CPAN::CacheMgr::new which was called: # once (94µs+56.2s) by CPAN::Distribution::run_preps_on_packagedir at line 470 of CPAN/Distribution.pm
sub new {
19311µs my($class,$phase) = @_;
19411µs $phase ||= "atstart";
19511µs my $time = time;
19610s my($debug,$t2);
19711µs $debug = "";
198 my $self = {
199 ID => $CPAN::Config->{build_dir},
200 MAX => $CPAN::Config->{'build_cache'},
20115µs SCAN => $CPAN::Config->{'scan_cache'} || 'atstart',
202 DU => 0
203 };
204 $CPAN::Frontend->mydie("Unknown scan_cache argument: $self->{SCAN}")
205118µs110µs unless $self->{SCAN} =~ /never|atstart|atexit/;
# spent 10µs making 1 call to CPAN::CacheMgr::CORE:match
20612µs154µs File::Path::mkpath($self->{ID});
# spent 54µs making 1 call to File::Path::mkpath
20716µs153µs my $dh = DirHandle->new($self->{ID});
# spent 53µs making 1 call to DirHandle::new
20815µs bless $self, $class;
20913µs156.2s $self->scan_cache($phase);
# spent 56.2s making 1 call to CPAN::CacheMgr::scan_cache
21012µs $t2 = time;
21115µs $debug .= "timing of CacheMgr->new: ".($t2 - $time);
21211µs $time = $t2;
21310s CPAN->debug($debug) if $CPAN::DEBUG;
214132µs155µs $self;
# spent 55µs making 1 call to DirHandle::DESTROY
215}
216
217#-> sub CPAN::CacheMgr::scan_cache ;
218
# spent 56.2s (5.48ms+56.2) within CPAN::CacheMgr::scan_cache which was called: # once (5.48ms+56.2s) by CPAN::CacheMgr::new at line 209
sub scan_cache {
21911µs my ($self, $phase) = @_;
22010s $phase = '' unless defined $phase;
221112µs return unless $phase eq $self->{SCAN};
22212µs return unless $CPAN::META->{LOCK};
223 $CPAN::Frontend->myprint(
224 sprintf("Scanning cache %s for sizes\n",
225112µs149µs $self->{ID}));
# spent 49µs making 1 call to App::Cpan::__ANON__[App/Cpan.pm:673]
22610s my $e;
227130µs1338ms my @entries = $self->entries($self->{ID});
# spent 338ms making 1 call to CPAN::CacheMgr::entries
22811µs my $i = 0;
22911µs my $painted = 0;
23014µs for $e (@entries) {
231719231µs my $symbol = ".";
232719530µs if ($self->{DU} > $self->{MAX}) {
233612118µs $symbol = "-";
2346121.08ms61226.5ms $self->disk_usage($e,1);
# spent 26.5ms making 612 calls to CPAN::CacheMgr::disk_usage, avg 43µs/call
235 } else {
236107309µs1071.56s $self->disk_usage($e);
# spent 1.56s making 107 calls to CPAN::CacheMgr::disk_usage, avg 14.6ms/call
237 }
238719144µs $i++;
239719912µs while (($painted/76) < ($i/@entries)) {
24076322µs762.75ms $CPAN::Frontend->myprint($symbol);
# spent 2.75ms making 76 calls to App::Cpan::__ANON__[App/Cpan.pm:673], avg 36µs/call
24176122µs $painted++;
242 }
243719393µs return if $CPAN::Signal;
244 }
24512µs146µs $CPAN::Frontend->myprint("DONE\n");
# spent 46µs making 1 call to App::Cpan::__ANON__[App/Cpan.pm:673]
2461372µs154.3s $self->tidyup;
# spent 54.3s making 1 call to CPAN::CacheMgr::tidyup
247}
248
2491;
 
# spent 7.91ms within CPAN::CacheMgr::CORE:ftdir which was called 15633 times, avg 506ns/call: # 14322 times (3.34ms+0s) by CPAN::CacheMgr::__ANON__[/usr/local/perls/perl-5.26.1/lib/5.26.1/CPAN/CacheMgr.pm:136] at line 121, avg 233ns/call # 719 times (4.18ms+0s) by CPAN::CacheMgr::disk_usage at line 92, avg 6µs/call # 591 times (371µs+0s) by CPAN::CacheMgr::entries at line 73, avg 628ns/call # once (13µs+0s) by CPAN::CacheMgr::tidyup at line 37
sub CPAN::CacheMgr::CORE:ftdir; # opcode
# spent 5.62ms within CPAN::CacheMgr::CORE:fteexec which was called 2948 times, avg 2µs/call: # 2357 times (2.07ms+0s) by CPAN::CacheMgr::__ANON__[/usr/local/perls/perl-5.26.1/lib/5.26.1/CPAN/CacheMgr.pm:136] at line 122, avg 880ns/call # 591 times (3.55ms+0s) by CPAN::CacheMgr::disk_usage at line 93, avg 6µs/call
sub CPAN::CacheMgr::CORE:fteexec; # opcode
# spent 223ms within CPAN::CacheMgr::CORE:ftfile which was called 1340 times, avg 166µs/call: # 719 times (210ms+0s) by CPAN::CacheMgr::entries at line 73, avg 293µs/call # 493 times (11.8ms+0s) by CPAN::CacheMgr::_clean_cache at line 163, avg 24µs/call # 128 times (757µs+0s) by CPAN::CacheMgr::disk_usage at line 92, avg 6µs/call
sub CPAN::CacheMgr::CORE:ftfile; # opcode
# spent 18.1ms within CPAN::CacheMgr::CORE:ftis which was called 1331 times, avg 14µs/call: # 719 times (6.08ms+0s) by CPAN::CacheMgr::disk_usage at line 91, avg 8µs/call # 612 times (12.0ms+0s) by CPAN::CacheMgr::_clean_cache at line 151, avg 20µs/call
sub CPAN::CacheMgr::CORE:ftis; # opcode
# spent 84.0ms within CPAN::CacheMgr::CORE:ftlink which was called 14322 times, avg 6µs/call: # 14322 times (84.0ms+0s) by CPAN::CacheMgr::__ANON__[/usr/local/perls/perl-5.26.1/lib/5.26.1/CPAN/CacheMgr.pm:136] at line 115, avg 6µs/call
sub CPAN::CacheMgr::CORE:ftlink; # opcode
# spent 64.4ms within CPAN::CacheMgr::CORE:ftmtime which was called 11872 times, avg 5µs/call: # 11872 times (64.4ms+0s) by CPAN::CacheMgr::CORE:sort at line 82, avg 5µs/call
sub CPAN::CacheMgr::CORE:ftmtime; # opcode
# spent 3.65ms within CPAN::CacheMgr::CORE:ftsize which was called 11965 times, avg 305ns/call: # 11965 times (3.65ms+0s) by CPAN::CacheMgr::__ANON__[/usr/local/perls/perl-5.26.1/lib/5.26.1/CPAN/CacheMgr.pm:136] at line 133, avg 305ns/call
sub CPAN::CacheMgr::CORE:ftsize; # opcode
# spent 2.69ms within CPAN::CacheMgr::CORE:match which was called 499 times, avg 5µs/call: # 498 times (2.68ms+0s) by CPAN::CacheMgr::_clean_cache at line 163, avg 5µs/call # once (10µs+0s) by CPAN::CacheMgr::new at line 205
sub CPAN::CacheMgr::CORE:match; # opcode
# spent 94.8ms (30.4+64.4) within CPAN::CacheMgr::CORE:sort which was called: # once (30.4ms+64.4ms) by CPAN::CacheMgr::entries at line 82
sub CPAN::CacheMgr::CORE:sort; # opcode
# spent 27.7ms within CPAN::CacheMgr::CORE:unlink which was called 114 times, avg 243µs/call: # 114 times (27.7ms+0s) by CPAN::CacheMgr::_clean_cache at line 182, avg 243µs/call
sub CPAN::CacheMgr::CORE:unlink; # opcode
Report produced by the NYTProf 6.04 Perl profiler, developed by Tim Bunce based on work by Adam Kaplan and Salvador Fandiño García.