Re: Performance profiling of makeinfo

[Gavin Smith]

On Fri, Dec 26, 2014 at 9:27 AM, Patrice Dumas <address@hidden> wrote:
> On Wed, Dec 24, 2014 at 05:21:55PM +0000, Gavin Smith wrote:
>>
>> 37432;5;1;29.9s;57.8s;Texinfo::Parser::_deep_copy
>>
>> I note a significant amount of time is spent in _deep_copy, which
>> takes a dump of a data structure and then reads it back in again with
>> "eval". Patrice, do you think it is worth investigating other ways of
>> duplicating a data structure? I saw a page at
>> http://stackoverflow.com/questions/388187/whats-the-best-way-to-make-a-deep-copy-of-a-data-structure-in-perl
>> that suggested using the "Clone" module instead.
>
> I remember that my idea was that it only needed to be done once, so it
> was no big deal if it was not that fast.  I checked the code, and indeed
> parser() should be called only once.  I am a bit puzzled here.  How
> comes it is called so often?
>

sub _deep_copy($)
# spent 57.8s (29.9+27.9) within Texinfo::Parser::_deep_copy which was
called 37432 times, avg 1.55ms/call:
# 18716 times (1.23s+1.40s) by Texinfo::Parser::parser at line 624,
avg 141µs/call
#  4679 times (21.9s+19.9s) by Texinfo::Parser::parser at line 643,
avg 8.92ms/call
#  4679 times (3.72s+3.61s) by Texinfo::Parser::parser at line 642,
avg 1.57ms/call
#  4679 times (1.84s+1.60s) by Texinfo::Parser::parser at line 580,
avg 735µs/call
#  4679 times (1.27s+1.45s) by Texinfo::Parser::parser at line 645,
avg 580µs/call

for sub parser itself:

sub parser(;$$)
# spent 63.3s (3.74+59.5) within Texinfo::Parser::parser which was
called 4679 times, avg 13.5ms/call: # 4678 times (3.74s+59.5s) by
Texinfo::Report::gdt at line 401 of
/usr/local/share/texinfo/Texinfo/Report.pm, avg 13.5ms/call # once
(781µs+10.9ms) by main::RUNTIME at line 1192 of
/usr/local/bin/makeinfo

The gdt function uses a parser, which I believe is used for
translation of strings.