Re: texi2any is too slow because of Unicode::Collate

[Gavin Smith]

On Sun, Feb 12, 2023 at 07:52:50AM +0200, Eli Zaretskii wrote:
> Btw, I'm not sure I understand the time data presented by Gavin:
> 
> > Top 15 Subroutines
> > Calls   P  F Exc   Inc      Subroutine
> > 2280071 1  1 23.1s 25.5s    Unicode::Collate::getWt
> > 122770  1  1 14.4s 15.6s    Unicode::Collate::splitEnt
> > 351998  22 1 7.86s 67.2s    Texinfo::Convert::Plaintext::_convert
> > 122770  1  1 6.86s 48.8s    Unicode::Collate::getSortKey
> > 270366  28 1 1.52s 1.59s    Texinfo::Convert::Plaintext::_count_added
> > 2280071 1  1 973ms 973ms    Unicode::Collate::varCE (xsub)
> > 167542  1  1 899ms 1.26s    Texinfo::Convert::Plaintext::_process_text
> > 184832  8  2 842ms 842ms    Texinfo::Convert::Paragraph::add_text (xsub)
> > 2280071 1  1 724ms 724ms    Unicode::Collate::_fetch_simple (xsub)
> > 2280071 1  1 550ms 550ms    Unicode::Collate::_ignorable_simple (xsub)
> > 4564446 8  1 530ms 530ms    Unicode::Collate::CORE:match (opcode)
> > 2280071 1  1 508ms 508ms    Unicode::Collate::_exists_simple (xsub)
> > 62010   1  1 463ms 49.7s    Texinfo::Structuring::_collator_sort_string
> > 122770  1  1 444ms 622ms    Unicode::Collate::process
> > 1       1  1 434ms 434ms    Texinfo::Parser::parse_file (xsub)
> 
> This seems to say that Unicode::Collate::getWt alone took 23.1 sec??
> and Unicode::Collate::getSortKey with all its callees took 48.8 sec??
> and the entire conversion took 67.2 sec??

When you run it with Devel::NYTProf it is much slower than without.
It's really the percentage of total time taken that is meaningful, not the
absolute time.

(By the way, the top line of the report it generates stated:

Profile of ../texi2any.pl for 69.3s (of 117s), executing 72008243 statements 
and 19979851 subroutine calls in 76 source files and 17 string evals.

- although I don't know what the 117 seconds refers to - it could be the
wall clock time it took for perl -d:NYTProf to run.)

Without Devel::NTYProf, it takes about 14.5 seconds on my system
(with XS extensions).  Texinfo 7.0.2 only takes 6.1 seconds, under
half the time.

With TEXINFO_XS=omit, it now takes 52 seconds.  I tested Texinfo
7.0.2 and it only took 42 seconds.

(I thought this was still longer than I remembered, so tested
with Texinfo 6.8, where it came out 23 seconds without XS modules.
This appears to be a major performance regression which I will need to
investigate, although it is unrelated to the Unicode::Collate issue.)

>  On my system, which is a
> 12-year old Windows XP, producing the Emacs Lisp Reference manual for
> Emacs 27.2 takes just 18.1 sec of CPU time, so how come Gavin reports
> such huge timings?  I measured with Texinfo 7.0.1 -- are you saying
> that the current version from the Texinfo Git's master branch is so
> much slower?  Did we not use Unicode::Collate in Texinfo 7.0.x?

Yes, it is much slower than 7.0.x.  Unicode::Collate was only introduced
after the 7.0 release.