Guess is that it could be in one of the in-process caches (e.g. LocalBufferedBagOStuff).
Description
Details
Related Objects
- Mentioned In
- rMW7c95573c21a2: Updated mediawiki/core Project: mediawiki/extensions/Flow…
rEFLWa42fa42c3ac1: Change how memcache.local_buffered/buffered are handled
rMEXT348dde29a151: Updated mediawiki/extensions Project: mediawiki/extensions/Flow…
rEFLWdaec0fd3e1d8: Change how memcache.local_buffered/buffered are handled
T108972: InvalidDataException on support desk
T106614: F9. Run LQT conversion script on mediawiki.org Project:Support desk
rMW494e30149490: Updated mediawiki/core Project: mediawiki/extensions/Flow…
rEFLWa4bdad4b66a8: Eliminate some memory leaks affecting LQT->Flow:
rMEXT149ab0f431f4: Updated mediawiki/extensions Project: mediawiki/extensions/Flow…
rEFLWd9e250d1339a: Eliminate some memory leaks affecting LQT->Flow: - Mentioned Here
- T106614: F9. Run LQT conversion script on mediawiki.org Project:Support desk
Event Timeline
Change 230723 had a related patch set uploaded (by Mattflaschen):
WIP: Eliminate some memory leaks affecting LQT->Flow:
Change 230723 merged by jenkins-bot:
Eliminate some memory leaks affecting LQT->Flow:
Nothing too obvious when running convertLqtPageOnLocalWiki.php in test.wikimedia.beta.wmflabs - the process(es) properly stopped when finished and %MEM returns to normal values.
Change 230929 had a related patch set uploaded (by Mattflaschen):
Eliminate some memory leaks affecting LQT->Flow:
Change 230929 merged by jenkins-bot:
Eliminate some memory leaks affecting LQT->Flow:
See also T106614#1530532 for more background information on this.
This uses XDebug's memory profiling.
I ran:
sudo -u www-data php -d "xdebug.trace_format=1" -d "xdebug.show_mem_delta=1" -d "xdebug.auto_trace=1" /srv/mediawiki-staging/multiversion/MWScript.php extensions/Flow/maintenance/convertLqtPageOnLocalWiki.php --wiki=mediawikiwiki --debug --srcpage "Project:Support_desk/LQT_Archive_1" --logfile "/tmp/Project:Support_desk.log" | tee --append ~/2015_08_12_LQT_Flow_Support_desk_resume.log
then ran the analyzer script with two variants (including sub-calls and not)
mattflaschen@terbium:~$ php tracefile-analyser.php /tmp/trace.1139352307.0dd119.xt memory-own 20
parsing...
( 0.08%)
...
(100.00%)
Done.
Showing the 20 most costly calls sorted by 'memory-own'.
Inclusive Own
function #calls time memory time memory
------------------------------------------------------------------------------------------------------------------
json_encode 317 12.0353 896017832 12.0353 896017832
array_merge 147232 1.4293 269969864 1.4293 269969864
ApiModuleManager->addModule 185234 9.0721 155236248 4.9456 155236248
preg_replace 290062 3.8912 117905544 3.8912 117905544
array_keys 28509 0.3640 89114552 0.3640 89114552
str_replace 244076 2.1500 79318416 2.1500 79318416
Liuggio\StatsdClient\Factory\StatsdDataFactory->produceStatsdDataEntity 63186 1.7174 70103800 1.0984 70072096
AutoLoader::autoload 445 0.7737 72350848 0.2140 61333120
debug_backtrace 933 0.0956 56139288 0.0956 56139288
set_error_handler 97163 0.9352 54520600 0.9352 54520600
mysqli_result->fetch_object 23914 0.3867 49990184 0.3867 49990184
Title::makeTitle 7641 1.5886 48073432 0.6851 45175272
ApiMain->getAllowedParams 5495 0.1234 43879192 0.1234 43879192
func_get_args 33872 0.3100 40455064 0.3100 40455064
MWNamespace::getCanonicalNamespaces 6582 0.1185 40900432 0.1121 39949072
array_filter 103355 0.9158 39144784 0.8824 38880368
array_map 14269 0.4878 35109208 0.2360 33892208
explode 44764 0.4198 30705184 0.4198 30705184
preg_match 122175 1.3806 29076304 1.3806 29076304
str_ireplace 12474 0.2096 23513432 0.2096 23513432mattflaschen@terbium:~$ php tracefile-analyser.php /tmp/trace.1139352307.0dd119.xt memory-inclusive 20
parsing...
( 0.08%)
...
(100.00%)
Done.
Showing the 20 most costly calls sorted by 'memory-inclusive'.
Inclusive Own
function #calls time memory time memory
------------------------------------------------------------------------------------------------------------------
json_encode 317 12.0353 896017832 12.0353 896017832
array_merge 147232 1.4293 269969864 1.4293 269969864
call_user_func_array 126187 222.4631 195126944 0.4437 18641248
Flow\Import\LiquidThreadsApi\LocalApiBackend->apiCall 917 126.5677 170261944 0.0742 6310264
ApiModuleManager->addModules 9170 12.7245 169866432 2.3002 15455416
Hooks::run 60012 112.7617 163740768 5.4085 -205797128
ApiModuleManager->addModule 185234 9.0721 155236248 4.9456 155236248
Flow\Import\Postprocessor\LqtRedirector->afterTopicImported 308 181.9841 152943504 0.0150 24640
Flow\Import\Postprocessor\ProcessorGroup->call 618 182.0619 152482880 0.0152 -558000
Flow\Import\Postprocessor\ProcessorGroup->afterTopicImported 616 182.0756 152480232 0.0107 -197304
Flow\Import\LiquidThreadsApi\CachedData->getMulti 1320 113.9530 148248048 0.0328 3070424
Flow\Import\LiquidThreadsApi\CachedData->get 1320 114.0018 147697792 0.0344 -2965240
Flow\Import\LiquidThreadsApi\CachedData->ensureLoaded 1320 113.9201 145177624 0.0694 -42775296
preg_replace 290062 3.8912 117905544 3.8912 117905544
ApiBase->getFinalParams 8556 10.9517 109443024 0.2535 -715104
ApiMain->__construct 917 10.0481 105398504 0.1481 5970824
ApiModuleManager->getModule 1834 10.2599 102756648 0.0460 825088
Liuggio\StatsdClient\Factory\StatsdDataFactory->increment 61846 12.5000 102693968 1.0014 14287480
ApiModuleManager->instantiateModule 1834 10.2139 101931560 0.0525 5552904
Flow\Import\LiquidThreadsApi\ApiBackend->retrievePageData 310 71.5395 101308400 0.0086 355640It makes it seem like json_encode is using a lot of memory (and there is a report about a json_encode memory leak). However, I'm not sure if this fully takes into account when things are freed/GCed.
Change 231201 had a related patch set uploaded (by Mattflaschen):
Add explicit calls to the garbage collector every 100 topics
Since this leak does not appear to occur with HHVM, I suggested temporarily depooling an HHVM app server and setting it aside for @Mattflaschen to use. I'm going to use mw1041 for this purpose.
@matthiasmullie Looking at my change again, I'm worried about the impact of separating 'memcache.buffered' and 'memcache.local_buffered'.
The indexes and such still use 'memcache.local_buffered', and I think that means they may not be committed, leading to a cache fill.
Actually, I think the ones that were still using memcache.local_buffered were being committed to cache immediately since that's what defer does if it's not in a transaction:
Change 231449 had a related patch set uploaded (by Mattflaschen):
Change how memcache.local_buffered/buffered are handled
Change 231449 merged by jenkins-bot:
Change how memcache.local_buffered/buffered are handled
Change 231450 had a related patch set uploaded (by Mattflaschen):
Change how memcache.local_buffered/buffered are handled
Change 231450 merged by jenkins-bot:
Change how memcache.local_buffered/buffered are handled
Change 231201 abandoned by Mattflaschen:
Add explicit calls to the garbage collector every 100 topics
Reason:
Abandoning this for now. This is a little hacky, and we don't have any huge boards to convert right now.