Bug #78794 for DateTime-Locale: Speed up module load time (0.55s for me)

Sun Aug 05 14:08:19 2012 NERDVANA [...] cpan.org - Ticket created

CC:	mike [...] nrdvana.net
Subject:	Speed up module load time (0.55s for me)

DateTime is an amazingly useful module! Unfortunately it isn't very suitable for quick commandline usage, because it adds half a second delay to command execution. Also, because DateTime is used by so many other modules, it makes many others unsuitable for small shell utilities. I was wondering if you could take a look at the things it includes, and either avoid modules that aren't strictly necessary, or load some lesser used features on demand via 'require' within methods. A quick review of strace output shows a long delay following perl opening the 'utf8.pm' module. Here's the output of strace -e trace=open -r perl -e 'use DateTime;' 0.000000 open("/etc/ld.so.cache", O_RDONLY) = 3 0.000427 open("/usr/lib/libperl.so.5.12", O_RDONLY) = 3 0.000531 open("/lib/libc.so.6", O_RDONLY) = 3 0.000888 open("/lib/libdl.so.2", O_RDONLY) = 3 0.000601 open("/lib/libm.so.6", O_RDONLY) = 3 0.000449 open("/lib/libcrypt.so.1", O_RDONLY) = 3 0.003186 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3 0.000632 open("/dev/urandom", O_RDONLY|O_LARGEFILE) = 3 0.002876 open("/dev/null", O_RDONLY|O_LARGEFILE) = 3 0.002172 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/DateTime.pm", O_RDONLY|O_LARGEFILE) = 4 0.002987 open("/usr/lib/perl5/5.12.4/strict.pm", O_RDONLY|O_LARGEFILE) = 5 0.004273 open("/usr/lib/perl5/5.12.4/warnings.pm", O_RDONLY|O_LARGEFILE) = 5 0.013314 open("/usr/lib/perl5/5.12.4/Carp.pm", O_RDONLY|O_LARGEFILE) = 5 0.010418 open("/usr/lib/perl5/5.12.4/Exporter.pm", O_RDONLY|O_LARGEFILE) = 5 0.004610 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/DateTime/Duration.pm", O_RDONLY|O_LARGEFILE) = 5 0.001572 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/DateTime/Helpers.pm", O_RDONLY|O_LARGEFILE) = 6 0.001554 open("/usr/lib/perl5/vendor_perl/5.12.4/i686- linux/Scalar/Util.pm", O_RDONLY|O_LARGEFILE) = 7 0.002458 open("/usr/lib/perl5/5.12.4/vars.pm", O_RDONLY|O_LARGEFILE) = 8 0.002588 open("/usr/lib/perl5/5.12.4/warnings/register.pm", O_RDONLY|O_LARGEFILE) = 9 0.006139 open("/usr/lib/perl5/vendor_perl/5.12.4/i686- linux/List/Util.pm", O_RDONLY|O_LARGEFILE) = 7 0.003878 open("/usr/lib/perl5/5.12.4/XSLoader.pm", O_RDONLY|O_LARGEFILE) = 7 0.004082 open("/usr/lib/perl5/vendor_perl/5.12.4/i686- linux/auto/List/Util/Util.so", O_RDONLY) = 7 0.002693 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/Params/Validate.pm", O_RDONLY|O_LARGEFILE) = 6 0.001839 open("/usr/lib/perl5/site_perl/5.12.4/Module/Implementation.pm", O_RDONLY|O_LARGEFILE) = 7 0.001585 open("/usr/lib/perl5/site_perl/5.12.4/Module/Runtime.pm", O_RDONLY|O_LARGEFILE) = 8 0.007459 open("/usr/lib/perl5/site_perl/5.12.4/Try/Tiny.pm", O_RDONLY|O_LARGEFILE) = 8 0.007638 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/Params/Validate/Constants.pm", O_RDONLY|O_LARGEFILE) = 7 0.005338 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/Params/Validate/XS.pm", O_RDONLY|O_LARGEFILE) = 6 0.002735 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/auto/Params/Validate/XS/XS.so", O_RDONLY) = 6 0.003537 open("/usr/lib/perl5/5.12.4/overload.pm", O_RDONLY|O_LARGEFILE) = 6 0.007881 open("/usr/lib/perl5/5.12.4/constant.pm", O_RDONLY|O_LARGEFILE) = 6 0.014536 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/Locale.pm", O_RDONLY|O_LARGEFILE) = 5 0.002066 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/Locale/Base.pm", O_RDONLY|O_LARGEFILE) = 6 0.001519 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/List/MoreUtils.pm", O_RDONLY|O_LARGEFILE) = 7 0.002608 open("/usr/lib/perl5/5.12.4/i686-linux/DynaLoader.pm", O_RDONLY|O_LARGEFILE) = 8 0.002466 open("/usr/lib/perl5/5.12.4/i686-linux/Config.pm", O_RDONLY|O_LARGEFILE) = 9 0.009498 open("/usr/lib/perl5/5.12.4/AutoLoader.pm", O_RDONLY|O_LARGEFILE) = 8 0.006735 open("/usr/lib/perl5/5.12.4/i686-linux/Config_heavy.pl", O_RDONLY|O_LARGEFILE) = 8 0.009558 open("/usr/lib/perl5/5.12.4/i686-linux/Config_git.pl", O_RDONLY|O_LARGEFILE) = 8 0.003216 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/auto/List/MoreUtils/MoreUtils.so", O_RDONLY) = 8 0.017674 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/Locale/Catalog.pm", O_RDONLY|O_LARGEFILE) = 6 0.002712 open("/usr/lib/perl5/5.12.4/utf8.pm", O_RDONLY|O_LARGEFILE) = 7 0.261864 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/TimeZone.pm", O_RDONLY|O_LARGEFILE) = 5 0.002128 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/TimeZone/Catalog.pm", O_RDONLY|O_LARGEFILE) = 6 0.015146 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/TimeZone/Floating.pm", O_RDONLY|O_LARGEFILE) = 6 0.003154 open("/usr/lib/perl5/5.12.4/base.pm", O_RDONLY|O_LARGEFILE) = 7 0.006219 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/TimeZone/OffsetOnly.pm", O_RDONLY|O_LARGEFILE) = 7 0.002345 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/TimeZone/UTC.pm", O_RDONLY|O_LARGEFILE) = 8 0.005778 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/TimeZone/Local.pm", O_RDONLY|O_LARGEFILE) = 6 0.001782 open("/usr/lib/perl5/vendor_perl/5.12.4/i686- linux/File/Spec.pm", O_RDONLY|O_LARGEFILE) = 7 0.002111 open("/usr/lib/perl5/vendor_perl/5.12.4/i686- linux/File/Spec/Unix.pm", O_RDONLY|O_LARGEFILE) = 7 0.024346 open("/usr/lib/perl5/site_perl/5.12.4/Math/Round.pm", O_RDONLY|O_LARGEFILE) = 5 0.002417 open("/usr/lib/perl5/5.12.4/i686-linux/POSIX.pm", O_RDONLY|O_LARGEFILE) = 6 0.001259 open("/usr/lib/perl5/5.12.4/i686- linux/auto/POSIX/autosplit.ix", O_RDONLY|O_LARGEFILE) = 7 0.006308 open("/usr/lib/perl5/5.12.4/i686-linux/Fcntl.pm", O_RDONLY|O_LARGEFILE) = 7 0.002466 open("/usr/lib/perl5/5.12.4/i686- linux/auto/Fcntl/Fcntl.so", O_RDONLY) = 8 0.008151 open("/usr/lib/perl5/5.12.4/Tie/Hash.pm", O_RDONLY|O_LARGEFILE) = 7 0.005231 open("/usr/lib/perl5/5.12.4/i686- linux/auto/POSIX/POSIX.so", O_RDONLY) = 6 0.003182 open("/usr/share/locale/locale.alias", O_RDONLY) = 6 0.000942 open("/usr/share/locale/en_US.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) 0.000182 open("/usr/share/locale/en_US.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) 0.000345 open("/usr/share/locale/en_US/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) 0.000155 open("/usr/share/locale/en.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) 0.000136 open("/usr/share/locale/en.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) 0.000132 open("/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) 0.000282 open("/usr/lib/perl5/5.12.4/i686- linux/auto/POSIX/load_imports.al", O_RDONLY|O_LARGEFILE) = 6 0.007776 open("/usr/lib/perl5/5.12.4/Exporter/Heavy.pm", O_RDONLY|O_LARGEFILE) = 6 0.039999 open("/usr/lib/perl5/5.12.4/integer.pm", O_RDONLY|O_LARGEFILE) = 5 0.041378 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/auto/DateTime/DateTime.so", O_RDONLY) = 4 0.001480 open("/usr/lib/perl5/site_perl/5.12.4/i686- linux/DateTime/Infinite.pm", O_RDONLY|O_LARGEFILE) = 4 0.006546 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/Locale/en_US.pm", O_RDONLY|O_LARGEFILE) = 4 0.002057 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/Locale/en.pm", O_RDONLY|O_LARGEFILE) = 5 0.002065 open("/usr/lib/perl5/site_perl/5.12.1/DateTime/Locale/root.pm", O_RDONLY|O_LARGEFILE) = 6

