doc/users/mathdesc.mdwn

   1 mathdesc-at-scourge.biz
   2 .
   3 ## PROFILING slow render  : Case buggy [[plugins/filecheck]] ?
   4
   5 Saving an article from ikiwiki editor is long ?
   6 <tt>ikiwiki  --setup wiki.setup --rebuild</tt> is long ?
   7
   8 Of course it depends the size of the wiki but if it's tiny and still take
   9 more that two minutes, it's boring. But if it takes a **dozen of minutes**, it's plain buggy.
  10
  11 Actually one can with a verbose rebuild narrow down which page "lags" :
  12
  13 <code>
  14     private/admin.mdmn
  15     tag/admin
  16     tag/private
  17 </code>
  18
  19 It's also possible to measure render time on one of these pages like this:
  20
  21 <code>
  22 time ikiwiki  --setup wiki.setup --render private/admin.mdwn
  23 </code>
  24
  25 Well indeed for such a simple page, something fishy is going on.
  26
  27 Still for simple yet superficial but enough profiling test, it requires
  28 a sub-level perl profiler.
  29
  30 ## Using SmallProf
  31
  32 [[tips/optimising_ikiwiki/#index10h2]] proposed [[!cpan Devel::NYTProf]].
  33
  34 Try it hard to make it spits realistic numbers or even a trend to point
  35 the bottleneck in the code. Bref -- nothing valuable nor coherent, it's way to sophisticated to be handy
  36 in my situation (virtual machine, SMP system, long runs, clock drifts, etc...)
  37
  38 [[!cpan Devel::SmallProf]] is simple and just works(c)
  39
  40 <pre>
  41 export PERL5OPT=-d:SmallProf
  42 time ikiwiki  --setup wiki.setup --rebuild
  43 sort -k 2nr,2 -k 3nr,3  smallprof.out | head -n 6
  44 </pre>
  45
  46
  47 ### Results : 6 top slowpits
  48
  49 Total rebuild time:<br/>
  50 real    5m16.283s<br/>
  51 user    2m38.935s<br/>
  52 sys     2m32.704s<br/>
  53
  54
  55 Total rebuild time (under profiling) : <br/>
  56 real    19m21.633s<br/>
  57 user    14m47.831s<br/>
  58 sys     4m11.046s<br/>
  59
  60
  61 <pre>
  62 [num]   [walltime]      [cputime]       [line]: [code]
  63 3055    114.17165       15.34000        149:    $mimetype=<$file_h>;
  64 1626527 69.39272        101.4700    93:     read($fh, $line, $$ref[1]); # read max
  65 3055    50.62106        34.78000        148:    open(my $file_h, "-|", "file", "-bi",
  66 1626527  14.86525       48.50000         92:    seek($fh, $$ref[0], SEEK_SET); # seek
  67 1626527  13.95613       44.78000        102:    return undef unless $line =~ $$ref[3]; #
  68 3055    5.75528         5.81000         76:     for my $type (map @$_, @rules) {
  69 </pre>
  70
  71 legend :
  72 *num* is the number of times that the line was executed, *time* is the amount of "wall time" (time according the the clock on the wall vs. cpu time)
  73 spent executing it, *ctime* is the amount of cpu time expended on it and *line* and *code* are the line number and the actual text of the executed line
  74 (read from the file).
  75
  76
  77 3 topmost issues are located in this file :
  78
  79 <tt>/usr/lib/perl5/vendor_perl/5.12.3/IkiWiki/Plugin/filecheck.pm</tt>
  80 <pre>
  81 sub match_mimetype ($$;@) {
  82         my $page=shift;
  83         my $wanted=shift;
  84
  85         my %params=@_;
  86         my $file=exists $params{file} ? $params{file} : IkiWiki::srcfile($IkiWiki::pagesources{$page});
  87         if (! defined $file) {
  88                 return IkiWiki::ErrorReason->new("file does not exist");
  89         }
  90
  91         # Get the mime type.
  92         #
  93         # First, try File::Mimeinfo. This is fast, but doesn't recognise
  94         # all files.
  95         eval q{use File::MimeInfo::Magic};
  96         my $mimeinfo_ok=! $@;
  97         my $mimetype;
  98         if ($mimeinfo_ok) {
  99                 my $mimetype=File::MimeInfo::Magic::magic($file);
 100         }
 101
 102         # Fall back to using file, which has a more complete
 103         # magic database.
 104         if (! defined $mimetype) {
 105                 open(my $file_h, "-|", "file", "-bi", $file);
 106                 $mimetype=<$file_h>;
 107                 chomp $mimetype;
 108                 close $file_h;
 109         }
 110         if (! defined $mimetype || $mimetype !~s /;.*//) {
 111                 # Fall back to default value.
 112                 $mimetype=File::MimeInfo::Magic::default($file)
 113                         if $mimeinfo_ok;
 114                 if (! defined $mimetype) {
 115                         $mimetype="unknown";
 116                 }
 117         }
 118
 119         my $regexp=IkiWiki::glob2re($wanted);
 120         if ($mimetype!~$regexp) {
 121                 return IkiWiki::FailReason->new("file MIME type is $mimetype, not $wanted");
 122         }
 123         else {
 124                 return IkiWiki::SuccessReason->new("file MIME type is $mimetype");
 125         }
 126 }
 127 </pre>
 128
 129 Next 3 in this file :
 130
 131 <tt>/usr/lib/perl5/vendor_perl/5.12.3/File/MimeInfo/Magic.pm</tt>
 132 <pre>
 133 sub _check_rule {
 134         my ($ref, $fh, $lev) = @_;
 135         my $line;
 136
 137         # Read
 138         if (ref $fh eq 'GLOB') {
 139                 seek($fh, $$ref[0], SEEK_SET);  # seek offset
 140                 read($fh, $line, $$ref[1]);     # read max length
 141         }
 142         else { # allowing for IO::Something
 143                 $fh->seek($$ref[0], SEEK_SET);  # seek offset
 144                 $fh->read($line, $$ref[1]);     # read max length
 145         }
 146
 147         # Match regex
 148         $line = unpack 'b*', $line if $$ref[2]; # unpack to bits if using mask
 149         return undef unless $line =~ $$ref[3];  # match regex
 150         print STDERR    '>', '>'x$lev, ' Value "', _escape_bytes($2),
 151                         '" at offset ', $$ref[1]+length($1),
 152                         " matches at $$ref[4]\n"
 153                 if $DEBUG;
 154         return 1 unless $#$ref > 4;
 155
 156         # Check nested rules and recurs
 157         for (5..$#$ref) {
 158                 return 1 if _check_rule($$ref[$_], $fh, $lev+1);
 159         }
 160         print STDERR "> Failed nested rules\n" if $DEBUG && ! $lev;
 161         return 0;
 162 }
 163 </pre>
 164
 165 *"It seems it's a unique cause, that snails it all"*
 166
 167 ## Conclusion
 168
 169 This describes an issue in the attachment filechecker with mime type detection.
 170 The smallprof out file reveals it always fall back to using file which is very time-consuming.
 171
 172 So what the hell did I put as complex allowed file attachment ruining File::Mimeinfo fast yet sparse recon ?
 173 Well, it was set in the config this way:
 174
 175 <tt>allowed_attachments => 'mimetype(image/*) or maxsize(5000kb) or mimetype(text/plain) or mimetype(text/css) or mimetype(video/*)'</tt>
 176
 177 Ok... maybe the wildcards induce ....hum whatever... let's try something , the simplest thing :
 178
 179 <tt>allowed_attachments => 'mimetype(text/plain) or mimetype(text/css)'</tt>
 180
 181 Same slowness : yek, File::Mimeinfo recons nothing ... not even simplest files.
 182
 183 Disabling it is a temporary cure obviously but it only took **30 seconds** .
 184
 185 <tt>disable_plugins => [qw{filecheck}]</tt>
 186
 187 I tried also to upgrade [[!cpan File::MimeInfo]] to current 0.16, did not helped either. :/
 188
 189 I opened a bug [[bugs/Slow_Filecheck_attachments___34__snails_it_all__34__]]
 190