From: Maxime H. <mhe...@gm...> - 2012-01-04 13:15:22
|
Hello all, I have been trying to use rst2pdf to produce potentially very large documents containing patches, such as those produced by a ``cvs diff'' command. Unfortunately, I have observed that the rst2pdf code doesn't seem to scale linearly with the size of the input file size, and when files get large, it starts taking so much time to run that it becomes completely unusable for me (I had one such run taking ~9 hours). This behaviour gets easy to observe using ~2MB .rst files, at least with the hardware I'm using. Here are some more data points : $ ls -l foo*.rst -rw-r--r-- 1 mhe dev 3900918 Jan 3 15:34 foo2.rst -rw-r--r-- 1 mhe dev 1950459 Jan 3 15:33 foo.rst The foo2.rst file is the foo.rst file concatenated with itself, and is thus exactly two times the size of foo.rst. $ time rst2pdf -c -o foo.pdf -s doc/sdlc.stylesheet --custom-cover=doc/cover.tmpl foo.rst real 9m1.998s user 8m27.206s sys 0m33.631s $ time rst2pdf -c -o foo.pdf -s doc/sdlc.stylesheet --custom-cover=doc/cover.tmpl foo2.rst real 39m6.937s user 37m17.725s sys 1m45.256s While trying to pinpoint where exactly the problem lies, I have seen that using rst2latex or rst2html instead of rst2pdf yields a similar behaviour, so that seems to indicate a problem within the reStructuredText parser itself, which is why I'm actually mailing you guys. I used cProfile to profile these rst2pdf runs, and here are the first few lines of the profiling statistics sorted by time, and then by cumulative time : Wed Jan 4 10:49:32 2012 rst2pdf.prof 69453616 function calls (67946896 primitive calls) in 628.887 CPU seconds Ordered by: internal time, cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 541748 139.312 0.000 192.712 0.000 statemachine.py:1110(__getitem__) 21410 86.406 0.004 375.675 0.018 states.py:2278(explicit_list) 125996 51.815 0.000 52.821 0.000 statemachine.py:1054(__init__) 707880 46.462 0.000 89.487 0.000 statemachine.py:690(make_transitions) 21535 46.456 0.002 46.456 0.002 {method 'index' of 'list' objects} 21715 39.820 0.002 39.820 0.002 {method 'remove' of 'list' objects} 4058512 13.771 0.000 40.898 0.000 statemachine.py:657(make_transition) 3742055 10.998 0.000 14.382 0.000 re.py:229(_compile) 707880 10.829 0.000 12.005 0.000 statemachine.py:613(add_transitions) 6067804 9.313 0.000 9.685 0.000 {hasattr} 2931 8.950 0.003 46.976 0.016 states.py:1516(line_block) 202437 6.270 0.000 6.270 0.000 {range} 21410 5.165 0.000 98.773 0.005 misc.py:44(apply) 140863 5.094 0.000 11.796 0.000 basenodehandler.py:169(findsubclass) 4945645 4.641 0.000 5.049 0.000 {getattr} 353940 4.547 0.000 118.871 0.000 states.py:212(__init__) 3515957 4.294 0.000 17.725 0.000 re.py:188(compile) 353940 3.980 0.000 112.378 0.000 statemachine.py:559(__init__) 353940 3.899 0.000 90.450 0.000 statemachine.py:606(add_initial_transitions) 2826759 3.851 0.000 3.851 0.000 {isinstance} 955648/16 3.373 0.000 4.450 0.278 nodes.py:189(_fast_traverse) 4039749 3.254 0.000 3.254 0.000 {method 'get' of 'dict' objects} 109975 3.246 0.000 4.496 0.000 nodes.py:436(__init__) The explicit_list() method looks particularly suspicious to me; more specifically this code : newline_offset, blank_finish = self.nested_list_parse( self.state_machine.input_lines[offset:], input_offset=self.state_machine.abs_line_offset() + 1, node=self.parent, initial_state='Explicit', blank_finish=blank_finish, match_titles=self.state_machine.match_titles) ...looks like it slices the whole input file from the current offset to the *end*, thus copying a lot of data in the process, and it's getting called a lot in my case. As far as I understand this code, it would definitely explain the behaviour I'm observing. Also, there are several other places in the code that do similar things with the input. This is mostly a guess though, and I'm not claiming to have understood exactly what the problem is. Unfortunately, I see no easy way to test this theory without making large changes throughout the code... Of course, I can send the .rst files mentioned above, or the data from the profiling run if necessary; just ask me. Thanks in advance, Maxime Henrion PS: I'm not subscribed to the mailing list, so please keep me Cc'ed in your replies. |
From: Maxime H. <mhe...@gm...> - 2012-01-04 15:11:41
|
On Wed, Jan 4, 2012 at 4:09 PM, Roberto Alsina <ra...@ne...> wrote: > On 1/4/2012 10:09 AM, Maxime Henrion wrote: >> >> Hello all, >> >> I have been trying to use rst2pdf to produce potentially very large >> documents containing patches, such as those produced by a ``cvs diff'' >> command. >> >> Unfortunately, I have observed that the rst2pdf code doesn't seem to >> scale linearly with the size of the input file size, and when files >> get large, it starts taking so much time to run that it becomes >> completely unusable for me (I had one such run taking ~9 hours). This >> behaviour gets easy to observe using ~2MB .rst files, at least with >> the hardware I'm using. Here are some more data points : >> > > I am fairly sure rst2pdf is to blame for most of this. If you want to test > the parser's behaviour, you could just > parse the rst and time that, without a writer. Please read my mail until the end, I have observed similar behaviour with both rst2html and rst2latex... |
From: Roberto A. <ra...@ne...> - 2012-01-04 15:23:27
|
On 1/4/2012 12:11 PM, Maxime Henrion wrote: > On Wed, Jan 4, 2012 at 4:09 PM, Roberto Alsina > <ra...@ne...> wrote: >> On 1/4/2012 10:09 AM, Maxime Henrion wrote: >>> Hello all, >>> >>> I have been trying to use rst2pdf to produce potentially very large >>> documents containing patches, such as those produced by a ``cvs diff'' >>> command. >>> >>> Unfortunately, I have observed that the rst2pdf code doesn't seem to >>> scale linearly with the size of the input file size, and when files >>> get large, it starts taking so much time to run that it becomes >>> completely unusable for me (I had one such run taking ~9 hours). This >>> behaviour gets easy to observe using ~2MB .rst files, at least with >>> the hardware I'm using. Here are some more data points : >>> >> I am fairly sure rst2pdf is to blame for most of this. If you want to test >> the parser's behaviour, you could just >> parse the rst and time that, without a writer. > Please read my mail until the end, I have observed similar behaviour > with both rst2html and rst2latex... I am not saying they don't, I am saying that since I wrote it I know of several ways in which rst2pdf sucks for long documents ;-) Ding similar timings with just parsing would be useful to figure out where the bottleneck is. Something like this script would just parse the document and do nothing: #/usr/bin/env python import docutils, sys docutils.core.publish_doctree(open(sys.argv).read()) > > ------------------------------------------------------------------------------ > Ridiculously easy VDI. With Citrix VDI-in-a-Box, you don't need a complex > infrastructure or vast IT resources to deliver seamless, secure access to > virtual desktops. With this all-in-one solution, easily deploy virtual > desktops for less than the cost of PCs and save 60% on VDI infrastructure > costs. Try it free! http://p.sf.net/sfu/Citrix-VDIinabox > _______________________________________________ > Docutils-users mailing list > Doc...@li... > https://lists.sourceforge.net/lists/listinfo/docutils-users > > Please use "Reply All" to reply to the list. |
From: Maxime H. <mhe...@gm...> - 2012-01-04 15:24:37
|
On Wed, Jan 4, 2012 at 4:15 PM, Roberto Alsina <ra...@ne...> wrote: > On 1/4/2012 12:11 PM, Maxime Henrion wrote: > > On Wed, Jan 4, 2012 at 4:09 PM, Roberto Alsina > <ra...@ne...> wrote: > > On 1/4/2012 10:09 AM, Maxime Henrion wrote: > > Hello all, > > I have been trying to use rst2pdf to produce potentially very large > documents containing patches, such as those produced by a ``cvs diff'' > command. > > Unfortunately, I have observed that the rst2pdf code doesn't seem to > scale linearly with the size of the input file size, and when files > get large, it starts taking so much time to run that it becomes > completely unusable for me (I had one such run taking ~9 hours). This > behaviour gets easy to observe using ~2MB .rst files, at least with > the hardware I'm using. Here are some more data points : > > I am fairly sure rst2pdf is to blame for most of this. If you want to test > the parser's behaviour, you could just > parse the rst and time that, without a writer. > > Please read my mail until the end, I have observed similar behaviour > with both rst2html and rst2latex... > > > I am not saying they don't, I am saying that since I wrote it I know of > several ways in > which rst2pdf sucks for long documents ;-) Oh, alright then, sorry! > Ding similar timings with just parsing would be useful to figure out where > the bottleneck is. > > Something like this script would just parse the document and do nothing: > > #/usr/bin/env python > import docutils, sys > docutils.core.publish_doctree(open(sys.argv).read()) I'll be doing that and will report results ASAP. Thanks, Maxime Henrion |
From: Maxime H. <mhe...@gm...> - 2012-01-04 18:55:29
|
On Wed, Jan 4, 2012 at 4:24 PM, Maxime Henrion <mhe...@gm...> wrote: > On Wed, Jan 4, 2012 at 4:15 PM, Roberto Alsina > <ra...@ne...> wrote: >> On 1/4/2012 12:11 PM, Maxime Henrion wrote: >> >> On Wed, Jan 4, 2012 at 4:09 PM, Roberto Alsina >> <ra...@ne...> wrote: >> >> On 1/4/2012 10:09 AM, Maxime Henrion wrote: >> >> Hello all, >> >> I have been trying to use rst2pdf to produce potentially very large >> documents containing patches, such as those produced by a ``cvs diff'' >> command. >> >> Unfortunately, I have observed that the rst2pdf code doesn't seem to >> scale linearly with the size of the input file size, and when files >> get large, it starts taking so much time to run that it becomes >> completely unusable for me (I had one such run taking ~9 hours). This >> behaviour gets easy to observe using ~2MB .rst files, at least with >> the hardware I'm using. Here are some more data points : >> >> I am fairly sure rst2pdf is to blame for most of this. If you want to test >> the parser's behaviour, you could just >> parse the rst and time that, without a writer. >> >> Please read my mail until the end, I have observed similar behaviour >> with both rst2html and rst2latex... >> >> >> I am not saying they don't, I am saying that since I wrote it I know of >> several ways in >> which rst2pdf sucks for long documents ;-) > > Oh, alright then, sorry! > >> Ding similar timings with just parsing would be useful to figure out where >> the bottleneck is. >> >> Something like this script would just parse the document and do nothing: >> >> #/usr/bin/env python >> import docutils, sys >> docutils.core.publish_doctree(open(sys.argv).read()) > > I'll be doing that and will report results ASAP. And here they are (I kept more input than the last time) : Wed Jan 4 19:50:35 2012 parse.prof 93830802 function calls (91365385 primitive calls) in 756.464 seconds Ordered by: internal time, cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 42816 109.227 0.003 109.227 0.003 {method 'index' of 'list' objects} 42950 109.028 0.003 109.028 0.003 {method 'remove' of 'list' objects} 8115820 61.310 0.000 162.500 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:694(make_transition) 1415550 58.928 0.000 233.888 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:727(make_transitions) 1126135 52.099 0.000 73.418 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:1146(__getitem__) 42816 32.828 0.001 369.596 0.009 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:2305(explicit_list) 7073431 29.456 0.000 41.976 0.000 /usr/local/lib/python2.7/re.py:228(_compile) 7030615 23.547 0.000 65.210 0.000 /usr/local/lib/python2.7/re.py:188(compile) 8823706 23.216 0.000 23.216 0.000 {hasattr} 251953 17.871 0.000 19.358 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:1091(__init__) 8401923 14.627 0.000 14.627 0.000 {getattr} 1911176/8 14.090 0.000 20.244 2.531 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:189(_fast_traverse) 8837605 13.637 0.000 13.637 0.000 {method 'append' of 'list' objects} 177289 12.476 0.000 12.476 0.000 {range} 7074365 12.196 0.000 12.196 0.000 {method 'get' of 'dict' objects} 1415550 11.459 0.000 14.716 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:650(add_transitions) 42816 11.363 0.000 244.017 0.006 /usr/local/lib/python2.7/site-packages/docutils/transforms/misc.py:44(apply) 707775 8.114 0.000 264.300 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:974(add_initial_transitions) 4388502 8.020 0.000 8.020 0.000 {isinstance} 707775 6.231 0.000 208.259 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:643(add_initial_transitions) 707775 5.550 0.000 269.849 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:596(__init__) 220854/146028 5.199 0.000 476.727 0.003 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:422(check_line) 707775 5.097 0.000 279.352 0.000 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:212(__init__) 2210838 4.616 0.000 4.616 0.000 {method 'match' of '_sre.SRE_Pattern' objects} 2123360 4.607 0.000 4.607 0.000 {method 'update' of 'dict' objects} 707775 4.547 0.000 6.693 0.000 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:217(runtime_init) 707775 4.405 0.000 274.255 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:958(__init__) 219937 3.591 0.000 6.237 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:433(__init__) 5862 3.483 0.001 58.607 0.010 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:1532(line_block) 707775 3.425 0.000 282.777 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:466(add_state) 2179337 3.168 0.000 3.168 0.000 {method 'extend' of 'list' objects} 1715474/1534444 3.086 0.000 3.712 0.000 {len} 47185/1 2.829 0.000 481.962 481.962 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:182(run) 42816 2.767 0.000 9.687 0.000 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:2102(parse_directive_block) 391543 2.747 0.000 4.488 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:510(notify_observers) 238897/1 2.198 0.000 5.707 5.707 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:100(walk) 297175 1.987 0.000 7.008 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:300(next_line) 238897 1.979 0.000 3.119 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:1593(dispatch_visit) 73104 1.944 0.000 8.851 0.000 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:693(inline_obj) 535104 1.735 0.000 2.522 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:1140(__len__) 294528 1.695 0.000 3.617 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:619(append) 76320 1.674 0.000 13.320 0.000 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:483(parse) 47185 1.650 0.000 284.428 0.006 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:478(add_states) 47184 1.640 0.000 2.838 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:176(unlink) 47185 1.633 0.000 8.412 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:485(runtime_init) 42816 1.626 0.000 25.876 0.001 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:2040(run_directive) 397021 1.601 0.000 2.773 0.000 {method 'join' of 'str' objects} 76320 1.550 0.000 4.342 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:1370(get_indented) 271000 1.437 0.000 2.303 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:532(__getitem__) 338538 1.404 0.000 1.652 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:91(setup_child) 381889 1.378 0.000 4.135 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:623(extend) 149424 1.166 0.000 6.999 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:793(__init__) 201318 1.157 0.000 4.036 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:577(__iadd__) 707760 1.109 0.000 1.109 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:639(unlink) 76320 1.092 0.000 8.491 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:863(get_first_known_indented) 47184 1.082 0.000 320.496 0.007 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:296(nested_list_parse) 42816 1.079 0.000 2.713 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:1803(make_id) 707775 1.071 0.000 1.071 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:632(runtime_init) 391544 1.062 0.000 1.062 0.000 /usr/local/lib/python2.7/site-packages/docutils/nodes.py:1185(note_source) 519991 0.902 0.000 0.902 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:1303(info) 42816 0.832 0.000 11.038 0.000 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:405(paragraph) 189026 0.823 0.000 0.823 0.000 {method 'search' of '_sre.SRE_Pattern' objects} 42816 0.805 0.000 6.333 0.000 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/directives/misc.py:294(run) 16368/5862 0.769 0.000 3.596 0.001 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:1577(nest_line_block_segment) 477794 0.766 0.000 0.766 0.000 /usr/local/lib/python2.7/site-packages/docutils/utils.py:196(debug) 33504 0.750 0.000 13.207 0.000 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:1559(line_block_line) 1 0.749 0.749 1.521 1.521 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:1495(string2lines) 42833 0.684 0.000 1.230 0.000 /usr/local/lib/python2.7/site-packages/docutils/utils.py:612(normalize_language_tag) 1 0.663 0.663 272.563 272.563 /usr/local/lib/python2.7/site-packages/docutils/transforms/__init__.py:159(apply_transforms) 42816 0.639 0.000 28.453 0.001 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:2288(explicit_construct) 76320 0.634 0.000 1.204 0.000 /usr/local/lib/python2.7/site-packages/docutils/utils.py:544(escape2null) 42816 0.606 0.000 27.327 0.001 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:2028(directive) 128448 0.548 0.000 0.770 0.000 /usr/local/lib/python2.7/site-packages/docutils/statemachine.py:363(get_source_and_line) 47184 0.540 0.000 31.072 0.001 /usr/local/lib/python2.7/site-packages/docutils/parsers/rst/states.py:182(run) Thanks, Maxime Henrion |
From: Roberto A. <ra...@ne...> - 2012-01-04 15:36:58
|
On 1/4/2012 10:09 AM, Maxime Henrion wrote: > Hello all, > > I have been trying to use rst2pdf to produce potentially very large > documents containing patches, such as those produced by a ``cvs diff'' > command. > > Unfortunately, I have observed that the rst2pdf code doesn't seem to > scale linearly with the size of the input file size, and when files > get large, it starts taking so much time to run that it becomes > completely unusable for me (I had one such run taking ~9 hours). This > behaviour gets easy to observe using ~2MB .rst files, at least with > the hardware I'm using. Here are some more data points : > I am fairly sure rst2pdf is to blame for most of this. If you want to test the parser's behaviour, you could just parse the rst and time that, without a writer. |