(no commit message)
[ikiwiki] / 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