Sun Aug 05 16:37:28 2012 NERDVANA [...] cpan.org - Correspondence added

Upon further investigation using NYTProf, it seems that most of the time is spent in DateTime::Locale registering 466 locales and 422 aliases. It also seems that DateTime will often only load one locale. Could you perhaps write an optimized module that would create the default locale object, and then only register the rest if "->load()" asked for a locale that wasn't the default? I attached my NYTProf output, in case you are getting different results.

Subject:

nytprof-before.tar.bz2

Download nytprof-before.tar.bz2
application/x-bzip 989.1k

Message body not shown because it is not plain text.

Sun Aug 05 16:37:30 2012 NERDVANA [...] cpan.org - Status changed from 'new' to 'open'

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.64 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.65 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.66 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.67 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.68 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.69 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.70 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.71 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.72 deleted

Sun Aug 05 16:41:04 2012 NERDVANA [...] cpan.org - Broken in 0.73 deleted

Sun Aug 05 16:41:05 2012 NERDVANA [...] cpan.org - Broken in 0.74 deleted

Sun Aug 05 16:41:05 2012 NERDVANA [...] cpan.org - Broken in 0.75 deleted

Fri Nov 16 12:31:58 2012 DROLSKY [...] cpan.org - Correspondence added

On Sun Aug 05 16:37:28 2012, NERDVANA wrote: Show quoted text

