More questions than observations on installman

atcroft has asked for the wisdom of the Perl Monks concerning the following question:

Recently I took a look through the TODO list with 5.12.1, to see if there was anything that I felt up to attempting, when I found the item 'profile installman'.

perltodo says, "The installman script is slow. All it is doing text processing, which we're told is something Perl is good at. So it would be nice to know what it is doing that is taking so much CPU, and where possible address it." So I installed a few modules, watched a presentation or two about them, ran installman with Devel::NYTProf, and got the following results:

Profile of installman for 499s (of 802s), executing 43948889 statements and 11014444 subroutine calls in 56 source files and 15 string evals.
Top 15 Subroutines Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
27932	1	1	51.6s	443s	Pod::Simple::BlackBox::::parse_lines
2907612	54	1	45.4s	45.5s	Pod::Man::::CORE:subst (opcode)
153341	1	1	28.5s	55.6s	Pod::Man::::guesswork
110758	5	1	26.2s	380s	Pod::Simple::BlackBox::::_ponder_paragraph_buffer
211551	1	1	23.4s	85.9s	Pod::Man::::format_text
83544	1	1	22.2s	30.4s	Pod::Simple::BlackBox::::_treelet_from_formatting_codes
751	1	1	20.9s	474s	Pod::Simple::::parse_file
166278	3	1	18.4s	101s	Pod::Man::::_handle_element_end
161254	2	1	18.2s	242s	Pod::Simple::BlackBox::::_traverse_treelet_bit (recurses: max depth 2, inclusive time 49.4s)
2173841	13	1	17.3s	17.5s	Pod::Simple::BlackBox::::CORE:match (opcode)
166278	3	1	16.7s	31.6s	Pod::Man::::_handle_element_start
83544	1	1	11.5s	91.1s	Pod::Simple::::_make_treelet
551544	1	1	9.43s	9.43s	Pod::Simple::::CORE:readline (opcode)
83544	1	1	9.40s	9.40s	Pod::Simple::::_remap_sequences
33447	1	1	9.21s	9.81s	Pod::Simple::::_wrap_up

Now I am afraid I am a bit confused, or, at least, feeling outside my depth. Looking at the details on those calls, it seems as almost all of those top 15 were taking tenths of a second a most per run, but the sheer number of calls resulting in the lengthy processing time. Am I reading this right, or ignoring something obvious?

(As always, the time and feedback are appreciated.)

Update: 2011-02-23

Added "per run" to clarify my thought on the times the routines were taking per run.

Update: 2011-02-23

The average run time for the functions above are as follows:

Calls	Inclusive time	Average time per call	Subroutine
27932	443s	15.9ms	Pod::Simple::BlackBox::parse_lines
2907612	45.5s	16盜	Pod::Man::CORE:subst
153341	55.6s	363盜	Pod::Man::guesswork
110758	380s	3.43ms	Pod::Simple::BlackBox::_ponder_paragraph_buffer
211551	85.9s	406盜	Pod::Man::format_text
83544	30.4s	364盜	Pod::Simple::BlackBox::_treelet_from_formatting_codes
751	474s	631ms	Pod::Simple::parse_file
166278	101s	608盜	Pod::Man::_handle_element_end
161254	242s	1.50ms	Pod::Simple::BlackBox::_traverse_treelet_bit
2173841	17.5s	8盜	Pod::Simple::BlackBox::CORE:match
166278	31.6	190盜	Pod::Man::_handle_element_start
83544	91.1s	1.09ms	Pod::Simple::_make_treelet
551544	9.43s	17盜	Pod::Simple::CORE:readline
83544	9.40s	113盜	Pod::Simple::_remap_sequences
33447	9.81s	293盜	Pod::Simple::_wrap_up

Update: 2011-02-25

Fixed typo in table.

Comment on More questions than observations on installman

