Last modified: 2014-08-28 23:33:36 UTC
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
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. :)
Hmm interesting. But that file should be in use only in MW < 1.16.
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 function #calls time memory time memory ---------------------------------------------------------------------- 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 function #calls time memory time memory ---------------------------------------------------------------------- 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 function #calls time memory time memory ---------------------------------------------------------------------- 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: * There is no newer version of jsminplus.php, and I did not find a bug tracker for the project. * Minifying the previous revision of Twinkle consumed less memory, but not dramatically so (I forgot to write it down and am too lazy to rerun the check). So it's probably not the case that some unusually aberrant syntax in the diff between those two revisions caused memory usage to balloon (which was my initial suspicion).
(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 change #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.
