Page MenuHomePhabricator

Fix memory leak in LQT->Flow conversion script
Open, LowPublic

Description

Guess is that it could be in one of the in-process caches (e.g. LocalBufferedBagOStuff).

Event Timeline

Mattflaschen-WMF updated the task description. (Show Details)
Mattflaschen-WMF raised the priority of this task from to Needs Triage.
Mattflaschen-WMF claimed this task.
Restricted Application added a project: Collaboration-Team-Triage. · View Herald TranscriptAug 10 2015, 5:36 PM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript

Change 230723 had a related patch set uploaded (by Mattflaschen):
WIP: Eliminate some memory leaks affecting LQT->Flow:

https://gerrit.wikimedia.org/r/230723

Change 230723 merged by jenkins-bot:
Eliminate some memory leaks affecting LQT->Flow:

https://gerrit.wikimedia.org/r/230723

DannyH triaged this task as Unbreak Now! priority.Aug 11 2015, 6:58 PM
DannyH added a subscriber: DannyH.

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:

https://gerrit.wikimedia.org/r/230929

Change 230929 merged by jenkins-bot:
Eliminate some memory leaks affecting LQT->Flow:

https://gerrit.wikimedia.org/r/230929

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 23513432
mattflaschen@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   355640

It 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

https://gerrit.wikimedia.org/r/231201

ori added a subscriber: ori.Aug 13 2015, 1:06 AM

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.

I've never actually tried a long page with HHVM, but it's worth a shot.

Catrope removed Mattflaschen-WMF as the assignee of this task.Aug 13 2015, 5:41 PM

@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:

https://git.wikimedia.org/blob/mediawiki%2Fextensions%2FFlow.git/215f4a015855667ee0ed6310715d17e6e9a90cdd/includes%2FData%2FBagOStuff%2FBufferedBagOStuff.php#L416

Change 231449 had a related patch set uploaded (by Mattflaschen):
Change how memcache.local_buffered/buffered are handled

https://gerrit.wikimedia.org/r/231449

Change 231449 merged by jenkins-bot:
Change how memcache.local_buffered/buffered are handled

https://gerrit.wikimedia.org/r/231449

Change 231450 had a related patch set uploaded (by Mattflaschen):
Change how memcache.local_buffered/buffered are handled

https://gerrit.wikimedia.org/r/231450

Change 231450 merged by jenkins-bot:
Change how memcache.local_buffered/buffered are handled

https://gerrit.wikimedia.org/r/231450

Mattflaschen-WMF lowered the priority of this task from Unbreak Now! to Low.Aug 14 2015, 7:33 AM
ori added a comment.Aug 14 2015, 6:25 PM

(mw1041 is now repooled.)

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.

https://gerrit.wikimedia.org/r/231201