> Upon further investigation using NYTProf, it seems that most of the

time Show quoted text

> is spent in DateTime::Locale registering 466 locales and 422 aliases. > > It also seems that DateTime will often only load one locale. Could

you Show quoted text

> perhaps write an optimized module that would create the default locale > object, and then only register the rest if "->load()" asked for a

locale Show quoted text

> that wasn't the default? > > I attached my NYTProf output, in case you are getting different

results. autarch@houseabsolute:~/projects/DateTime.pm (master $=)$ time perl -e 'use DateTime' real 0m0.075s user 0m0.064s sys 0m0.008s Of course, I have an SSD, but half a second seems insanely slow. I tried this on another sytem without an SSD. The first load was 0.8 seconds, but once the cache was primed it was 0.142. If you're consistently seeing half second times there might be other issues. That all said, I think deferring work in DateTime::Locale is a good idea, and patches are welcome. It might be possible to only register the en locale and register others if ->load is called for any other id.

Sat Dec 15 16:46:30 2012 NERDVANA [...] cpan.org - Correspondence added

On Fri Nov 16 12:31:58 2012, DROLSKY wrote: Show quoted text

> On Sun Aug 05 16:37:28 2012, NERDVANA wrote:

> > Upon further investigation using NYTProf, it seems that most of the

> time

> > is spent in DateTime::Locale registering 466 locales and 422

aliases. Show quoted text

> >

> > autarch@houseabsolute:~/projects/DateTime.pm (master $=)$ time perl -e > 'use DateTime' > > real 0m0.075s > user 0m0.064s > sys 0m0.008s > > > Of course, I have an SSD, but half a second seems insanely slow. > > I tried this on another sytem without an SSD. The first load was 0.8 > seconds, but once the cache was primed it was 0.142. If you're > consistently seeing half second times there might be other issues.

