Always the same error message:
PHP Fatal error: Allowed memory size of 146800640 bytes exhausted (tried to allocate 629392 bytes) in /www/w/includes/libs/jsminplus.php on line 1680
Version: 1.22.0
Severity: normal
Always the same error message:
PHP Fatal error: Allowed memory size of 146800640 bytes exhausted (tried to allocate 629392 bytes) in /www/w/includes/libs/jsminplus.php on line 1680
Version: 1.22.0
Severity: normal
As a workaround for now, disable the parsing checks by setting $wgResourceLoaderValidateJS = false;
Looks like the culprit is the bundled jquery-ui in Translate extension; I can get it to fail very reliably on that file setting the overall memory limit to 53M or below when parsing it standalone in a maint script (jsparse.php added in r91908):
brion@stormcloud:/var/www/trunk$ php maintenance/jsparse.php --memory-limit=54M extensions/Translate/js/jquery-ui-1.7.2.custom.min.js
extensions/Translate/js/jquery-ui-1.7.2.custom.min.js OK
brion@stormcloud:/var/www/trunk$ php maintenance/jsparse.php --memory-limit=53M extensions/Translate/js/jquery-ui-1.7.2.custom.min.js
PHP Fatal error: Allowed memory size of 55574528 bytes exhausted (tried to allocate 86 bytes) in /var/www/trunk/includes/libs/jsminplus.php on line 1162
PHP Stack trace:
PHP 1. {main}() /var/www/trunk/maintenance/jsparse.php:0
PHP 2. require_once() /var/www/trunk/maintenance/jsparse.php:72
PHP 3. JSParseHelper->execute() /var/www/trunk/maintenance/doMaintenance.php:105
PHP 4. JSParser->parse() /var/www/trunk/maintenance/jsparse.php:55
PHP 5. JSParser->Script() /var/www/trunk/includes/libs/jsminplus.php:616
PHP 6. JSParser->Statements() /var/www/trunk/includes/libs/jsminplus.php:625
PHP 7. JSParser->Statement() /var/www/trunk/includes/libs/jsminplus.php:639
PHP 8. JSParser->Expression() /var/www/trunk/includes/libs/jsminplus.php:956
PHP 9. JSParser->FunctionDefinition() /var/www/trunk/includes/libs/jsminplus.php:1209
PHP 10. JSParser->Script() /var/www/trunk/includes/libs/jsminplus.php:1002
PHP 11. JSParser->Statements() /var/www/trunk/includes/libs/jsminplus.php:625
PHP 12. JSParser->Statement() /var/www/trunk/includes/libs/jsminplus.php:639
PHP 13. JSParser->Expression() /var/www/trunk/includes/libs/jsminplus.php:956
PHP 14. JSParser->Expression() /var/www/trunk/includes/libs/jsminplus.php:1314
PHP 15. JSParser->FunctionDefinition() /var/www/trunk/includes/libs/jsminplus.php:1209
PHP 16. JSParser->Script() /var/www/trunk/includes/libs/jsminplus.php:1002
PHP 17. JSParser->Statements() /var/www/trunk/includes/libs/jsminplus.php:625
PHP 18. JSParser->Statement() /var/www/trunk/includes/libs/jsminplus.php:639
PHP 19. JSParser->ParenExpression() /var/www/trunk/includes/libs/jsminplus.php:679
PHP 20. JSParser->Expression() /var/www/trunk/includes/libs/jsminplus.php:1432
If there's enough another stuff going on, hitting a larger limit when processing that is not inconceivable.
Since these should be static files anyway, they're not essential to be parsing anyway; will probably switch it over to only apply this by default on wiki-sourced JS modules, which usually won't be giant bulk libraries in one piece like this. :)
Indeed; further it's loaded via OutputPage::addScriptFile not ResourceLoader at all...
Must be dying on something else -- probably the core jquery.js which is also largeish (but not large enough to die with my default memory limits at present)
Ok, r91914 adds finer-grained $wgResourceLoaderValidateStaticJS (defaults off), so on a default setup we'll now only run the validation on modules backed by wiki pages, which are the most error-prone. (Gadgets, user & site JS pages)
If any reqs are still dying with this setting, you might have some giant user/site/gadget JS pages. :)
(In reply to comment #2)
Hmm interesting. But that file should be in use only in MW < 1.16.
Does that make this report obsolete / WONTFIX?
(In reply to comment #2)
Hmm interesting. But that file should be in use only in MW < 1.16.
Niklas / Brion: Does that make this report obsolete / WONTFIX nowadays?
AFAICS, the problem was that even later versions had the problem even though they shouldn't. That said, per comment 4 prio is probably lower.
(In reply to comment #1)
As a workaround for now, disable the parsing checks by setting
$wgResourceLoaderValidateJS = false;
translatewiki.net still has this.
http://en.wikipedia.org/w/index.php?title=MediaWiki:Gadget-Twinkle.js&action=raw&oldid=557261853 appears to have tripped up OOMs, too.
I think there's a bad leak in jsminplus.php, and my hunch is that it has something to do with keeping references to substring copies of the input buffer.
To investigate this, I added the following line to the bottom of jsminplus.php:
JSMinPlus::minify( file_get_contents( $argv[1] ) );
This allows it to be invoked against some file from the command line.
I then downloaded the version of Twinkle that was causing crashes:
curl "https://en.wikipedia.org/w/index.php?title=MediaWiki:Gadget-Twinkle.js&action=raw&oldid=557261853" -o twinkle-557261853.js
I then ran:
$ /usr/bin/time -v php --no-php-ini jsminplus.php twinkle-557261853.js 2>&1 | grep Maximum
Maximum resident set size (kbytes): 215552
That's 210.5 megabytes. Yikes.
This is with PHP 5.3.10-1ubuntu3.6+wmf1 with Suhosin-Patch. I ran the same command on one of the Apaches and got a similar result.
On #wikimedia-operations, Azatoth was trying to reproduce these measurements, but memory consumption on his machine was much lower: around 35 megabytes. He is running PHP 5.4.4-14+deb7u1. I upgrade a test machine to 5.4.15-1~precise+1 to see if perhaps the underlying cause was a memory leak that had been fixed in PHP. With that version, memory usage went down to 127 megabytes -- much lower, but still very high. I don't know why Azatoth was getting such different results.
I ran jsminplus.php under XDebug (this was with 5.3.10-1ubuntu3.6+wmf1) to produce a function trace and a cachegrind file. Both are too large to attach here. I ran tracefile-analyser.php (available in the contrib/ subfolder of XDebug's trunk) to produce the following reports:
Showing the 25 most costly calls sorted by 'memory-inclusive'.
Inclusive Own
JSTokenizer->getInput 165360 114.4447 12172424424 75.0972 13841944
substr 167744 39.9809 12158771784 39.9809 12158771784
preg_match 272096 63.2338 37906160 63.2338 37906160
rtrim 3925 0.9227 35834032 0.9227 35834032
JSMinPlus->parseTree 56734 97.3480 20106208 2.7083 -34902944
func_get_args 16804 3.8140 17558600 3.8140 17558600
JSNode->addNode 59938 14.1259 16062936 14.1259 16062936
JSParser->Variables 1017 170.5382 15314304 3.1037 3815424
JSTokenizer->get 116567 390.5212 9476264 170.0294 -12200722168
JSTokenizer->match 39648 139.7419 7702976 19.8020 2129472
JSParser->reduce 8715 40.7495 6143944 21.1107 -137456
array_push 49937 11.4957 6061784 11.4957 6061784
JSParser->nest 35 21.1327 4364896 0.0329 0
JSNode->__set 23239 5.3959 3797512 5.3959 3797512
JSTokenizer->peek 22443 70.8936 3206192 10.5485 0
JSTokenizer->mustMatch 20217 105.4872 2770336 13.4861 -1633224
JSTokenizer->isDone 5546 33.2490 2109248 2.4946 446064
array_splice 8554 2.0875 2043416 2.0875 2043416
JSParser->ParenExpression 663 56.9034 1954440 0.6503 0
{main} 1 823.7359 1948864 0.0220 208
JSParser->Statements 1183 823.5497 1429432 0.0037 1688
JSParser->Statement 6302 823.5046 1425056 0.0030 1800
JSParser->Expression 11273 823.4974 1422832 0.0190 11928
JSMinPlus::minify 1 823.5846 1406040 0.0005 672
JSParser->FunctionDefinition 365 823.3641 1405944 0.0069 -103608
Showing the 25 most costly calls sorted by 'memory-own'.
Inclusive Own
substr 167744 39.9809 12158771784 39.9809 12158771784
preg_match 272096 63.2338 37906160 63.2338 37906160
rtrim 3925 0.9227 35834032 0.9227 35834032
func_get_args 16804 3.8140 17558600 3.8140 17558600
JSNode->addNode 59938 14.1259 16062936 14.1259 16062936
JSTokenizer->getInput 165360 114.4447 12172424424 75.0972 13841944
array_push 49937 11.4957 6061784 11.4957 6061784
JSParser->Variables 1017 170.5382 15314304 3.1037 3815424
JSNode->set 23239 5.3959 3797512 5.3959 3797512
JSTokenizer->match 39648 139.7419 7702976 19.8020 2129472
array_splice 8554 2.0875 2043416 2.0875 2043416
JSTokenizer->unget 34685 8.1175 587496 8.1175 587496
file_get_contents 1 0.0162 538608 0.0162 538608
JSTokenizer->isDone 5546 33.2490 2109248 2.4946 446064
JSNode->get 156169 38.4977 124376 38.4977 124376
JSMinPlus->isValidIdentifier 964 1.1048 78888 0.6843 78888
array_map 1 0.0002 15840 0.0002 15840
JSParser->Expression 11273 823.4974 1422832 0.0190 11928
JSMinPlus->isWordChar 148 0.0970 11904 0.0636 11904
define 97 0.0193 4008 0.0193 4008
JSParser->construct 1 0.0012 2520 0.0003 2240
JSParser->Statement 6302 823.5046 1425056 0.0030 1800
JSParser->Statements 1183 823.5497 1429432 0.0037 1688
JSTokenizer->init 1 0.0002 856 0.0002 856
JSMinPlus->construct 1 0.0015 3208 0.0004 688
Showing the 25 most costly calls sorted by 'time-own'.
Inclusive Own
JSTokenizer->get 116567 390.5212 9476264 170.0294 -12200722168
JSTokenizer->getInput 165360 114.4447 12172424424 75.0972 13841944
preg_match 272096 63.2338 37906160 63.2338 37906160
JSNode->construct 67494 98.8944 -2112880 56.9707 -28682112
substr 167744 39.9809 12158771784 39.9809 12158771784
JSNode->get 156169 38.4977 124376 38.4977 124376
strlen 126407 28.8690 0 28.8690 0
JSTokenizer->currentToken 108812 25.2751 80 25.2751 80
JSParser->reduce 8715 40.7495 6143944 21.1107 -137456
JSTokenizer->match 39648 139.7419 7702976 19.8020 2129472
func_num_args 67494 15.2409 0 15.2409 0
JSNode->addNode 59938 14.1259 16062936 14.1259 16062936
JSTokenizer->mustMatch 20217 105.4872 2770336 13.4861 -1633224
array_push 49937 11.4957 6061784 11.4957 6061784
JSTokenizer->peek 22443 70.8936 3206192 10.5485 0
substr_count 37358 8.5390 0 8.5390 0
JSTokenizer->unget 34685 8.1175 587496 8.1175 587496
in_array 31880 7.3246 0 7.3246 0
count 31500 7.2972 0 7.2972 0
array_pop 31298 7.1604 -6043640 7.1604 -6043640
JSNode->__set 23239 5.3959 3797512 5.3959 3797512
end 16918 3.9226 0 3.9226 0
func_get_args 16804 3.8140 17558600 3.8140 17558600
JSParser->Variables 1017 170.5382 15314304 3.1037 3815424
JSMinPlus->parseTree 56734 97.3480 20106208 2.7083 -34902944
Cachegrind file:
http://kubo.wmflabs.org/cachegrind.out.3012.gz
Xdebug function trace (trace_format=1):
http://kubo.wmflabs.org/trace.105056044.xt.gz
Two other details I forgot to mention:
(In reply to comment #8)
To investigate this, I added the following line to the bottom of
jsminplus.php:JSMinPlus::minify( file_get_contents( $argv[1] ) );
Note this is actually going to be using less memory than what ResourceLoader actually does. JSMinPlus::minify passes itself to the JSParser constructor, which causes it to trim the node tree for the body of each function. ResourceLoader passes null, so this isn't done.
We could easily enough get that advantage in RL by passing JSParser an instance of this:
class DummyMinifier { function parseTree() { return null; } }
If we really want to cut the memory usage, though, we could add a mode to do the same sort of pruning even more aggressively, maybe on every statement instead of only on every function body.
On #wikimedia-operations, Azatoth was trying to reproduce these measurements,
but memory consumption on his machine was much lower: around 35 megabytes. He
is running PHP 5.4.4-14+deb7u1. I upgrade a test machine to
5.4.15-1~precise+1
to see if perhaps the underlying cause was a memory leak that had been fixed
in
PHP. With that version, memory usage went down to 127 megabytes -- much
lower,
but still very high. I don't know why Azatoth was getting such different
results.
Me neither. On my local machine, with Debian's 5.4.15-1, I get around 42M.
I think there's a bad leak in jsminplus.php, and my hunch is that it has
something to do with keeping references to substring copies of the input
buffer.
It looks like the problem is just that jsminplus builds up a huge tree of JSNode objects (i.e. 86487 of them). Dumping this tree doesn't show copies of the input buffer.
However, I do see that it makes temporary copies of large substrings of the input buffer very often, because it treats "no comment" the same as "comment longer than $chunksize" for some unknown reason. This can be reduced by adding the following check just before line 1864:
// If it's not possibly a comment (or regex), exit the loop if ($input[0] !== '/') break;
Even though these temporary copies are soon freed, they still cause memory usage spikes. Although even after making this change, XDebug seems to be reporting that PHP is still allocating 128K memory buffers associated with calls to JSTokenizer::get for no obvious reason.
Can this be closed? We no longer use JSMinPlus. Looks like it still exist in the repository though, should it be removed?
(In reply to comment #11)
Can this be closed? We no longer use JSMinPlus. Looks like it still exist in
the repository though, should it be removed?
MaxSem was going to remove it in gerrit 74283, also thinking it was unused. It is actually still used for syntax checking of user/site JS, though not for minification.
Bumping priority (since this is still affecting production if you have a large gadget or user script).
Mentioning JsMinPlus in title for easier finding via search.
Change 359191 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] [WIP] benchmarks: Add benchmark for JSMinPlus
[mediawiki/core@master] benchmarks: Add benchmark for JSMinPlus
Example output:
vagrant@mediawiki-vagrant:/vagrant/mediawiki$ mwscript maintenance/benchmarks/benchmarkJSMinPlus.php --file resources/lib/jquery/jquery.js -v --count 100 Running PHP version 5.6.30-0+deb8u1 (x86_64) on Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.39-1 (2016-12-30) # 0 - memory: 73.25 MB - peak: 73.75 MB # 1 - memory: 73 MB - peak: 73.75 MB # 2 - memory: 73.25 MB - peak: 73.75 MB # 3 - memory: 73.25 MB - peak: 73.75 MB # 4 - memory: 73.5 MB - peak: 73.75 MB # 5 - memory: 73.75 MB - peak: 74 MB # 6 - memory: 74 MB - peak: 74.25 MB # 7 - memory: 74.25 MB - peak: 74.5 MB # 8 - memory: 74.5 MB - peak: 74.75 MB # 9 - memory: 74.75 MB - peak: 75 MB # 10 - memory: 75 MB - peak: 75.25 MB # 11 - memory: 75.25 MB - peak: 75.5 MB # 12 - memory: 75.25 MB - peak: 75.75 MB # 13 - memory: 75.5 MB - peak: 75.75 MB # 14 - memory: 75.25 MB - peak: 76 MB # 15 - memory: 75.5 MB - peak: 76 MB # 16 - memory: 75.5 MB - peak: 76 MB # 17 - memory: 75.5 MB - peak: 76 MB # 18 - memory: 75.5 MB - peak: 76 MB # 19 - memory: 75.75 MB - peak: 76 MB # 20 - memory: 75.75 MB - peak: 76.25 MB # 21 - memory: 76 MB - peak: 76.25 MB # 22 - memory: 76 MB - peak: 76.5 MB # 23 - memory: 76 MB - peak: 76.5 MB # 24 - memory: 76 MB - peak: 76.5 MB # 25 - memory: 76 MB - peak: 76.5 MB # 26 - memory: 76.25 MB - peak: 76.5 MB # 27 - memory: 76.25 MB - peak: 76.75 MB # 28 - memory: 76.25 MB - peak: 76.75 MB # 29 - memory: 76.25 MB - peak: 76.75 MB # 30 - memory: 76.5 MB - peak: 76.75 MB # 31 - memory: 76 MB - peak: 77 MB # 32 - memory: 76 MB - peak: 77 MB # 33 - memory: 76 MB - peak: 77 MB # 34 - memory: 76 MB - peak: 77 MB # 35 - memory: 76 MB - peak: 77 MB # 36 - memory: 76.25 MB - peak: 77 MB # 37 - memory: 76 MB - peak: 77 MB # 38 - memory: 76 MB - peak: 77 MB # 39 - memory: 76 MB - peak: 77 MB # 40 - memory: 76 MB - peak: 77 MB # 41 - memory: 76.25 MB - peak: 77 MB # 42 - memory: 76 MB - peak: 77 MB # 43 - memory: 76 MB - peak: 77 MB # 44 - memory: 76 MB - peak: 77 MB # 45 - memory: 76 MB - peak: 77 MB # 46 - memory: 76 MB - peak: 77 MB # 47 - memory: 76 MB - peak: 77 MB # 48 - memory: 76.25 MB - peak: 77 MB # 49 - memory: 76.5 MB - peak: 77 MB # 50 - memory: 76.5 MB - peak: 77 MB # 51 - memory: 76.25 MB - peak: 77 MB # 52 - memory: 76.25 MB - peak: 77 MB # 53 - memory: 76.25 MB - peak: 77 MB # 54 - memory: 76.25 MB - peak: 77 MB # 55 - memory: 76.25 MB - peak: 77 MB # 56 - memory: 76.25 MB - peak: 77 MB # 57 - memory: 76 MB - peak: 77 MB # 58 - memory: 76 MB - peak: 77 MB # 59 - memory: 76 MB - peak: 77 MB # 60 - memory: 76 MB - peak: 77 MB # 61 - memory: 76 MB - peak: 77 MB # 62 - memory: 76 MB - peak: 77 MB # 63 - memory: 76 MB - peak: 77 MB # 64 - memory: 76 MB - peak: 77 MB # 65 - memory: 76.25 MB - peak: 77 MB # 66 - memory: 76 MB - peak: 77 MB # 67 - memory: 76 MB - peak: 77 MB # 68 - memory: 76 MB - peak: 77 MB # 69 - memory: 76 MB - peak: 77 MB # 70 - memory: 76 MB - peak: 77 MB # 71 - memory: 76 MB - peak: 77 MB # 72 - memory: 76 MB - peak: 77 MB # 73 - memory: 76 MB - peak: 77 MB # 74 - memory: 76 MB - peak: 77 MB # 75 - memory: 76 MB - peak: 77 MB # 76 - memory: 76.25 MB - peak: 77 MB # 77 - memory: 76.5 MB - peak: 77 MB # 78 - memory: 76.5 MB - peak: 77 MB # 79 - memory: 76.5 MB - peak: 77 MB # 80 - memory: 76.25 MB - peak: 77 MB # 81 - memory: 76.25 MB - peak: 77 MB # 82 - memory: 76.25 MB - peak: 77 MB # 83 - memory: 76.25 MB - peak: 77 MB # 84 - memory: 76 MB - peak: 77 MB # 85 - memory: 76 MB - peak: 77 MB # 86 - memory: 76 MB - peak: 77 MB # 87 - memory: 76 MB - peak: 77 MB # 88 - memory: 76 MB - peak: 77 MB # 89 - memory: 76 MB - peak: 77 MB # 90 - memory: 76 MB - peak: 77 MB # 91 - memory: 76 MB - peak: 77 MB # 92 - memory: 76 MB - peak: 77 MB # 93 - memory: 76 MB - peak: 77 MB # 94 - memory: 76 MB - peak: 77 MB # 95 - memory: 76 MB - peak: 77 MB # 96 - memory: 76 MB - peak: 77 MB # 97 - memory: 76 MB - peak: 77 MB # 98 - memory: 76 MB - peak: 77 MB # 99 - memory: 76 MB - peak: 77 MB JSParser::parse (jquery.js) times: 100 total: 165384.25ms min: 1533.54ms median: 1650.38ms mean: 1653.84ms max: 1777.70ms Current memory usage: 76 MB Peak memory usage: 77 MB
It seems to keep increasing during the first 30 runs, but then stays at 77 MB.
Here's another run, using https://en.wikipedia.org/w/index.php?title=MediaWiki:Gadget-Twinkle.js&action=raw&oldid=557261853 as input instead.
vagrant@mediawiki-vagrant:/vagrant/mediawiki$ mwscript maintenance/benchmarks/benchmarkJSMinPlus.php --file twinkle.js --count 200 -v Running PHP version 5.6.30-0+deb8u1 (x86_64) on Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.39-1 (2016-12-30) # 0 - memory: 86 MB - peak: 86.5 MB # 1 - memory: 85 MB - peak: 87.5 MB # 2 - memory: 85.25 MB - peak: 87.5 MB # 3 - memory: 85.5 MB - peak: 87.5 MB # 4 - memory: 85.75 MB - peak: 87.5 MB # 5 - memory: 86 MB - peak: 87.5 MB # 6 - memory: 86.25 MB - peak: 87.5 MB # 7 - memory: 86.5 MB - peak: 87.75 MB # 8 - memory: 86.75 MB - peak: 88 MB # 9 - memory: 87 MB - peak: 88.25 MB # 10 - memory: 87.25 MB - peak: 88.5 MB # 11 - memory: 87.5 MB - peak: 88.75 MB # 12 - memory: 87.75 MB - peak: 89 MB # 13 - memory: 88 MB - peak: 89.25 MB # 14 - memory: 88.25 MB - peak: 89.5 MB # 15 - memory: 88.5 MB - peak: 89.75 MB # 16 - memory: 88.75 MB - peak: 90 MB # 17 - memory: 88.25 MB - peak: 90.25 MB # 18 - memory: 88.5 MB - peak: 90.25 MB # 19 - memory: 88.75 MB - peak: 90.25 MB # 20 - memory: 89 MB - peak: 90.25 MB # 21 - memory: 89.25 MB - peak: 90.5 MB # 22 - memory: 88.5 MB - peak: 90.75 MB # 23 - memory: 88.75 MB - peak: 90.75 MB # 24 - memory: 89 MB - peak: 90.75 MB # 25 - memory: 89.25 MB - peak: 90.75 MB # 26 - memory: 89.25 MB - peak: 90.75 MB # 27 - memory: 88.75 MB - peak: 90.75 MB # 28 - memory: 89 MB - peak: 90.75 MB # 29 - memory: 89 MB - peak: 90.75 MB # 30 - memory: 89.25 MB - peak: 90.75 MB # 31 - memory: 89.25 MB - peak: 90.75 MB # 32 - memory: 89 MB - peak: 90.75 MB # 33 - memory: 89.25 MB - peak: 90.75 MB # 34 - memory: 89.25 MB - peak: 90.75 MB # 35 - memory: 89.5 MB - peak: 90.75 MB # 36 - memory: 89.75 MB - peak: 91 MB # 37 - memory: 89.5 MB - peak: 91.25 MB # 38 - memory: 89.75 MB - peak: 91.25 MB # 39 - memory: 90 MB - peak: 91.25 MB # 40 - memory: 90.25 MB - peak: 91.5 MB # 41 - memory: 90.5 MB - peak: 91.75 MB # 42 - memory: 90.25 MB - peak: 92 MB # 43 - memory: 90.25 MB - peak: 92 MB # 44 - memory: 90.5 MB - peak: 92 MB # 45 - memory: 90.75 MB - peak: 92 MB # 46 - memory: 91 MB - peak: 92.25 MB # 47 - memory: 90 MB - peak: 92.5 MB # 48 - memory: 90.25 MB - peak: 92.5 MB # 49 - memory: 90.5 MB - peak: 92.5 MB # 50 - memory: 90.75 MB - peak: 92.5 MB # 51 - memory: 91 MB - peak: 92.5 MB # 52 - memory: 90.25 MB - peak: 92.5 MB # 53 - memory: 90.25 MB - peak: 92.5 MB # 54 - memory: 90.5 MB - peak: 92.5 MB # 55 - memory: 90.75 MB - peak: 92.5 MB # 56 - memory: 91 MB - peak: 92.5 MB # 57 - memory: 90.75 MB - peak: 92.5 MB # 58 - memory: 90.25 MB - peak: 92.5 MB # 59 - memory: 90.5 MB - peak: 92.5 MB # 60 - memory: 90.75 MB - peak: 92.5 MB # 61 - memory: 91 MB - peak: 92.5 MB # 62 - memory: 90.75 MB - peak: 92.5 MB # 63 - memory: 90.5 MB - peak: 92.5 MB # 64 - memory: 90.75 MB - peak: 92.5 MB # 65 - memory: 91 MB - peak: 92.5 MB # 66 - memory: 91.25 MB - peak: 92.5 MB # 67 - memory: 91 MB - peak: 92.75 MB # 68 - memory: 91.25 MB - peak: 92.75 MB # 69 - memory: 91.25 MB - peak: 92.75 MB # 70 - memory: 91.5 MB - peak: 92.75 MB # 71 - memory: 91.75 MB - peak: 93 MB # 72 - memory: 91.25 MB - peak: 93.25 MB # 73 - memory: 91 MB - peak: 93.25 MB # 74 - memory: 91.25 MB - peak: 93.25 MB # 75 - memory: 91.5 MB - peak: 93.25 MB # 76 - memory: 91.75 MB - peak: 93.25 MB # 77 - memory: 91.25 MB - peak: 93.25 MB # 78 - memory: 91.25 MB - peak: 93.25 MB # 79 - memory: 91.5 MB - peak: 93.25 MB # 80 - memory: 91.75 MB - peak: 93.25 MB # 81 - memory: 92 MB - peak: 93.25 MB # 82 - memory: 91.5 MB - peak: 93.5 MB # 83 - memory: 91.25 MB - peak: 93.5 MB # 84 - memory: 91.5 MB - peak: 93.5 MB # 85 - memory: 91.75 MB - peak: 93.5 MB # 86 - memory: 92 MB - peak: 93.5 MB # 87 - memory: 92.25 MB - peak: 93.5 MB # 88 - memory: 92 MB - peak: 93.75 MB # 89 - memory: 92 MB - peak: 93.75 MB # 90 - memory: 92.25 MB - peak: 93.75 MB # 91 - memory: 92.5 MB - peak: 93.75 MB # 92 - memory: 92.25 MB - peak: 94 MB # 93 - memory: 92.5 MB - peak: 94 MB # 94 - memory: 92.75 MB - peak: 94 MB # 95 - memory: 93 MB - peak: 94.25 MB # 96 - memory: 93.25 MB - peak: 94.5 MB # 97 - memory: 92.5 MB - peak: 94.75 MB # 98 - memory: 92.5 MB - peak: 94.75 MB # 99 - memory: 92.75 MB - peak: 94.75 MB #100 - memory: 93 MB - peak: 94.75 MB #101 - memory: 93.25 MB - peak: 94.75 MB #102 - memory: 93 MB - peak: 94.75 MB #103 - memory: 92.75 MB - peak: 94.75 MB #104 - memory: 93 MB - peak: 94.75 MB #105 - memory: 93.25 MB - peak: 94.75 MB #106 - memory: 93.5 MB - peak: 94.75 MB #107 - memory: 93.25 MB - peak: 95 MB #108 - memory: 93.5 MB - peak: 95 MB #109 - memory: 93.75 MB - peak: 95 MB #110 - memory: 94 MB - peak: 95.25 MB #111 - memory: 94.25 MB - peak: 95.5 MB #112 - memory: 93.25 MB - peak: 95.75 MB #113 - memory: 93.25 MB - peak: 95.75 MB #114 - memory: 93.5 MB - peak: 95.75 MB #115 - memory: 93.75 MB - peak: 95.75 MB #116 - memory: 94 MB - peak: 95.75 MB #117 - memory: 93.5 MB - peak: 95.75 MB #118 - memory: 93.25 MB - peak: 95.75 MB #119 - memory: 93.5 MB - peak: 95.75 MB #120 - memory: 93.75 MB - peak: 95.75 MB #121 - memory: 94 MB - peak: 95.75 MB #122 - memory: 94 MB - peak: 95.75 MB #123 - memory: 94.25 MB - peak: 95.75 MB #124 - memory: 94.25 MB - peak: 95.75 MB #125 - memory: 94.5 MB - peak: 95.75 MB #126 - memory: 94.75 MB - peak: 96 MB #127 - memory: 94.25 MB - peak: 96.25 MB #128 - memory: 94.5 MB - peak: 96.25 MB #129 - memory: 94.5 MB - peak: 96.25 MB #130 - memory: 94.75 MB - peak: 96.25 MB #131 - memory: 95 MB - peak: 96.25 MB #132 - memory: 94.5 MB - peak: 96.5 MB #133 - memory: 94 MB - peak: 96.5 MB #134 - memory: 94.25 MB - peak: 96.5 MB #135 - memory: 94.5 MB - peak: 96.5 MB #136 - memory: 94.75 MB - peak: 96.5 MB #137 - memory: 94.25 MB - peak: 96.5 MB #138 - memory: 94.25 MB - peak: 96.5 MB #139 - memory: 94.5 MB - peak: 96.5 MB #140 - memory: 94.75 MB - peak: 96.5 MB #141 - memory: 94.75 MB - peak: 96.5 MB #142 - memory: 94.5 MB - peak: 96.5 MB #143 - memory: 94 MB - peak: 96.5 MB #144 - memory: 94.25 MB - peak: 96.5 MB #145 - memory: 94.5 MB - peak: 96.5 MB #146 - memory: 94.5 MB - peak: 96.5 MB #147 - memory: 94.25 MB - peak: 96.5 MB #148 - memory: 94.5 MB - peak: 96.5 MB #149 - memory: 94.75 MB - peak: 96.5 MB #150 - memory: 95 MB - peak: 96.5 MB #151 - memory: 95.25 MB - peak: 96.5 MB #152 - memory: 95 MB - peak: 96.75 MB #153 - memory: 94.75 MB - peak: 96.75 MB #154 - memory: 95 MB - peak: 96.75 MB #155 - memory: 95.25 MB - peak: 96.75 MB #156 - memory: 95.5 MB - peak: 96.75 MB #157 - memory: 95.25 MB - peak: 97 MB #158 - memory: 95 MB - peak: 97 MB #159 - memory: 95.25 MB - peak: 97 MB #160 - memory: 95.5 MB - peak: 97 MB #161 - memory: 95.5 MB - peak: 97 MB #162 - memory: 95 MB - peak: 97 MB #163 - memory: 95.25 MB - peak: 97 MB #164 - memory: 95.5 MB - peak: 97 MB #165 - memory: 95.5 MB - peak: 97 MB #166 - memory: 95.5 MB - peak: 97 MB #167 - memory: 94.75 MB - peak: 97 MB #168 - memory: 95 MB - peak: 97 MB #169 - memory: 95.25 MB - peak: 97 MB #170 - memory: 95.5 MB - peak: 97 MB #171 - memory: 95.75 MB - peak: 97 MB #172 - memory: 95.5 MB - peak: 97.25 MB #173 - memory: 95.75 MB - peak: 97.25 MB #174 - memory: 96 MB - peak: 97.25 MB #175 - memory: 96.25 MB - peak: 97.5 MB #176 - memory: 96.5 MB - peak: 97.75 MB #177 - memory: 95.25 MB - peak: 98 MB #178 - memory: 95.5 MB - peak: 98 MB #179 - memory: 95.75 MB - peak: 98 MB #180 - memory: 96 MB - peak: 98 MB #181 - memory: 96.25 MB - peak: 98 MB #182 - memory: 95.75 MB - peak: 98 MB #183 - memory: 95.75 MB - peak: 98 MB #184 - memory: 96 MB - peak: 98 MB #185 - memory: 96.25 MB - peak: 98 MB #186 - memory: 96.5 MB - peak: 98 MB #187 - memory: 95.75 MB - peak: 98 MB #188 - memory: 96 MB - peak: 98 MB #189 - memory: 96.25 MB - peak: 98 MB #190 - memory: 96.5 MB - peak: 98 MB #191 - memory: 96.5 MB - peak: 98 MB #192 - memory: 96 MB - peak: 98 MB #193 - memory: 96 MB - peak: 98 MB #194 - memory: 96.25 MB - peak: 98 MB #195 - memory: 96 MB - peak: 98 MB #196 - memory: 96.25 MB - peak: 98 MB #197 - memory: 96 MB - peak: 98 MB #198 - memory: 96.25 MB - peak: 98 MB #199 - memory: 96.25 MB - peak: 98 MB JSParser::parse (twinkle.js) times: 200 total: 781317.67ms min: 3237.34ms median: 3945.98ms mean: 3906.59ms max: 4708.13ms Current memory usage: 96.25 MB Peak memory usage: 98 MB
It starts at 86MB (10MB higher than with jquery.js) and doesn't seem to stop increasing. Where jquery.js parsing stopped growing after iteration 30, this one keeps increasing until at least iteration 175 when it reaches 98 MB. Growth slows down, so I'm not sure whether it really stopped or not.
Change 359191 merged by jenkins-bot:
[mediawiki/core@master] benchmarks: Add benchmark for JSMinPlus
Made some progress towards finding the memory leak. I added __destruct handlers on all the classes used by JSMinPlus. Then, running it from the command-line shows which objects get dereferenced at the end of the minification call, and which stay until the end of the process and get destructed only then. (Thanks to @tstarling for the idea!)
diff --git a/includes/libs/jsminplus.php b/includes/libs/jsminplus.php index 40f22c5efb..7d139b39ee 100644 --- a/includes/libs/jsminplus.php +++ b/includes/libs/jsminplus.php @@ -1624,6 +1625,7 @@ class JSParser class JSCompilerContext { + public function __destruct() { if ($GLOBALS['debugEnd']) { echo "destruct " . spl_object_hash( $this ) . " " . __CLASS__ . "\n"; } } public $inFunction = false; public $inForLoopInit = false; public $ecmaStrictMode = false; @@ -1644,6 +1646,7 @@ class JSCompilerContext class JSNode { + public function __destruct() { if ($GLOBALS['debugEnd']) { echo "destruct " . spl_object_hash( $this ) . " " . __CLASS__ . "\n"; } } private $type; private $value; private $lineno; @@ -1708,6 +1711,7 @@ class JSNode class JSTokenizer { + public function __destruct() { if ($GLOBALS['debugEnd']) { echo "destruct " . spl_object_hash( $this ) . " " . __CLASS__ . "\n"; } } private $cursor = 0; private $source; @@ -2125,6 +2129,8 @@ class JSTokenizer class JSToken { + public function __destruct() { if ($GLOBALS['debugEnd']) { echo "destruct " . spl_object_hash( $this ) . " " . __CLASS__ . "\n"; } } public $type; public $value; public $start; diff --git a/maintenance/benchmarks/benchmarkJSMinPlus.php b/maintenance/benchmarks/benchmarkJSMinPlus.php index dc92516018..f6868f9fed 100644 --- a/maintenance/benchmarks/benchmarkJSMinPlus.php +++ b/maintenance/benchmarks/benchmarkJSMinPlus.php @@ -45,6 +45,7 @@ class BenchmarkJSMinPlus extends Benchmarker { } $filename = basename( $this->getOption( 'file' ) ); + $GLOBALS['debugEnd'] = false; $parser = new JSParser(); $this->bench( [ @@ -55,6 +56,7 @@ class BenchmarkJSMinPlus extends Benchmarker { 'args' => [ $parser, $content, $filename ] ] ] ); + $GLOBALS['debugEnd'] = true; } }
On a simple run for a 1-line file like resources/src/moment-global.js, I could already see a few objects remaining.
$ mwscript maintenance/benchmarks/benchmarkJSMinPlus.php --file resources/src/moment-global.js --count 10 Running PHP version 5.6.30-0+deb8u1 (x86_64) on Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.39-1 (2016-12-30) JSParser::parse (moment-global.js) times: 10 total: 2.97ms min: 0.26ms median: 0.27ms mean: 0.30ms max: 0.46ms Current memory usage: 17 MB Peak memory usage: 17 MB destruct 0000000048fdc5ea0000000007758941 JSTokenizer destruct 0000000048fdc5e90000000007758941 JSToken destruct 0000000048fdc5f00000000007758941 JSToken destruct 0000000048fdc5f40000000007758941 JSToken destruct 0000000048fdc5eb0000000007758941 JSToken
This suggests the leak starts with JSTokenizer. Running it with count 1 or count 100 didn't make any difference. Looking through the code, this makes sense given there is only ever one instance of it. It is re-used between parser iterations and reset at the start of each run. It doesn't reset itself at the end of a run, so it keeps a small imprint of the last run, but that's fairly innocent. Disabled that one for now with the below patch,
diff --git a/includes/libs/jsminplus.php b/includes/libs/jsminplus.php index 40f22c5efb..bbf6249b5e 100644 --- a/includes/libs/jsminplus.php +++ b/includes/libs/jsminplus.php @@ -727,12 +727,12 @@ class JSParser public function __construct($minifier=null) { $this->minifier = $minifier; - $this->t = new JSTokenizer(); } public function parse($s, $f, $l) { // initialize tokenizer + $this->t = new JSTokenizer(); $this->t->init($s, $f, $l); $x = new JSCompilerContext(false); @@ -740,6 +740,7 @@ class JSParser if (!$this->t->isDone()) throw $this->t->newSyntaxError('Syntax error'); + $this->t = null; return $n; }
After this, the simple run with benchmarkJSMinPlus.php --file resources/src/moment-global.js --count 10 no longer showed any leaks.
Going on with the larger example of jquery.js, immediately shows over 1500 JSNode objects remaining in memory.
JSParser::parse (jquery.js) times: 1 ... Current memory usage: 71.5 MB Peak memory usage: 72 MB destruct 000000005613a6ab0000000062a2a2d2 JSNode destruct 000000005613a6a80000000062a2a2d2 JSNode destruct 000000005613a6a90000000062a2a2d2 JSNode ...
The first one being dereferenced:
class JSNode { + public function __destruct() { if ($GLOBALS['debugEnd']) { + echo "destruct " . spl_object_hash( $this ) . " " . __CLASS__ . "\n"; + var_dump($this); + exit; + } }
destruct 00000000068f6008000000005e78bf20 JSNode class JSNode#593 (13) { private $type => int(103) # JS_FOR_IN private $value => string(3) "for" private $lineno => int(205) private $start => int(5087) private $end => int(5090) public $treeNodes => array(0) {} public $funDecls => array(0) {} public $varDecls => array(0) {} public $isLoop => bool(true) public $iterator => class JSNode#594 (8) { private $type => int(3) # TOKEN_IDENTIFIER private $value => string(4) "name" private $lineno => int(205) private $start => int(5093) private $end => int(5097) public $treeNodes => array(0) {} public $funDecls => array(0) {} public $varDecls => array(0) {} } public $varDecl => NULL public $object => class JSNode#595 (8) { private $type => int(3) # TOKEN_IDENTIFIER private $value => string(7) "options" private $lineno => int(205) private $start => int(5101) private $end => int(5108)
Which represents the following input snippet:
201 for ( ; i < length; i++ ) { 202 // Only deal with non-null/undefined values 203 if ( (options = arguments[ i ]) != null ) { 204 // Extend the base object 205 for ( name in options ) { 206 src = target[ name ]; 207 copy = options[ name ];
I couldn't reproduce it with just the for-in loop itself. Copied the whole jQuery.extend method and narrowed it down to any continue statement basically:
while ( 0 ) { continue; }
$ mwscript maintenance/benchmarks/benchmarkJSMinPlus.php --file maintenance/benchmarks/sample.js --count 1 JSParser::parse (sample.js) times: 1 total: 0.40ms.. max: 0.40ms Current memory usage: 17 MB Peak memory usage: 17 MB destruct 00000000203d352c0000000037cca76f JSNode type: while, value: while destruct 00000000203d35290000000037cca76f JSNode type: 2, value: 0 destruct 00000000203d35370000000037cca76f JSNode type: 101, value: { destruct 00000000203d35360000000037cca76f JSNode type: continue, value: continue
$ mwscript maintenance/benchmarks/benchmarkJSMinPlus.php --file maintenance/benchmarks/sample.js --count 2 .. destruct 000000002ddfe9c4000000006fac1bc2 JSNode type: while, value: while destruct 000000002ddfe9c2000000006fac1bc2 JSNode type: while, value: while destruct 000000002ddfe9c1000000006fac1bc2 JSNode type: 2, value: 0 destruct 000000002ddfe9df000000006fac1bc2 JSNode type: 101, value: { destruct 000000002ddfe9de000000006fac1bc2 JSNode type: continue, value: continue destruct 000000002ddfe9dd000000006fac1bc2 JSNode type: 2, value: 0 destruct 000000002ddfe9db000000006fac1bc2 JSNode type: 101, value: { destruct 000000002ddfe9da000000006fac1bc2 JSNode type: continue, value: continue
Etc., growing after each iteration.
Any block levels in the tree between continue and the outer for loop or while loop are being held in memory.
Change 362117 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] jsminplus: Fix JSNode memory leak from 'continue' statements
Even with this 3-line sample file, the leak is measurable given enough iterations:
$ mwscript maintenance/benchmarks/benchmarkJSMinPlus.php --file maintenance/benchmarks/sample.js --count 5000 --verbose Running PHP version 5.6.30-0+deb8u1 (x86_64) on Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.39-1 (2016-12-30) # 0 - memory: 17 MB - peak: 20.25 MB # 1 - memory: 19 MB - peak: 20.25 MB # 2 - memory: 19 MB - peak: 20.25 MB # 3 - memory: 19 MB - peak: 20.25 MB # 4 - memory: 19 MB - peak: 20.25 MB # 5 - memory: 19 MB - peak: 20.25 MB .. #546 - memory: 21.25 MB - peak: 21.25 MB #547 - memory: 21.25 MB - peak: 21.25 MB .. #4998 - memory: 33.5 MB - peak: 33.5 MB #4999 - memory: 33.5 MB - peak: 33.5 MB JSParser::parse (sample.js) times: 5000 total: 1.7s median: 0.31ms
As it appears specific to the continue statement (and it is freed up last), I added some extra logging to dump object from the __destruct handler.
destruct 0000000003200bbf000000001436935b JSNode type: continue, value: continue class JSNode#10086 (9) { private $type => string(8) "continue" private $value => string(8) "continue" .. public $target => class JSNode#10077 (11) { private $type => string(5) "while" private $value => string(5) "while" .. public $condition => class JSNode#10088 (8) { private $type => int(2) private $value => string(1) "0" .. } public $body => class JSNode#10084 (8) { private $type => int(101) private $value => string(1) "{" .. } } }
It appears to store a reference to the JSNode for the while statement in a target property. However, the JSNode class declares no such property. This property is only referenced once in jsminplus.php, and that's in JSParser::Statement when it sees KEYWORD_CONTINUE. It's not read or otherwise used anywhere in the program.
class JSParser { .. private function Statement($x) { .. switch ($tt) { .. case KEYWORD_BREAK: case KEYWORD_CONTINUE: $n = new JSNode($this->t); .. $n->target = $ss[$i]; break;
Commenting out fixed the leak.
mwscript maintenance/benchmarks/benchmarkJSMinPlus.php --file maintenance/benchmarks/sample.js --count 5000 --verbose Running PHP version 5.6.30-0+deb8u1 (x86_64) on Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.39-1 (2016-12-30) # 0 - memory: 17 MB - peak: 20.25 MB # 1 - memory: 19 MB - peak: 20.25 MB #4999 - memory: 20.25 MB - peak: 20.25 MB
Peak start-end (before fix) | Peak start-end (after fix) | |
---|---|---|
sample.js (5000x) | 20.25M -> 33.5M | 20.25M – 20.25M |
jquery.js (100x) | 73.75 MB -> 77M | 73.75 MB -> 74 MB |
Change 362117 merged by jenkins-bot:
[mediawiki/core@master] jsminplus: Fix JSNode memory leak from 'continue' statements