Replies are listed 'Best First'.
Re: More questions than observations on installman by Anonymous Monk on Feb 23, 2011 at 09:08 UTC
Am I reading this right, or ignoring something obvious? That is the way I read it as well. I took a look at installman , here are some ideas I had for making it faster Read more... (804 Bytes) But, I doubt you could make a significant dent in the runtime with these simple ideas (I guesstimate 10 seconds), due to OS level file system caching . What would probably work better is making `Pod::Man->new` happen in a few threads Oh, and I didn't even look at Pod::Simple::BlackBox :)	[reply] [d/l] [select]
Re: More questions than observations on installman by JavaFan (Canon) on Feb 23, 2011 at 10:30 UTC
What it tells me is that there isn't an obvious bottleneck. Even if you optimize the hell out of the most costly subroutine (parse_lines), making it run in no time at all, all you save is about 10%.	[reply]
Re^2: More questions than observations on installman by davido (Cardinal) on Feb 23, 2011 at 19:39 UTC
That being the case, it's a good thing that installman fits into the category of "seldomly run." It makes a lot of sense to "optimize the hell out of" something that gets frequently used. But if that ten percent savings amounts to two minutes per install, and there is one install done per month, the total annual savings is 24 minutes. We spend more time than that in a week, tapping our fingers on the desk waiting for our computers to awaken from sleep mode. I ++'ed this thread because I enjoyed the discussion as well as appreciating the curiosity that lead atcroft to look into installman's performance issues. But it almost seems like in the end it just is what it is: Something that processes thousands of files once, once in awhile. While on the one hand it's surprising there's no smoking gun, on the other hand, highlights the topic of the complexity of managing to pull POD/MAN out of a large number of source code files in a way that is flexible and doesn't break anything already out there in the wild. If there is any approach that has a chance of significantly improving things, it would probably be to throw out the current solution and re-implement from scratch, taking care to not break things. Whether this would actually be productive I have no idea. Perhaps another solution that could save some time when installing on top of existing installations would be to keep the teased out POD's/MAN's, and verify them against a checksum from the source such that if the source changes, then we pull a new page out. But if there's no change to the source (as evidenced by the checksum) the previous version which is already installed will remain in tact, and nothing will be regenerated. Since it's unlikely that everything changes at once, this could save some time. But it may show my inexperience on the matter to assume that such an approach is even possible. Dave	[reply]
Re: More questions than observations on installman by ELISHEVA (Prior) on Feb 23, 2011 at 08:36 UTC
All I have to offer is yet more questions. My first guess if no one function is a gobbler of CPU (aside from parse_file) that maybe the algorithms that are making all these calls are doing more work than they need to. Perhaps the code is recalculating values over and over rather than caching them? Or perhaps some part of the code is inefficiently traversing a graph. I notice that one of the routines is called guesswork. Is this the only place where guesswork is being done or is this a small piece of a larger heuristic algorithm? If so, what sort of heuristic are they using and what is your best guess of its big-O? Could that be the culprit? Also what is the memory profile? Do you have any reason to believe that the CPU consumption is actually the result of page thrashing? I once had a program that was taking somewhere between 10 and 30 minutes to run. When I altered the program to write out data to disk as soon as it was produced rather than waiting until all the results were collected, the time dropped down to 2-3 minutes. Could you provide a link to the source code? It might help us put the results you posted in context.	[reply]
Re^2: More questions than observations on installman by atcroft (Abbot) on Feb 23, 2011 at 09:19 UTC
installman is the code to install the manual pages when building perl. The particular version I was examining is in the 5.12.1 perl source distribution, which (I think I would be safe to assume) would be processing the code included in the perl source for POD to install as man pages. (Anyone: Correct me if I am wrong, please.) How could I best examine the memory usage, to determine if maybe it is swapping at that time?	[reply]
Re^2: More questions than observations on installman by Anonymous Monk on Feb 23, 2011 at 09:24 UTC
http://perl5.git.perl.org/perl.git/blob/HEAD:/installman	[reply]


P is for Practical
	PerlMonks