My numbers actually came from an older Gentoo box with Perl 5.8 (and all these are "hot cache" numbers. i.e. I run the command several times in a row) To get some more real-world numbers, I have a fresh install of Linux Mint 12 and perl 5.12 on a 2.9Ghz Core2 Duo and I get: $ time perl -e 'use DateTime;' real 0m0.100s user 0m0.088s sys 0m0.008s I also have a small file server on an Intel Atom 330 1.6 Ghz running Gentoo and perl 5.12, which gets: $ time perl -e 'use DateTime;' real 0m0.404s user 0m0.386s sys 0m0.015s So it might be we're just looking at raw CPU speed. Show quoted text

> That all said, I think deferring work in DateTime::Locale is a good > idea, and patches are welcome. It might be possible to only register

the Show quoted text

> en locale and register others if ->load is called for any other id.

I was thinking about making a more streamlined code path for registering the Locale::Catalog. What I see is that most of the time spent is in the calls to validate(), when you already know that the hashes in Catalog are valid. validate() is great for catching misuse by third parties, but for the built-in defaults how about we just iterate them in a tight loop? I'll work on a patch sometime soon, but let me know if you want it implemented in a specific way.

Sun Dec 16 01:57:57 2012 NERDVANA [...] cpan.org - Correspondence added

The attached patch is actually for DateTime::Locale, but I'm putting it here for context. It decreases load time of DateTime from 0.101s to 0.068 on my Core2 x64 Mint system, though has less effect on my Atom 330 x86 Gentoo system, dropping from 0.399 to 0.358. I wanted to take a more aggressive approach and avoid loading DateTime::Locale::Catalog if the user avoided asking for aliases or by- name, however the parameters in Catalog are passed to each Locale constructor. It might be reasonable to add a class method to each Locale called "DefaultParams" or something, and then Catalog would only be a hash of key->id for each search criteria (alias, english name, native name) which could be consulted directly instead of copying it into the Locale package. I figured I would see what you though about that before making such a large change. To clarify: the algorithm would look like this: 1. load: 1.1 If name in cache, return instance 1.2 If name is registered, return instance using registered params 1.3 If package Locale::$name exists or is loadable, return instance using Locale::$name->DefaultParams 1.4 require Catalog 1.5 Use combination of registered and Catalog lookups to find best match, and create instance

Subject:

startup_speed.patch

