Beefy Boxes and Bandwidth Generously Provided by pair Networks
"be consistent"
 
PerlMonks  

More questions than observations on installman

by atcroft (Monsignor)
on Feb 23, 2011 at 07:46 UTC ( #889750=perlquestion: print w/ replies, xml ) Need Help??
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
279321151.6s443sPod::Simple::BlackBox::::parse_lines
290761254145.4s45.5sPod::Man::::CORE:subst (opcode)
1533411128.5s55.6sPod::Man::::guesswork
1107585126.2s380sPod::Simple::BlackBox::::_ponder_paragraph_buffer
2115511123.4s85.9sPod::Man::::format_text
835441122.2s30.4sPod::Simple::BlackBox::::_treelet_from_formatting_codes
7511120.9s474sPod::Simple::::parse_file
1662783118.4s101sPod::Man::::_handle_element_end
1612542118.2s242sPod::Simple::BlackBox::::_traverse_treelet_bit (recurses: max depth 2, inclusive time 49.4s)
217384113117.3s17.5sPod::Simple::BlackBox::::CORE:match (opcode)
1662783116.7s31.6sPod::Man::::_handle_element_start
835441111.5s91.1sPod::Simple::::_make_treelet
551544119.43s9.43sPod::Simple::::CORE:readline (opcode)
83544119.40s9.40sPod::Simple::::_remap_sequences
33447119.21s9.81sPod::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
27932443s15.9msPod::Simple::BlackBox::parse_lines
290761245.5s16ÁsPod::Man::CORE:subst
15334155.6s363ÁsPod::Man::guesswork
110758380s3.43msPod::Simple::BlackBox::_ponder_paragraph_buffer
21155185.9s406ÁsPod::Man::format_text
8354430.4s364ÁsPod::Simple::BlackBox::_treelet_from_formatting_codes
751474s631msPod::Simple::parse_file
166278101s608ÁsPod::Man::_handle_element_end
161254242s1.50msPod::Simple::BlackBox::_traverse_treelet_bit
217384117.5s8ÁsPod::Simple::BlackBox::CORE:match
16627831.6190ÁsPod::Man::_handle_element_start
8354491.1s1.09msPod::Simple::_make_treelet
5515449.43s17ÁsPod::Simple::CORE:readline
835449.40s113ÁsPod::Simple::_remap_sequences
334479.81s293ÁsPod::Simple::_wrap_up

Update: 2011-02-25

Fixed typo in table.

Comment on More questions than observations on installman
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.

      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?

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

    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 :)

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%.

      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

Log In?
Username:
Password:

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://889750]
Approved by Corion
Front-paged by planetscape
help
Chatterbox?
and the web crawler heard nothing...

How do I use this? | Other CB clients
Other Users?
Others browsing the Monastery: (9)
As of 2014-12-21 03:25 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    Is guessing a good strategy for surviving in the IT business?





    Results (102 votes), past polls