Re: [viewvc-dev] ViewVC 1.1.13 viewvc.get_result tricked by unusually long patch message
"Robert C. Kahlert" <[email protected]> Fri, 30 Mar 2012 14:28:28 -0500
| Newsgroups | gmane.comp.version-control.cvs.viewcvs.devel |
|---|---|
| Message-ID | <CAGgsKjyzNmS2aHGTFbjGV8Z--PKwepYJT4P-Ji-dmpnzv_H+cA@mail.gmail.com> |
------=_Part_5466_1219947451.1333135731210 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit The following change to viewvc.py 1219,1221d1218 < if maxlen > 0 and len(s) > maxlen*10: < # discard the tail < s = s[:maxlen*10] cuts the times in half already. --rck On Fri, Mar 30, 2012 at 2:00 PM, Robert C. Kahlert <[email protected]> wrote: > Hi, > > this may or may not be the right list to report this problem to, so > apologies if it is not. > > We are running into a situation with ViewVC 1.1.13 where the get_result() > method in viewvc.py (line 1210) is being bitten by an update with a very > long VC log message (~250K). > > Specifically, the maxlen parameter does not seem to be passed down to the > self._tokenize_text() method, which is going to town on the 250K message, > calling the search method millions of times, for emitting a few hundred > characters in the summary view. > > Here are some python profiling results for one folder with 100 files, and > for one with 1000 files (which, sad to say, reflect true examples from our > repository). The first takes 30 seconds to render, the second over 4 > minutes (!). > > (A) The Directory with one hundred files > > 15997575 function calls (15991810 primitive calls) in 31.856 CPU > seconds > > Ordered by: internal time > List reduced from 989 to 99 due to restriction <0.10000000000000001> > > ncalls tottime percall cumtime percall filename:lineno(function) > 3788767 17.651 0.000 17.651 0.000 {built-in method search} > 228 6.709 0.029 27.035 0.119 > viewvc.py:1232(_tokenize_text) > 632512 1.232 0.000 3.002 0.000 sapi.py:35(escape) > 1263162 1.056 0.000 2.273 0.000 viewvc.py:4550(__init__) > 2530277 1.046 0.000 1.843 0.000 string.py:511(replace) > 228 0.843 0.004 31.431 0.138 viewvc.py:1210(get_result) > 2530283 0.797 0.000 0.797 0.000 {method 'replace' of 'str' > objects} > 1263164 0.625 0.000 0.625 0.000 {vars} > 1263177 0.591 0.000 0.591 0.000 {method 'update' of 'dict' > objects} > 631794 0.481 0.000 3.552 0.000 viewvc.py:1187(format_text) > 1268335 0.190 0.000 0.190 0.000 {method 'append' of 'list' > objects} > 600 0.142 0.000 0.142 0.000 {method 'split' of 'str' > objects} > 118 0.079 0.001 0.093 0.001 {_fs.svn_fs_check_path} > 637068/636957 0.074 0.000 0.074 0.000 {len} > > (B) The Directory with one thousand files > > 133750340 function calls (133704141 primitive calls) in 269.160 > CPU seconds > > Ordered by: internal time > List reduced from 1002 to 100 due to restriction <0.10000000000000001> > > ncalls tottime percall cumtime percall filename:lineno(function) > 31701892 147.583 0.000 147.583 0.000 {built-in method search} > 2087 58.027 0.028 228.247 0.109 > viewvc.py:1232(_tokenize_text) > 5293057 10.545 0.000 25.366 0.000 sapi.py:35(escape) > 10569433 8.868 0.000 19.292 0.000 viewvc.py:4550(__init__) > 21174316 8.785 0.000 15.433 0.000 string.py:511(replace) > 2087 7.067 0.003 265.489 0.127 viewvc.py:1210(get_result) > 21174322 6.648 0.000 6.648 0.000 {method 'replace' of 'str' > objects} > 10569448 5.270 0.000 5.270 0.000 {method 'update' of 'dict' > objects} > 10569435 5.154 0.000 5.154 0.000 {vars} > 5286693 4.238 0.000 30.173 0.000 viewvc.py:1187(format_text) > 10586140 1.573 0.000 1.573 0.000 {method 'append' of 'list' > objects} > 3363 1.171 0.000 1.171 0.000 {method 'split' of 'str' > objects} > 46995 0.761 0.000 0.761 0.000 {method 'write' of 'file' > objects} > 1021 0.649 0.001 0.784 0.001 {_fs.svn_fs_check_path} > 5298333/5298222 0.611 0.000 0.611 0.000 {len} > > Obviously, this situation (large folder, unusually large patch message) is > an edge case; but the situation should be easy to replicate and the > solution equally straight-forward. > > Two ideas come to mind: > > (a) pre-truncating the message (e.g. to 10 x the max len intended, to pick > a heuristic) > (b) caching the tokenization summary, since patches usually affect > multiple files > > Either solution would fix our situation. > > Best > Robert C. Kahlert > Senior Programmer Analyst > Cycorp Inc (http://www.cyc.com) > 7718 Wood Hollow Drive, Suite #250 > ------------------------------------------------------ http://viewvc.tigris.org/ds/viewMessage.do?dsForumId=4251&dsMessageId=2942588 To unsubscribe from this discussion, e-mail: [[email protected]]. ------=_Part_5466_1219947451.1333135731210 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable The following change to viewvc.py<br><br>1219,1221d1218<br><=A0=A0=A0=A0= if maxlen > 0 and len(s) > maxlen*10:<br><=A0=A0=A0=A0=A0=A0 # di= scard the tail<br><=A0=A0=A0=A0=A0=A0 s =3D s[:maxlen*10]<br><br>cuts th= e times in half already.<br><br> --rck<br><br><div class=3D"gmail_quote">On Fri, Mar 30, 2012 at 2:00 PM, Ro= bert C. Kahlert <span dir=3D"ltr"><<a href=3D"mailto:[email protected]">rck@cy= c.com</a>></span> wrote:<br><blockquote class=3D"gmail_quote" style=3D"m= argin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> Hi,<br><br>this may or may not be the right list to report this problem to,= so apologies if it is not.<br><br>We are running into a situation with Vie= wVC 1.1.13 where the get_result() method in viewvc.py (line 1210) is being = bitten by an update with a very long VC log message (~250K).<br> <br>Specifically, the maxlen parameter does not seem to be passed down to t= he self._tokenize_text() method, which is going to town on the 250K message= , calling the search method millions of times, for emitting a few hundred c= haracters in the summary view.<br> <br>Here are some python profiling results for one folder with 100 files, a= nd for one with 1000 files (which, sad to say, reflect true examples from o= ur repository). The first takes 30 seconds to render, the second over 4 min= utes (!).<br> <br>(A) The Directory with one hundred files<br><br><span style=3D"font-fam= ily:courier new,monospace">=A0=A0=A0=A0=A0=A0=A0=A0 15997575 function calls= (15991810 primitive calls) in 31.856 CPU seconds</span><br style=3D"font-f= amily:courier new,monospace"> <br style=3D"font-family:courier new,monospace"><span style=3D"font-family:= courier new,monospace">=A0=A0 Ordered by: internal time</span><br style=3D"= font-family:courier new,monospace"><span style=3D"font-family:courier new,m= onospace">=A0=A0 List reduced from 989 to 99 due to restriction <0.10000= 000000000001></span><br style=3D"font-family:courier new,monospace"> <br style=3D"font-family:courier new,monospace"><span style=3D"font-family:= courier new,monospace">=A0=A0 ncalls=A0 tottime=A0 percall=A0 cumtime=A0 pe= rcall filename:lineno(function)</span><br style=3D"font-family:courier new,= monospace"><span style=3D"font-family:courier new,monospace">=A0 3788767=A0= =A0 17.651=A0=A0=A0 0.000=A0=A0 17.651=A0=A0=A0 0.000 {built-in method sear= ch}</span><br style=3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0=A0 228=A0=A0= =A0 6.709=A0=A0=A0 0.029=A0=A0 27.035=A0=A0=A0 0.119 viewvc.py:1232(_tokeni= ze_text)</span><br style=3D"font-family:courier new,monospace"><span style= =3D"font-family:courier new,monospace">=A0=A0 632512=A0=A0=A0 1.232=A0=A0= =A0 0.000=A0=A0=A0 3.002=A0=A0=A0 0.000 sapi.py:35(escape)</span><br style= =3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0 1263162=A0=A0=A0 1.05= 6=A0=A0=A0 0.000=A0=A0=A0 2.273=A0=A0=A0 0.000 viewvc.py:4550(__init__)</sp= an><br style=3D"font-family:courier new,monospace"><span style=3D"font-fami= ly:courier new,monospace">=A0 2530277=A0=A0=A0 1.046=A0=A0=A0 0.000=A0=A0= =A0 1.843=A0=A0=A0 0.000 string.py:511(replace)</span><br style=3D"font-fam= ily:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0=A0 228=A0=A0= =A0 0.843=A0=A0=A0 0.004=A0=A0 31.431=A0=A0=A0 0.138 viewvc.py:1210(get_res= ult)</span><br style=3D"font-family:courier new,monospace"><span style=3D"f= ont-family:courier new,monospace">=A0 2530283=A0=A0=A0 0.797=A0=A0=A0 0.000= =A0=A0=A0 0.797=A0=A0=A0 0.000 {method 'replace' of 'str' o= bjects}</span><br style=3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0 1263164=A0=A0=A0 0.62= 5=A0=A0=A0 0.000=A0=A0=A0 0.625=A0=A0=A0 0.000 {vars}</span><br style=3D"fo= nt-family:courier new,monospace"><span style=3D"font-family:courier new,mon= ospace">=A0 1263177=A0=A0=A0 0.591=A0=A0=A0 0.000=A0=A0=A0 0.591=A0=A0=A0 0= .000 {method 'update' of 'dict' objects}</span><br style=3D= "font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0 631794=A0=A0=A0 0.= 481=A0=A0=A0 0.000=A0=A0=A0 3.552=A0=A0=A0 0.000 viewvc.py:1187(format_text= )</span><br style=3D"font-family:courier new,monospace"><span style=3D"font= -family:courier new,monospace">=A0 1268335=A0=A0=A0 0.190=A0=A0=A0 0.000=A0= =A0=A0 0.190=A0=A0=A0 0.000 {method 'append' of 'list' obje= cts}</span><br style=3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0=A0 600=A0=A0= =A0 0.142=A0=A0=A0 0.000=A0=A0=A0 0.142=A0=A0=A0 0.000 {method 'split&#= 39; of 'str' objects}</span><br style=3D"font-family:courier new,mo= nospace"><span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0=A0 = 118=A0=A0=A0 0.079=A0=A0=A0 0.001=A0=A0=A0 0.093=A0=A0=A0 0.001 {_fs.svn_fs= _check_path}</span><br style=3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">637068/636957=A0=A0=A0 0.= 074=A0=A0=A0 0.000=A0=A0=A0 0.074=A0=A0=A0 0.000 {len}</span><br style=3D"f= ont-family:courier new,monospace"><br>(B) The Directory with one thousand f= iles<br><br style=3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0=A0=A0=A0=A0 = 133750340 function calls (133704141 primitive calls) in 269.160 CPU seconds= </span><br style=3D"font-family:courier new,monospace"><br style=3D"font-fa= mily:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0 Ordered by: intern= al time</span><br style=3D"font-family:courier new,monospace"><span style= =3D"font-family:courier new,monospace">=A0=A0 List reduced from 1002 to 100= due to restriction <0.10000000000000001></span><br style=3D"font-fam= ily:courier new,monospace"> <br style=3D"font-family:courier new,monospace"><span style=3D"font-family:= courier new,monospace">=A0=A0 ncalls=A0 tottime=A0 percall=A0 cumtime=A0 pe= rcall filename:lineno(function)</span><br style=3D"font-family:courier new,= monospace"><span style=3D"font-family:courier new,monospace">=A031701892=A0= 147.583=A0=A0=A0 0.000=A0 147.583=A0=A0=A0 0.000 {built-in method search}<= /span><br style=3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0 2087=A0=A0 5= 8.027=A0=A0=A0 0.028=A0 228.247=A0=A0=A0 0.109 viewvc.py:1232(_tokenize_tex= t)</span><br style=3D"font-family:courier new,monospace"><span style=3D"fon= t-family:courier new,monospace">=A0 5293057=A0=A0 10.545=A0=A0=A0 0.000=A0= =A0 25.366=A0=A0=A0 0.000 sapi.py:35(escape)</span><br style=3D"font-family= :courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A010569433=A0=A0=A0 8.86= 8=A0=A0=A0 0.000=A0=A0 19.292=A0=A0=A0 0.000 viewvc.py:4550(__init__)</span= ><br style=3D"font-family:courier new,monospace"><span style=3D"font-family= :courier new,monospace">=A021174316=A0=A0=A0 8.785=A0=A0=A0 0.000=A0=A0 15.= 433=A0=A0=A0 0.000 string.py:511(replace)</span><br style=3D"font-family:co= urier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0 2087=A0=A0= =A0 7.067=A0=A0=A0 0.003=A0 265.489=A0=A0=A0 0.127 viewvc.py:1210(get_resul= t)</span><br style=3D"font-family:courier new,monospace"><span style=3D"fon= t-family:courier new,monospace">=A021174322=A0=A0=A0 6.648=A0=A0=A0 0.000= =A0=A0=A0 6.648=A0=A0=A0 0.000 {method 'replace' of 'str' o= bjects}</span><br style=3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A010569448=A0=A0=A0 5.27= 0=A0=A0=A0 0.000=A0=A0=A0 5.270=A0=A0=A0 0.000 {method 'update' of = 'dict' objects}</span><br style=3D"font-family:courier new,monospac= e"><span style=3D"font-family:courier new,monospace">=A010569435=A0=A0=A0 5= .154=A0=A0=A0 0.000=A0=A0=A0 5.154=A0=A0=A0 0.000 {vars}</span><br style=3D= "font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0 5286693=A0=A0=A0 4.23= 8=A0=A0=A0 0.000=A0=A0 30.173=A0=A0=A0 0.000 viewvc.py:1187(format_text)</s= pan><br style=3D"font-family:courier new,monospace"><span style=3D"font-fam= ily:courier new,monospace">=A010586140=A0=A0=A0 1.573=A0=A0=A0 0.000=A0=A0= =A0 1.573=A0=A0=A0 0.000 {method 'append' of 'list' objects= }</span><br style=3D"font-family:courier new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0 3363=A0=A0= =A0 1.171=A0=A0=A0 0.000=A0=A0=A0 1.171=A0=A0=A0 0.000 {method 'split&#= 39; of 'str' objects}</span><br style=3D"font-family:courier new,mo= nospace"><span style=3D"font-family:courier new,monospace">=A0=A0=A0 46995= =A0=A0=A0 0.761=A0=A0=A0 0.000=A0=A0=A0 0.761=A0=A0=A0 0.000 {method 'w= rite' of 'file' objects}</span><br style=3D"font-family:courier= new,monospace"> <span style=3D"font-family:courier new,monospace">=A0=A0=A0=A0 1021=A0=A0= =A0 0.649=A0=A0=A0 0.001=A0=A0=A0 0.784=A0=A0=A0 0.001 {_fs.svn_fs_check_pa= th}</span><br style=3D"font-family:courier new,monospace"><span style=3D"fo= nt-family:courier new,monospace">5298333/5298222=A0=A0=A0 0.611=A0=A0=A0 0.= 000=A0=A0=A0 0.611=A0=A0=A0 0.000 {len}</span><br style=3D"font-family:cour= ier new,monospace"> <br>Obviously, this situation (large folder, unusually large patch message)= is an edge case; but the situation should be easy to replicate and the sol= ution equally straight-forward. <br><br>Two ideas come to mind:<br><br> (a) pre-truncating the message (e.g. to 10 x the max len intended, to pick = a heuristic)<br>(b) caching the tokenization summary, since patches usually= affect multiple files<br><br>Either solution would fix our situation.<br> <br>Best<span class=3D"HOEnZb"><font color=3D"#888888"><br>Robert C. Kahler= t<br>Senior Programmer Analyst<br>Cycorp Inc (<a href=3D"http://www.cyc.com= " target=3D"_blank">http://www.cyc.com</a>)<br>7718 Wood Hollow Drive, Suit= e #250<br> </font></span></blockquote></div><br> ------=_Part_5466_1219947451.1333135731210--