diff --git a/lib/DateTime/Locale.pm b/lib/DateTime/Locale.pm index 7b62dfe..a5822e4 100644 --- a/lib/DateTime/Locale.pm +++ b/lib/DateTime/Locale.pm @@ -87,6 +87,20 @@ sub _register { $Class{$id} = $p{class} if defined exists $p{class}; } +sub _register_without_checks { + my ($class, %loc) = @_; + + $loc{native_language} = $loc{en_language} + unless exists $loc{native_language}; + + $loc{en_complete_name} = join ' ', grep { defined } @loc{'en_language','en_script','en_territory','en_variant'}; + $loc{native_complete_name} = join ' ', grep { defined } @loc{'native_language','native_script','native_territory','native_variant'}; + + $DataForID{$loc{id}} = \%loc; + $NameToID{$loc{native_complete_name}} = $loc{id}; + $NativeNameToID{$loc{en_complete_name}} = $loc{id}; +} + sub _registered_id { shift; my ($id) = validate_pos( @_, { type => SCALAR } ); @@ -138,8 +152,9 @@ sub remove_alias { } BEGIN { - __PACKAGE__->register( DateTime::Locale::Catalog->Locales() ); - __PACKAGE__->add_aliases( DateTime::Locale::Catalog->Aliases() ); + __PACKAGE__->_register_without_checks( %$_ ) + foreach DateTime::Locale::Catalog->Locales(); + %AliasToID= DateTime::Locale::Catalog->Aliases(); } sub ids { wantarray ? keys %DataForID : [ keys %DataForID ] } diff --git a/lib/DateTime/Locale/Base.pm b/lib/DateTime/Locale/Base.pm index acc2cab..5e5c486 100644 --- a/lib/DateTime/Locale/Base.pm +++ b/lib/DateTime/Locale/Base.pm @@ -5,7 +5,6 @@ use warnings; use Carp qw( carp ); use DateTime::Locale; -use List::MoreUtils (); use Params::Validate qw( validate_pos ); BEGIN { @@ -88,15 +87,11 @@ sub format_for { sub available_formats { my $self = shift; - # The various parens seem to be necessary to force uniq() to see - # the caller's list context. Go figure. - my @uniq - = List::MoreUtils::uniq( - map { keys %{ $_->_available_formats() || {} } } - _self_and_super_path( ref $self ) ); - - # Doing the sort in the same expression doesn't work under 5.6.x. - return sort @uniq; + my %seen; + $seen{$_}++ + foreach map { keys %{ $_->_available_formats() || {} } } + _self_and_super_path( ref $self ); + return sort keys %seen; } # Copied wholesale from Class::ISA, because said module warns as deprecated

Sun Dec 16 02:31:58 2012 NERDVANA [...] cpan.org - Correspondence added

Bug in previous. Attached revised patch.

Subject:

startup_speed.patch

diff --git a/lib/DateTime/Locale.pm b/lib/DateTime/Locale.pm index 7b62dfe..31a226f 100644 --- a/lib/DateTime/Locale.pm +++ b/lib/DateTime/Locale.pm @@ -87,6 +87,20 @@ sub _register { $Class{$id} = $p{class} if defined exists $p{class}; } +sub _register_without_checks { + my ($class, %loc) = @_; + + $loc{native_language} = $loc{en_language} + unless exists $loc{native_language}; + + $loc{en_complete_name} = join ' ', grep { defined } @loc{'en_language','en_script','en_territory','en_variant'}; + $loc{native_complete_name} = join ' ', grep { defined } @loc{'native_language','native_script','native_territory','native_variant'}; + + $DataForID{$loc{id}} = \%loc; + $NameToID{$loc{en_complete_name}} = $loc{id}; + $NativeNameToID{$loc{native_complete_name}} = $loc{id}; +} + sub _registered_id { shift; my ($id) = validate_pos( @_, { type => SCALAR } ); @@ -138,8 +152,9 @@ sub remove_alias { } BEGIN { - __PACKAGE__->register( DateTime::Locale::Catalog->Locales() ); - __PACKAGE__->add_aliases( DateTime::Locale::Catalog->Aliases() ); + __PACKAGE__->_register_without_checks( %$_ ) + foreach DateTime::Locale::Catalog->Locales(); + %AliasToID= DateTime::Locale::Catalog->Aliases(); } sub ids { wantarray ? keys %DataForID : [ keys %DataForID ] } diff --git a/lib/DateTime/Locale/Base.pm b/lib/DateTime/Locale/Base.pm index acc2cab..5e5c486 100644 --- a/lib/DateTime/Locale/Base.pm +++ b/lib/DateTime/Locale/Base.pm @@ -5,7 +5,6 @@ use warnings; use Carp qw( carp ); use DateTime::Locale; -use List::MoreUtils (); use Params::Validate qw( validate_pos ); BEGIN { @@ -88,15 +87,11 @@ sub format_for { sub available_formats { my $self = shift; - # The various parens seem to be necessary to force uniq() to see - # the caller's list context. Go figure. - my @uniq - = List::MoreUtils::uniq( - map { keys %{ $_->_available_formats() || {} } } - _self_and_super_path( ref $self ) ); - - # Doing the sort in the same expression doesn't work under 5.6.x. - return sort @uniq; + my %seen; + $seen{$_}++ + foreach map { keys %{ $_->_available_formats() || {} } } + _self_and_super_path( ref $self ); + return sort keys %seen; } # Copied wholesale from Class::ISA, because said module warns as deprecated

Sun Mar 31 14:05:56 2013 DROLSKY [...] cpan.org - Queue changed from DateTime to DateTime-Locale

Tue Nov 10 11:28:57 2015 DROLSKY [...] cpan.org - Status changed from 'open' to 'resolved'

Tue Nov 10 11:28:58 2015 DROLSKY [...] cpan.org - Fixed in 1.00 added

Bug #78794 for DateTime-Locale: Speed up module load time (0.55s for me)

Preferred bug tracker