Bug #74495 for CPAN: CPAN shell hangs reading JSON files

Sun Jan 29 01:05:16 2012 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Ticket created

Subject:

CPAN shell hangs reading JSON files

If I have many unpacked distributions in .cpan/build, CPAN sometimes hangs with 100% CPU usage after showing the list of dependencies. cpan shell -- CPAN exploration and modules installation (v1.9800) Enter 'h' for help. Show quoted text

cpan> test Dist::Zilla::PluginBundle::AVAR

Reading '/Users/sprout/.cpan/sources/authors/01mailrc.txt.gz' CPAN: Compress::Zlib loaded ok (v2.045) CPAN: YAML loaded ok (v0.78) Reading 224 yaml files from /Users/sprout/.cpan/build/ CPAN: Time::HiRes loaded ok (v1.9724) ..........................................................................DONE Restored the state of 182 (in 5.2685 secs) ............................................................................DONE Reading '/Users/sprout/.cpan/sources/modules/02packages.details.txt.gz' Database was generated on Sat, 28 Jan 2012 23:12:06 GMT HTTP::Date not available ............................................................................DONE Reading '/Users/sprout/.cpan/sources/modules/03modlist.data.gz' ............................................................................DONE Running test for module 'Dist::Zilla::PluginBundle::AVAR' Running make for H/HI/HINRIK/Dist-Zilla-PluginBundle-AVAR-0.26.tar.gz CPAN: Parse::CPAN::Meta loaded ok (v1.4401) CPAN: CPAN::Meta loaded ok (v2.113640) CPAN: Module::CoreList loaded ok (v2.60) CPAN.pm: Building H/HI/HINRIK/Dist-Zilla-PluginBundle-AVAR-0.26.tar.gz Warning: prerequisite Dist::Zilla 1.092990 not found. Warning: prerequisite Dist::Zilla::Plugin::Authority 0 not found. Warning: prerequisite Dist::Zilla::Plugin::CompileTests 0 not found. Warning: prerequisite Dist::Zilla::Plugin::MakeMaker::Awesome 0 not found. Warning: prerequisite Dist::Zilla::Plugin::MetaNoIndex 0 not found. Warning: prerequisite Dist::Zilla::Plugin::ReadmeFromPod 0.06 not found. Warning: prerequisite Dist::Zilla::PluginBundle::Filter 0 not found. Warning: prerequisite Dist::Zilla::PluginBundle::Git 1.102810 not found. Warning: prerequisite Dist::Zilla::Role::PluginBundle 0 not found. Writing Makefile for Dist::Zilla::PluginBundle::AVAR Writing MYMETA.yml and MYMETA.json Show quoted text

---- Unsatisfied dependencies detected during ---- ---- HINRIK/Dist-Zilla-PluginBundle-AVAR-0.26.tar.gz ---- Dist::Zilla::Role::PluginBundle [requires] Dist::Zilla::Plugin::CompileTests [requires] Dist::Zilla::Plugin::MakeMaker::Awesome [requires] Dist::Zilla::Plugin::Authority [requires] Dist::Zilla::Plugin::ReadmeFromPod [requires] Dist::Zilla::PluginBundle::Filter [requires] Dist::Zilla [requires] Dist::Zilla::Plugin::MetaNoIndex [requires] Dist::Zilla::PluginBundle::Git [requires] Could not read metadata file. Falling back to other methods to determine prerequisites If I attach to it with gdb and use ‘call Perl_warn(my_perl,"aaa")’, it shows a line number somewhere in JSON::PP. Continuing (the ‘c’ command) and then interrupting (ctrl-C) from time to time will sometimes show calls to perl’s internal utf8 functions that are fed strings of JSON that I can find in various unpacked distributions. So apparently CPAN.pm is parsing a lot of META.json or MYMETA.json files in all these directories. I can’t understand why it would need to do that. Whether it is doing it in some specific order and will actually finish, or whether it is stuck in a loop, I have not been able to determine.

Sun Jan 29 06:19:34 2012 ANDK [...] cpan.org - Correspondence added

I haven't seen this yet. Maybe you post your config?

Sun Jan 29 06:19:37 2012 The RT System itself - Status changed from 'new' to 'open'

Sun Jan 29 13:33:16 2012 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

On Sun Jan 29 06:19:34 2012, ANDK wrote: Show quoted text

> I haven't seen this yet. Maybe you post your config?

