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µs | Pod::Man::CORE:subst |
| 153341 | 55.6s | 363µs | Pod::Man::guesswork |
| 110758 | 380s | 3.43ms | Pod::Simple::BlackBox::_ponder_paragraph_buffer |
| 211551 | 85.9s | 406µs | Pod::Man::format_text |
| 83544 | 30.4s | 364µs | Pod::Simple::BlackBox::_treelet_from_formatting_codes |
| 751 | 474s | 631ms | Pod::Simple::parse_file |
| 166278 | 101s | 608µs | Pod::Man::_handle_element_end |
| 161254 | 242s | 1.50ms | Pod::Simple::BlackBox::_traverse_treelet_bit |
| 2173841 | 17.5s | 8µs | Pod::Simple::BlackBox::CORE:match |
| 166278 | 31.6 | 190µs | Pod::Man::_handle_element_start |
| 83544 | 91.1s | 1.09ms | Pod::Simple::_make_treelet |
| 551544 | 9.43s | 17µs | Pod::Simple::CORE:readline |
| 83544 | 9.40s | 113µs | Pod::Simple::_remap_sequences |
| 33447 | 9.81s | 293µs | Pod::Simple::_wrap_up |
Update: 2011-02-25
Fixed typo in table.