Attached. After cleaning out the build directory manually and starting up the CPAN shell again, I tried ‘test Dist::Zilla::PluginBundle::AVAR’ once more, and it was fast at first, but after a few dozen distributions (including some failures—maybe that’s part of the reason), it started to get slower gradually, until it was stuck for at least 30 minutes after showing one list of dependencies. I left it to go overnight and it eventually finished. So whatever it is doing is just really slow.

Subject:

MyConfig.pm

$CPAN::Config = { 'applypatch' => q[], 'auto_commit' => q[0], 'build_cache' => q[10], 'build_dir' => q[/Users/sprout/.cpan/build], 'build_dir_reuse' => q[1], 'build_requires_install_policy' => q[ask/yes], 'bzip2' => q[/usr/bin/bzip2], 'cache_metadata' => q[0], 'check_sigs' => q[0], 'colorize_output' => q[0], 'commandnumber_in_prompt' => q[0], 'connect_to_internet_ok' => q[1], 'cpan_home' => q[/Users/sprout/.cpan], 'curl' => q[/usr/bin/curl], 'ftp' => q[/usr/bin/ftp], 'ftp_passive' => q[1], 'ftp_proxy' => q[], 'getcwd' => q[cwd], 'gpg' => q[], 'gzip' => q[/usr/bin/gzip], 'halt_on_failure' => q[0], 'histfile' => q[], 'histsize' => q[500], 'http_proxy' => q[], 'inactivity_timeout' => q[0], 'index_expire' => q[1], 'inhibit_startup_message' => q[0], 'keep_source_where' => q[/Users/sprout/.cpan/sources], 'load_module_verbosity' => q[v], 'lynx' => q[], 'make' => q[/usr/bin/make], 'make_arg' => q[], 'make_install_arg' => q[-j4], 'make_install_make_command' => q[sudo make], 'makepl_arg' => q[], 'mbuild_arg' => q[ ], 'mbuild_install_arg' => q[], 'mbuild_install_build_command' => q[sudo ./Build], 'mbuildpl_arg' => q[], 'ncftp' => q[], 'ncftpget' => q[], 'no_proxy' => q[], 'pager' => q[/usr/bin/less], 'patch' => q[/usr/bin/patch], 'perl5lib_verbosity' => q[none], 'prefer_external_tar' => 1, 'prefer_installer' => q[MB], 'prefs_dir' => q[/Users/sprout/.cpan/prefs], 'prerequisites_policy' => q[follow], 'scan_cache' => q[atstart], 'shell' => q[/bin/bash], 'show_unparsable_versions' => q[0], 'show_upload_date' => q[0], 'show_zero_versions' => q[0], 'tar' => q[/usr/bin/tar], 'tar_verbosity' => q[v], 'term_is_latin' => q[0], 'term_ornaments' => q[1], 'test_report' => q[0], 'trust_test_report_history' => q[0], 'unzip' => q[/usr/bin/unzip], 'urllist' => [q[ftp://mirror.xmission.com/CPAN/], q[ftp://mirrors.24-7-solutions.net/pub/CPAN/], q[ftp://mirrors.igsobe.com/cpan/], q[ftp://mirrors.kernel.org/pub/CPAN/], q[ftp://mirrors.mednor.net/CPAN/], q[ftp://mirrors.rit.edu/CPAN/], q[ftp://mirrors1.kernel.org/pub/CPAN/], q[ftp://mirrors2.kernel.org/pub/CPAN/], q[ftp://www.stathy.com/CPAN/]], 'use_sqlite' => q[0], 'version_timeout' => q[15], 'wget' => q[], 'yaml_load_code' => q[0], 'yaml_module' => q[YAML], }; 1; __END__

Sun Jan 29 22:00:28 2012 dagolden [...] cpan.org - Correspondence added

Subject:	Re: [rt.cpan.org #74495] CPAN shell hangs reading JSON files
Date:	Sun, 29 Jan 2012 21:59:58 -0500
To:	bug-CPAN [...] rt.cpan.org
From:	David Golden <dagolden [...] cpan.org>

On Sun, Jan 29, 2012 at 1:05 AM, Father Chrysostomos via RT <bug-CPAN@rt.cpan.org> wrote: Show quoted text

> If I attach to it with gdb and use ‘call Perl_warn(my_perl,"aaa")’, it shows a line number > somewhere in JSON::PP. Continuing (the ‘c’ command) and then interrupting (ctrl-C) from > time to time will sometimes show calls to perl’s internal utf8 functions that are fed strings of > JSON that I can find in various unpacked distributions.

I'm curious if this is a JSON::PP issue or a CPAN/CPAN::Meta issue. If you install JSON::XS, do you see the same problem? -- David

Sun Jan 29 23:59:33 2012 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

On Sun Jan 29 22:00:28 2012, DAGOLDEN wrote: Show quoted text

> On Sun, Jan 29, 2012 at 1:05 AM, Father Chrysostomos via RT > <bug-CPAN@rt.cpan.org> wrote:

> > If I attach to it with gdb and use ‘call Perl_warn(my_perl,"aaa")’,

> it shows a line number

> > somewhere in JSON::PP. Continuing (the ‘c’ command) and then

> interrupting (ctrl-C) from

> > time to time will sometimes show calls to perl’s internal utf8

> functions that are fed strings of

> > JSON that I can find in various unpacked distributions.

> > I'm curious if this is a JSON::PP issue or a CPAN/CPAN::Meta issue. > > If you install JSON::XS, do you see the same problem?

Yes, and it still uses JSON::PP: $ gdb program 84663 GNU gdb 6.3.50-20050815 (Apple version gdb-1469) (Wed May 5 04:30:06 UTC 2010) Copyright 2004 Free Software Foundation, Inc. GDB is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Type "show copying" to see the conditions. There is absolutely no warranty for GDB. Type "show warranty" for details. This GDB was configured as "i386-apple-darwin"...program: No such file or directory /Users/sprout/84663: No such file or directory Attaching to process 84663. Reading symbols for shared libraries . done Reading symbols for shared libraries ................. done 0x001eb11b in Perl_utf8_length (my_perl=0x800000, s=0xa2545ad "FinderCode\",\n", ' ' <repeats 12 times>, "\"name\" : \":TestFiles\",\n", ' ' <repeats 12 times>, "\"version\" : \"4.300003\"\n },\n {\n", ' ' <repeats 12 times>, "\"class\" : \"Dist::Zilla::Plugin::FinderCode\",\n", ' ' <repeats 12 times>, "\"name\" : \":ExecFiles\",\n "..., e=0xa254889 "") at utf8.c:832 832 if (!UTF8_IS_INVARIANT(*s)) (gdb) bt #0 0x001eb11b in Perl_utf8_length (my_perl=0x800000, s=0xa2545ad "FinderCode\",\n", ' ' <repeats 12 times>, "\"name\" : \":TestFiles\",\n", ' ' <repeats 12 times>, "\"version\" : \"4.300003\"\n },\n {\n", ' ' <repeats 12 times>, "\"class\" : \"Dist::Zilla::Plugin::FinderCode\",\n", ' ' <repeats 12 times>, "\"name\" : \":ExecFiles\",\n "..., e=0xa254889 "") at utf8.c:832 #1 0x001323e0 in Perl_sv_len_utf8 (my_perl=0x800000, sv=0x33e74c0) at sv.c:6550 #2 0x001609bc in Perl_pp_substr (my_perl=0x800000) at pp.c:3093 #3 0x000c9689 in Perl_runops_debug (my_perl=0x800000) at dump.c:2119 #4 0x0002f9d9 in perl_run (my_perl=0x800000) at perl.c:2387 #5 0x00001b7b in main (argc=2, argv=0xbffff920, env=0xbffff92c) at perlmain.c:120 (gdb) call (void)Perl_warn(my_perl,"aaa") (gdb) In the other window: Show quoted text

---- Unsatisfied dependencies detected during ---- ---- HINRIK/Dist-Zilla-PluginBundle-AVAR-0.26.tar.gz ---- Dist::Zilla::Role::PluginBundle [requires] Dist::Zilla::Plugin::CompileTests [requires] Dist::Zilla::Plugin::MakeMaker::Awesome [requires] Dist::Zilla::Plugin::Authority [requires] Dist::Zilla::Plugin::ReadmeFromPod [requires] Dist::Zilla::PluginBundle::Filter [requires] Dist::Zilla [requires] Dist::Zilla::Plugin::MetaNoIndex [requires] Dist::Zilla::PluginBundle::Git [requires] Moose [requires] aaa at /usr/local/lib/perl5/5.15.7/JSON/PP.pm line 717.

Wed Feb 01 02:23:32 2012 andreas.koenig.7os6VVqR [...] franz.ak.mind.de - Correspondence added

Subject:	Re: [rt.cpan.org #74495] CPAN shell hangs reading JSON files
Date:	Wed, 01 Feb 2012 08:23:17 +0100
To:	bug-CPAN [...] rt.cpan.org
From:	andreas.koenig.7os6VVqR [...] franz.ak.mind.de (Andreas J. Koenig)

I can confirm the slowness and I observe memory growth that I cannot explain. On a 16 GB machine with an i5-2500T processor I started a cpan shell under bleadperl v5.15.7-154-g4b0b99d and called 'test Dist::Zilla::PluginBundle::AVAR' a couple of times and called ps in between. The test succeeds with this perl and every subsequent call finally answers "Has already been tested successfully" after about 5-6 minutes. USER PID %CPU %MEM VSZ RSS TTY STAT START TIME sand 31434 19.0 1.3 266932 213884 pts/19 S+ 06:37 0:10 sand 31434 27.7 2.0 397076 341972 pts/19 S+ 06:37 4:00 sand 31434 47.0 3.5 643752 588732 pts/19 S+ 06:37 9:39 sand 31434 57.7 5.1 890476 835444 pts/19 S+ 06:37 15:22 sand 31434 64.7 6.6 1137184 1082164 pts/19 S+ 06:37 21:06 sand 31434 36.7 8.1 1383908 1328876 pts/19 S+ 06:37 26:49 sand 31434 40.8 9.6 1630580 1575592 pts/19 S+ 06:37 32:56 sand 31434 44.4 11.1 1877300 1822308 pts/19 S+ 06:37 39:03 sand 31434 47.6 12.6 2124016 2069024 pts/19 S+ 06:37 45:06

Fri Feb 03 03:56:09 2012 ANDK [...] cpan.org - Correspondence added

RT-Send-CC:

dagolden [...] cpan.org

My experiment goes like this: I run "test Dist::Zilla::PluginBundle::AVAR" twice, taking a ps measurement after each. The first measurement in a process is discarded because it covers initializations. Then I switch version in the running shell, "reload cpan" and run above test again, take ps footprint, calculate the diffs. I hope the table comes out readable. | | timediff | memdiff | comment | | | | | | | Releases: | | | | | 1.9800 | 5:15 | 234 | | | 1.9600 | 4:45 | 241 | | | repeat | 4:46 | 244 | | | 1.94_63 | 1:37 | 0 | | | repeat | 1:34 | 0 | | | Tags: | | | | | 1.9600 | 5:11 | 246 | new process, not fully consistent with above | | 1.94_63 | 1:46 | 0 | | | 1.94_64 | 1:45 | 0 | | | 1.94_65 | 5:17 | 244 | | | Commits: | | | | | 330c0133 | 1:44 | 0 | starting bisecting | | f2063aa4 | 5:09 | 245 | | | da18ec3a | 5:10 | 246 | | | 896d3160 | 5:06 | 246 | gets the blame | | 90fd6686 | 1:42 | 0 | |

Fri Feb 03 04:50:24 2012 ANDK [...] cpan.org - Correspondence added

So the workaround for both speed and memory penalty is Show quoted text

cpan> o conf dontload_list push CPAN::Meta

And there was much rejoicing. No, not really. I have no idea what the cause for the leak is, so this needs to be found or at least a workaround must be put in place. Suggestions?

Fri Feb 03 08:37:19 2012 dagolden [...] cpan.org - Correspondence added

Subject:	Re: [rt.cpan.org #74495] CPAN shell hangs reading JSON files
Date:	Fri, 3 Feb 2012 08:36:51 -0500
To:	bug-CPAN [...] rt.cpan.org
From:	David Golden <dagolden [...] cpan.org>

On Fri, Feb 3, 2012 at 4:50 AM, Andreas Koenig via RT <bug-CPAN@rt.cpan.org> wrote: Show quoted text

> So the workaround for both speed and memory penalty is >

> cpan> o conf dontload_list push CPAN::Meta

> > And there was much rejoicing.

Thanks for narrowing it down. I'll see if I can replicate the memory leak just with CPAN::Meta as an isolated case and work from there. -- David

Fri Feb 03 11:51:43 2012 dagolden [...] cpan.org - Reference by ticket #74662 added

Fri Feb 03 11:53:18 2012 dagolden [...] cpan.org - Correspondence added

I've narrowed down the location of the bug and opened a ticket for it in the CPAN-Meta queue.

Fri Feb 03 22:01:43 2012 dagolden [...] cpan.org - Correspondence added

It turns out this is a memory leak involving version objects evaluated in boolean context. I've opened a perlbug ticket and will close this one. -- David

Fri Feb 03 22:01:45 2012 dagolden [...] cpan.org - Status changed from 'open' to 'resolved'