Page MenuHomePhabricator

mwscript rebuildLocalisationCache.php takes 40 minutes on HHVM (rather than ~5 on PHP 5)
Closed, ResolvedPublic

Description

When running a full scap sync as part of train we shell out to MediaWiki to use mwscript rebuildLocalisationCache.php. When using php5 this took between 5-10 minutes. Using HHVM this takes 40 minutes.

But we can't use php5 anymore after https://gerrit.wikimedia.org/r/#/c/425026/

And there are blockers to using php7 (T172165)

so it seems like we're between a rock and a hard place and that we have to figure out why hhvm takes so much longer otherwise scap sync will take an addition 30 minutes every time.

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes

Profiling info for rebuilding a single file via the command:

mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/thcipriani-l10nupdate --threads=1 --lang=en

==> php5 <==
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 71.76    5.819986      831427         7         3 wait4
 23.74    1.925016          16    117286           write
  0.67    0.054353          16      3405         4 lstat
  0.59    0.047723          39      1239        25 stat
  0.53    0.042748          13      3175           fstat
  0.42    0.033746          22      1552         2 read
  0.34    0.027765          25      1121        10 open
  0.32    0.025759          25      1018       212 access
  0.28    0.022592          19      1192         2 close
  0.27    0.022089          24       913           mmap
  0.27    0.022065          31       710           munmap
  0.23    0.018728         480        39           poll
  0.14    0.011014          45       243           brk
  0.10    0.008394        2099         4           select
  0.07    0.005713          32       176           mprotect
  0.06    0.005082        5082         1           nanosleep
  0.05    0.004390          11       402         3 lseek
  0.02    0.001865         373         5           execve

==> hhvm -v Eval.Jit=false <==
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 69.80   46.971521     6710217         7         3 wait4
 19.20   12.917497          14    922469           getrusage
  5.27    3.547834          13    270798           lseek
  3.31    2.230772          19    117144           write
  0.82    0.549315          14     39435         2 read
  0.45    0.305550          14     22187         1 fcntl
  0.33    0.220516          16     13577     11479 access
  0.30    0.201759          12     17200           fstat
  0.18    0.124413        2439        51           poll
  0.08    0.054005          14      3848           lstat
  0.05    0.035929          21      1729        44 open
  0.05    0.030655          27      1152        25 stat
  0.04    0.026710          15      1746         2 close
  0.03    0.021643          27       805           mmap
  0.02    0.012746        4249         3           set_robust_list
  0.02    0.010809          24       447           munmap
  0.01    0.008681          37       234           mprotect
  0.01    0.006976          50       139         1 readlink

What could it be wait4ing for?

What could it be wait4ing for?

Probably a red herring in this instance. There are 7 wait4 calls and there are 3 errors. There are 4 subprocesses that get start started as a result of the mwscript command. So 4 wait4 calls where there were actual child processes waiting on the 4 subprocesses. One of those wait4 calls was waiting on:

execve("/usr/bin/php", ["php", "/srv/mediawiki-staging/multiversion/MWScript.php", "rebuildLocalisationCache.php", "--wiki=enwiki", "--outdir=/tmp/thcipriani-l10nupdate", "--threads=1", "--lang=en"], [/* 18 vars */]) = 0

Which would take some time.

I'm interested in getrusage seems like a profiling thing. Maybe a profiling thing we could turn off?

fwrite is definitely different in hhvm -- accounts for all the lseek in the hhvm output: https://gist.github.com/thcipriani/6c8c7b13fe31df644bd8b7f8ee52b383

Joe added a comment.Apr 11 2018, 5:18 AM

What are the blockers for the use of PHP7?

All I see on the ticket mentioned is the memcached issue, which ops are working on right now. It should be fixed in 1-2 weeks.

Is the localisation cache currently generated incompletey as a consequence of that bug? I reimaged an app server with stretch and it logs this exception at a high rate (so I depooled it again):

mw1265 hhvm: #012Warning: Destructor threw an object exception: exception 'MWException' with message 'No localisation cache found for English. Please run
​maintenance/rebuildLocalisationCache.php.' in /srv/mediawiki/php-1.31.0-wmf.29/includes/cache/localisation/LocalisationCache.php:477#012Stack trace:#012#0 /srv/mediawiki/php-1.31.0-wmf.29/includes/cache/localisation/LocalisationCache.php(334): LocalisationCache->initLanguage()#012#1 /srv/mediawiki/php-1.31.0-wmf.29/includes/cache/localisation/LocalisationCache.php(271): LocalisationCache->loadItem()#012#2 /srv/mediawiki/php-1.31.0-wmf.29/languages/Language.php(600): LocalisationCache->getItem()#012#3 /srv/mediawiki/php-1.31.0-wmf.29/includes/title/MediaWikiTitleCodec.php(85): Language->needsGenderDistinction()#012#4 /srv/mediawiki/php-1.31.0-wmf.29/includes/Title.php(1041): MediaWikiTitleCodec->getNamespaceName()#012#5 /srv/mediawiki/php-1.31.0-wmf.29/includes/Title.php(1596): Title->getNsText()#012#6 /srv/mediawiki/php-1.31.0-wmf.29/includes/Title.php(1615): Title->prefix()#012#7 /srv/mediawiki/php-1.31.0-wmf.29/includes/Title.php(1928): Title->getPrefixedDBkey()#012#8 /srv/mediawiki/php-1.31.0-wmf.29/includes/Title.php(2061): Title->getLocalURL()#012#9 /srv/mediawiki/php-1.31.0-wmf.29/extensions/CentralAuth/includes/CentralAuthUtils.php(93): Title->getCanonicalURL()#012#10 /srv/mediawiki/php-1.31.0-wmf.29/extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php(378): CentralAuthUtils::setP3P()#012#11 /srv/mediawiki/php-1.31.0-wmf.29/includes/session/SessionBackend.php(695): CentralAuthSessionProvider->unpersistSession()#012#12 /srv/mediawiki/php-1.31.0-wmf.29/includes/session/SessionBackend.php(596): MediaWiki\Session\SessionBackend->save()#012#13 (): Closure$MediaWiki\Session\SessionBackend::delaySave()#012#14 /srv/mediawiki/php-1.31.0-wmf.29/vendor/wikimedia/scoped-callback/src/ScopedCallback.php(76): call_user_func_array()#012#15 /srv/mediawiki/php-1.31.0-wmf.29/vendor/wikimedia/scoped-callback/src/ScopedCallback.php(56): Wikimedia\ScopedCallback->__destruct()#012#16 /srv/mediawiki/php-1.31.0-wmf.29/includes/session/SessionManager.php(886): Wikimedia\ScopedCallback::consume()#012#17 /srv/mediawiki/php-1.31.0-wmf.29/includes/session/SessionManager.php(310): MediaWiki\Session\SessionManager->getSessionFromInfo()#012#18 /srv/mediawiki/php-1.31.0-wmf.29/includes/session/SessionManager.php(244): MediaWiki\Session\SessionManager->getEmptySessionInternal()#012#19 /srv/mediawiki/php-1.31.0-wmf.29/includes/session/SessionManager.php(194): MediaWiki\Session\SessionManager->getEmptySession()#012#20 /srv/mediawiki/php-1.31.0-wmf.29/includes/WebRequest.php(736): MediaWiki\Session\SessionManager->getSessionForRequest()#012#21 /srv/mediawiki/php-1.31.0-wmf.29/includes/session/SessionManager.php(130): WebRequest->getSession()#012#22 /srv/mediawiki/php-1.31.0-wmf.29/includes/Setup.php(848): MediaWiki\Session\SessionManager::getGlobalSession()#012#23 /srv/mediawiki/php-1.31.0-wmf.29/includes/WebStart.php(90): include()#012#24 /srv/mediawiki/php-1.31.0-wmf.29/index.php(39): include()#012#25 /srv/mediawiki/w/index.php(3): include()#012#26 {main} in /srv/mediawiki/php-1.31.0-wmf.29/vendor/wikimedia/scoped-callback/src/ScopedCallback.php on line 56

Pretty sure that's unrelated....but I've definitely seen it before. Mostly when running maintenance scripts from tin instead of terbium. It kinda makes sense, considering tin wouldn't have the l10n cache locally (and I think mwscript tries to run it out of mediawiki-staging when on the deploy hosts).

The newly imaged host would be fixed by a full scap or by forcing l10n rebuild on that individual machine. Ideally, provisioning a new Apache should do this automatically?

For deploy masters/cli operations, we can probably add something to core that basically kicks off an l10n rebuild automatically at that point?

Pretty sure that's unrelated....but I've definitely seen it before. Mostly when running maintenance scripts from tin instead of terbium. It kinda makes sense, considering tin wouldn't have the l10n cache locally (and I think mwscript tries to run it out of mediawiki-staging when on the deploy hosts).
The newly imaged host would be fixed by a full scap or by forcing l10n rebuild on that individual machine. Ideally, provisioning a new Apache should do this automatically?

Would that be a different command than "scap pull"? I ran that before (and usually /srv/mediawiki is fully provisioned after a fresh install)

No, that should've done it :(

Comparing the freshly installed app server (mw1265) with an existing one (mw1264) also shows that /srv/mediawiki/php-1.31.0-wmf.29/cache/l10n contains identical l10n_cache-en.cdb files

Comparing the freshly installed app server (mw1265) with an existing one (mw1264) also shows that /srv/mediawiki/php-1.31.0-wmf.29/cache/l10n contains identical l10n_cache-en.cdb files

This seems to have been temporary, although I don't have a good explanation why: I've pooled mw1265 for another ~15 mins of production traffic and that all worked fine, the error I quoted above didn't reoccur. I'll keep an eye on it as we proceed reimaging.

As suggested in IRC, I ran perf record for rebuilding only the English language cdb in beta (since perf requires root).

Not sure how to interpret results, I did see a lot of symbols referred to here in https://github.com/facebook/hhvm/blob/master/hphp/doc/hackers-guide/bytecode-interpreter.md#interpreter-dispatch-loop:

[thcipriani@deployment-tin ~]$ sudo -E perf record sudo -E -u www-data -- mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/thcipriani-
l10nupdate --threads=1 --lang=en
Rebuilding en...
1 languages rebuilt out of 1
[ perf record: Woken up 3 times to write data ]
[ perf record: Captured and wrote 0.816 MB perf.data (18425 samples) ]
[thcipriani@deployment-tin ~]$ sudo perf report --stdio
Failed to open /tmp/perf-1109.map, continuing without symbols
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 18K of event 'cpu-clock'
# Event count (approx.): 4606250000
#
# Overhead  Command   Shared Object                  Symbol
# ........  ........  .............................  ..................................................................................................
#
    16.34%  php       hhvm                           [.] HPHP::dispatchImpl<false>
     4.14%  php       hhvm                           [.] HPHP::instrCanHalt
     4.09%  php       hhvm                           [.] HPHP::decode_op
     3.90%  php       [kernel.kallsyms]              [k] __lock_text_start
     3.64%  php       [kernel.kallsyms]              [k] system_call_fast_compare
     2.01%  php       libc-2.19.so                   [.] __GI___getrusage
     1.59%  php       hhvm                           [.] HPHP::handle_request_surprise
     1.59%  php       libc-2.19.so                   [.] vfprintf
     1.38%  php       hhvm                           [.] .l26394
     1.11%  php       libjemalloc.so.1               [.] malloc
     1.09%  php       hhvm                           [.] HPHP::HierarchicalProfiler::endFrameEx
     1.08%  php       hhvm                           [.] HPHP::vmfp
     1.06%  php       hhvm                           [.] HPHP::Func::findFPI
     0.89%  php       [kernel.kallsyms]              [k] copy_user_enhanced_fast_string
     0.89%  php       hhvm                           [.] HPHP::Stack::pushVal<(HPHP::DataType)17, long>
     0.74%  php       hhvm                           [.] HPHP::MixedArray::Release
     0.74%  php       hhvm                           [.] HPHP::MD5Transform
     0.72%  php       libjemalloc.so.1               [.] free
     0.72%  php       [kernel.kallsyms]              [k] kmem_cache_alloc
     0.68%  php       hhvm                           [.] HPHP::decode<long>
     0.65%  php       hhvm                           [.] HPHP::cellBitAnd
     0.62%  php       hhvm                           [.] HPHP::NamedEntity::getCachedFunc
     0.60%  php       hhvm                           [.] HPHP::(anonymous namespace)::cellArithO<HPHP::(anonymous namespace)::Add, bool (*)(long, long)
     0.60%  php       hhvm                           [.] HPHP::Native::callFunc<false>
     0.53%  php       libpthread-2.19.so             [.] 0x000000000000f08d
     0.52%  php       hhvm                           [.] HPHP::arFromInstr
     0.51%  php       hhvm                           [.] folly::AtomicHashArray<unsigned long, HPHP::rds::Link<HPHP::TypedValue, false>, HPHP::(anonymo
     0.50%  php       hhvm                           [.] HPHP::prepareFuncEntry
thcipriani triaged this task as High priority.Apr 18 2018, 7:58 PM

From scap today: 19:37:56 Finished l10n-update (duration: 39m 12s)
30-40 minutes beta-scap-eqiad runs: https://integration.wikimedia.org/ci/job/beta-scap-eqiad/buildTimeTrend

I managed to grab a better perf report by using PHP='hhvm -vEval.PerfPidMap=true'. Then I waited for beta-scap-eqiad to start rebuildLocalisationCache and I recorded the event via: sudo perf record -g --call-graph dwarf -p $PID

P7014 is the report I got from: sudo perf report -g --stdio

@thcipriani Is this with or without translation cache (TC) and JIT?

This uses the value from /etc/hhvm/php.ini: hhvm.jit = false.

Played with -vEval.Jit=1 yesterday and it was quite a bit slower:

1[thcipriani@deployment-tin ~]$ sudo -u www-data -- sh -c 'rm -rf /tmp/thcipriani-l10nupdate && mkdir /tmp/thcipriani-l10nupdate'
2[thcipriani@deployment-tin ~]$ export PHP='hhvm -vEval.Jit=0'
3[thcipriani@deployment-tin ~]$ time sudo -E -u www-data -- mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/thcipriani-l10nupdate --threads=6 --lang=en
4Rebuilding en...
5
6real 0m7.109s
7user 0m3.520s
8sys 0m1.064s
9[thcipriani@deployment-tin ~]$ sudo -u www-data -- sh -c 'rm -rf /tmp/thcipriani-l10nupdate && mkdir /tmp/thcipriani-l10nupdate'
10[thcipriani@deployment-tin ~]$ export PHP='hhvm -vEval.Jit=1'
11[thcipriani@deployment-tin ~]$ time sudo -E -u www-data -- mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/thcipriani-l10nupdate --threads=6 --lang=en
12Rebuilding en...
13
14real 0m28.654s
15user 0m19.628s
16sys 0m3.700s

@thcipriani Hm.. these are seconds though, as opposed to minutes. Is there something different about these commands? I'm asking because on a short-lived process, JIT indeed adds more overhead than is worth. But if we're talking about a 40min process, JIT has got to speed things up. I'd be confused if it doesn't.

@thcipriani Hm.. these are seconds though, as opposed to minutes. Is there something different about these commands?

The --lang=en flag. Rebuilding a single language rather than 408 languages. I'll try the full rebuild with jit enabled.

Joe added a comment.Apr 23 2018, 6:56 AM

@thcipriani Hm.. these are seconds though, as opposed to minutes. Is there something different about these commands? I'm asking because on a short-lived process, JIT indeed adds more overhead than is worth. But if we're talking about a 40min process, JIT has got to speed things up. I'd be confused if it doesn't.

Given the way the JIT (used to) work in HHVM, I'd be surprise if it does speed things up - but we should surely test and confirm it.

using Eval.Jit=1 does actually seem faster on deployment-tin, anyway

[thcipriani@deployment-tin ~]$ export PHP='hhvm -vEval.Jit=1'
[thcipriani@deployment-tin ~]$ time sudo -E -u www-data -- mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/thcipriani-l10nupdate --threads=6
[...]
real    16m27.911s
user    11m36.524s
sys     4m44.920s
[thcipriani@deployment-tin ~]$ export PHP='hhvm -vEval.Jit=0'
[thcipriani@deployment-tin ~]$ time sudo -E -u www-data -- mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/thcipriani-l10nupdate --threads=6
[...]
real    28m56.778s
user    23m21.984s
sys     5m18.964s
Legoktm added a subscriber: Legoktm.EditedApr 26 2018, 5:39 AM

What are the blockers for the use of PHP7?
All I see on the ticket mentioned is the memcached issue, which ops are working on right now. It should be fixed in 1-2 weeks.

T184854 is now closed as resolved so I'll reiterate @Joe's question: are there any other blockers from just using PHP 7?

Macro full-steam-ahead: PHP7 full steam ahead

I've put a straw-man up at T176370#4161855.

Change 430602 had a related patch set uploaded (by Greg Grossmeier; owner: Thcipriani):
[integration/config@master] Change beta-scap-eqiad timeout to 60 minutes

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

Change 430602 merged by jenkins-bot:
[integration/config@master] Change beta-scap-eqiad timeout to 60 minutes

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

Paladox added a subscriber: Paladox.May 9 2018, 5:40 PM

coulden't a new flag be added that switches between php7.0 and hhvm?

I've put a straw-man up at T176370#4161855.

Seems reasonable, but I'm not sure all of that is necessary if we're just talking about flipping one script over to PHP 7 right now.

(..) I'm not sure all of that is necessary if we're just talking about flipping one script over to PHP 7 right now.

Yeah, let's not over-engineer this. I've written a proposal at T175288 , I'd like to hear RelEngs input in particular.

Reedy added a comment.May 24 2018, 1:43 PM

Interestingly for 1 branch of rebuildLocalisationCache.php

tin hhvm

real    40m32.809s

tin php5

real	24m13.240s

mwmaint1001 hhvm

real	16m59.381s

mwmaint1001 php7

real	4m35.088s

cf T195393#4228562

tin php5

real	24m13.240s

This result seems confusing to me. Doesn't match what I've been seeing on deployment-tin or in-practice. Looking back through scap logs:

From February when we were still using php5, rebuilding l10n-cache took 6 minutes as part of a release of a new version (https://tools.wmflabs.org/sal/log/AWHYvoP_kkJ8OkTwiIMQ)

thcipriani@mwlog1001:/srv/mw-log$ zgrep -i 'finished l10n-' /srv/mw-log/archive/scap.log-20180228.gz | jq '.'                                         
{                                                                                                                                                     
  "script": "/usr/bin/scap",
  "process": 47887,
  "@version": 1,
  "@timestamp": "2018-02-27T19:37:48Z",
  "module": "log",
  "funcName": "_record_elapsed",
  "host": "tin",
  "pathname": "/usr/lib/python2.7/dist-packages/scap/log.py",
  "user": "thcipriani",
  "message": "Finished l10n-update (duration: 06m 00s)",
  "filename": "log.py",
  "type": "scap",
  "levelname": "INFO",
  "channel": "timer",
  "lineno": 748
}

vs fairly recently with HHVM, rebuilding l10n-cache took 76 minutes as part of a release of a new version (https://tools.wmflabs.org/sal/log/AWL4yhlJCdtJF089I_kV):

thcipriani@mwlog1001:/srv/mw-log$ zgrep -i 'finished l10n-' /srv/mw-log/archive/scap.log-20180425.gz | jq '.'                                         
{                                                                                                                                                     
  "script": "/usr/bin/scap",
  "process": 38819,
  "@version": 1,
  "@timestamp": "2018-04-24T19:10:50Z",
  "module": "log",
  "funcName": "_record_elapsed",
  "host": "tin",
  "pathname": "/usr/lib/python2.7/dist-packages/scap/log.py",
  "user": "demon",
  "message": "Finished l10n-update (duration: 76m 04s)",
  "filename": "log.py",
  "type": "scap",
  "levelname": "INFO",
  "channel": "timer",
  "lineno": 748
}

rebuildLocalisationCache is the bulk of what is being timed inside Finished l10n-update: https://github.com/wikimedia/scap/blob/5c3646ad20df9c872ba6c62cc9ceae3f1e7ee219/scap/tasks.py#L532-L544

Reedy added a comment.May 24 2018, 4:19 PM
reedy@tin:~$ time PHP=php5 mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/l10nstuff3
408 languages rebuilt out of 408

real    24m37.609s
user    21m2.040s
sys     1m29.780s

Result looks fairly replicable to me

reedy@tin:~$ time PHP=php5 mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/l10nstuff3
408 languages rebuilt out of 408
real    24m37.609s
user    21m2.040s
sys     1m29.780s

Result looks fairly replicable to me

Probably to do with the --threads option, I suppose. Or something else specific to the way scap invokes it. The php7 result looks heartening.

Jdforrester-WMF renamed this task from mwscript rebuildLocalisationCache.php takes 40 minutes to mwscript rebuildLocalisationCache.php takes 40 minutes on HHVM (rather than ~5 on PHP 5).May 24 2018, 4:26 PM
Reedy added a comment.Jun 1 2018, 1:08 AM
reedy@mwmaint1001:~$ time PHP='hhvm -vEval.Jit=1' mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/l10nstuff
real    11m45.815s
Reedy added a comment.Jun 1 2018, 1:43 AM

The previous was with an unclean outdir...

This one is clean, dunno if it actually makes much/any difference (it was definitely out of date, so would've needed a rebuild)

reedy@mwmaint1001:~$ sudo -u www-data rm -rf /tmp/l10nstuff/*
reedy@mwmaint1001:~$ time PHP='hhvm -vEval.Jit=1' mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/l10nstuff
real    11m7.750s
reedy@mwmaint1001:~$ sudo -u www-data rm -rf /tmp/l10nstuff/*
reedy@mwmaint1001:~$ time PHP='hhvm -vEval.Jit=0' mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/l10nstuff
real    17m0.403s

I wonder why are we testing rebuildLocalisationCache.php with --threads option, as I don't know anyone running the script without it.

reedy@mwmaint1001:~$ sudo -u www-data rm -rf /tmp/l10nstuff/*
reedy@mwmaint1001:~$ time PHP='hhvm -vEval.Jit=1' mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/l10nstuff
real    11m7.750s

I wonder why are we testing rebuildLocalisationCache.php with --threads option, as I don't know anyone running the script without it.

(I assume you mean "without" instead of "with"). There is no particular reason why we tested with or without that option. Looking through this task, I see various results with and various results without. In fact, as mentioned at T176370#4247721, several quick tests indicate the script runs slower when using multiple threads.

In any event, a few one-off tests below

# 6 threads: Matching what @thcipriani used and seems to correlate to the default used by Scap on Beta Cluster (8 cores - 2)
mwmaint1001:~$ time PHP='hhvm -vEval.Jit=1' mwscript rebuildLocalisationCache.php --wiki=enwiki --threads=6 --outdir=/tmp/l10nstuff-krinkle1
real	10m35.274s

# 30 threads: Based on what I think Scap's default is in production (32 cores - 2)
mwmaint1001:~$ time PHP='hhvm -vEval.Jit=1' mwscript rebuildLocalisationCache.php --wiki=enwiki --threads=30 --outdir=/tmp/l10nstuff-krinkle2
real	12m10.013s

# 1 thread (MW default): Baseline
mwmaint1001:~$ time PHP='hhvm -vEval.Jit=1' mwscript rebuildLocalisationCache.php --wiki=enwiki --threads=1 --outdir=/tmp/l10nstuff-krinkle3
real	10m29.323s

# 15 threads: Random comparison
mwmaint1001:~$ time PHP='hhvm -vEval.Jit=1' mwscript rebuildLocalisationCache.php --wiki=enwiki --threads=15 --outdir=/tmp/l10nstuff-krinkle4
real	10m42.160s

It seems to be fairly constant, and while it might be a coincidence, it appears to run consistently slower with more threads:

  • 1 thread (32 cores): 10m 29s
  • 6 threads (32 cores): 10m 35s
  • 15 threads (32 cores): 10m 42s
  • 30 threads (32 cores): 12m 10s
Reedy added a comment.Jun 1 2018, 2:22 PM

More threads means more I/O contention... Not really unexpected. It's finding that balance :)

Krenair added a subscriber: Krenair.Aug 6 2018, 4:32 PM
hashar added a subscriber: hashar.

I have hit that today. From my dupe task T203458 :

rebuildLocalisationCache.php is run with --threads=30 but each sub process ends up on the same CPU. That defeat parallelism entirely :]

execve would inherit the parent process CPU affinity I guess hhvm / pcntl_fork sets some CPU affinitiy somehow? :-\

\_ /usr/bin/python /usr/bin/scap sync testwiki to php-1.32.0-wmf.20 and rebuild l10n cache - T191066
    \_ /bin/sh -c sudo -u www-data -n -- /usr/local/bin/mwscript rebuildLocalisationCache.php --wiki="testwiki" --outdir="/tmp/scap_l10n_3999488278" --threads=30  --force --quiet
        \_ sudo -u www-data -n -- /usr/local/bin/mwscript rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
            \_ /bin/bash /usr/local/bin/mwscript rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
                    \_ php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force --quiet
deploy1001:~$ php --version
HipHop VM 3.18.6-dev (rel)
Compiler: 3.18.5+dfsg-1+wmf8+deb9u1
Repo schema: 7be0062745976798500274e76b3907ae9448a681

on deployment-deploy01:

mwscript rebuildLocalisationCache.php --wiki="testwiki" --outdir="/tmp/scap_l10n_3999488278" --threads=30 --force

Then in another term:

while true; do echo "_____"; ps -A -o pid,cpuid,cmd|grep -i rebuild; sleep 1; done;

And eventually they are all on the same CPU.

hashar added a comment.EditedSep 4 2018, 5:12 PM

Then I am using taskset to find the CPU affinity mask.

The maintenance script is tied to CPU 1:

16735 php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force
$ taskset -p 16735
pid 16735's current affinity mask: 1

The parent process is not:

16730 sudo -u www-data php /srv/mediawiki-staging/multiversion/MWScript.php rebuildLocalisationCache.php --wiki=testwiki --outdir=/tmp/scap_l10n_3999488278 --threads=30 --force
$ taskset -p 16730
pid 16730's current affinity mask: ff

And from strace of the php process:

getpid()                                = 17963
sched_getaffinity(0, 128, [0, 1, 2, 3, 4, 5, 6, 7]) = 64
sched_setaffinity(0, 128, [6])          = 0

It is magically set to CPU 6 :]

/proc/self/status has informations about the process notably:

  • Cpus_allowed: Mask of CPUs on which this process may run (since Linux 2.6.24, see cpuset(7)).
  • Cpus_allowed_list: Same as previous, but in "list format" (since Linux 2.6.26, see cpuset(7)).

So here I go locally on Debian Stretch with HHVM from Wikimedia

$ php maintenance/shell.php
>>> preg_grep( "/Cpus_allowed/", split( '\n', file_get_contents('/proc/self/status') ) );

=> [
     47 => "Cpus_allowed:\tf",
     48 => "Cpus_allowed_list:\t0-3",
   ]
>>> 

And on deployment-deploy01:

$ mwscript shell.php --wiki=testwiki
>>> preg_grep( "/Cpus_allowed/", split( '\n', file_get_contents('/proc/self/status') ) );
=> [
     46 => "Cpus_allowed:\t08",
     47 => "Cpus_allowed_list:\t3",
   ]

So something on Wikimedia hosts ends up limiting the number of CPUs allowed. That might be related to includes/shell/limit.sh / the use of cgroups?

hashar added a comment.EditedSep 4 2018, 8:56 PM

Using PHP=php7.0 mwscript it is not affected. So I guess HHVM ends up invoking sched_setaffinity whenever it runs under a Linux CGroup.

Looking at the Debian package sources, there is only a few places having that system call:

hphp/util/alloc.cpp:  numa_sched_setaffinity(0, (*node_to_cpu_mask)[node]);
hphp/runtime/ext/hotprofiler/ext_hotprofiler.h:#define SET_AFFINITY(pid, size, mask) sched_setaffinity(0, size, mask)
...

The hot profiler can be disabled via hhvm.stats.enable_hot_profiler = 0. I did so by manually editing /etc/hhvm/php.ini and magic there is no more cpu limitation.

repro

Broken:

deployment-deploy01:~$ echo "preg_grep( '/Cpus_allowed/', split( '\n', file_get_contents('/proc/self/status') ) );"|mwscript shell.php --wiki=testwiki
=> [
     46 => "Cpus_allowed:\t20",
     47 => "Cpus_allowed_list:\t5",
   ]

Disabling hotprofiler fix the cpu limitation:

deployment-deploy01:~$ echo "preg_grep( '/Cpus_allowed/', split( '\n', file_get_contents('/proc/self/status') ) );"|PHP='hhvm -d hhvm.stats.enable_hot_profiler=0' mwscript shell.php --wiki=testwiki
=> [
     46 => "Cpus_allowed:\tff",
     47 => "Cpus_allowed_list:\t0-7",
   ]

@hashar Nice research!

For web servers, HHVM has 1 worker process per CPU (this happens before affinity is modified). And each worker process has numerous threads, one thread for one web request handling. Those worker process should ideally not affect each other or steal/saturate other worker process' CPUs. As such, it makes sense to limit the affinity. It makes even more sense for Xenon ("ext.hotprofiler") to limit the affinity because Xenon code within each worker process needs to interrupt all threads from the same worker in a cheap way. I am not sure, but I suspect that it makes Xenon easy/efficient to limit the affinity there, to prevent the threads from being "randomly" assigned to a different CPU.

In terms of efficiency/performance, I suspect that this does not cause any problem. In theory, it could mean that if a worker has all its request threads stalled, it means that its CPU time is not re-usable by another worker. On the other hand, if it would allow another worker to take over, it would lose that slot and experience stagnation once its own thread wants to resume.

If I understand this correctly (and I'm not sure that I do), this means HHVM optimises for predictable performance, good resource utilisation, and optimises for lower latency per-request. This means, it does not want to optimise for completing all tasks together with perfect resource utilisation, which incompatible with the other two goals.

This makes it great for web servers, but not great for offline processing and command-line usage. This reason, and other reasons, is why the jobrunner servers were changed from a maintenance script to a VirtualHost that accepts POST requests.

About rebuildLocalisationCache.php, note that --threads is not actually an option for threads (surprise!). It is actually an option to control the number of child processes. And yeah.. with how HHVM works there are two problems:

  • Trying to auto-detect the number of cores will yield 1 instead of N.
  • If you spawn more sub processes anyway, they get tied to the same CPU because of the affinity of the parent process.

Perhaps there is a way to override that, but probably not. Workarounds:

  • Add an option for rebuildLocalisationCache.php to tell it what portion to process, e.g. --threads-total=10 thread-self=1, --self=2, --self=3, ...). Then you can make the process separately from Scap, and it will not need to create further sub processes.
  • Use PHP 7.
  • Disable hotprofiler (we don't collect Xenon from CLI anyway).

Also remember that enabling JIT will speed things up as previously discovered. I believe this was not yet applied, is that right?

[...]
Also remember that enabling JIT will speed things up as previously discovered. I believe this was not yet applied, is that right?

That is correct, there's nothing in scap for this. I was hoping this task would be resolved when the maintenance scripts moved to using php7 so I moved scap-specific fixes down my priority list.

I'll start working on a way to pass flags when scap is using hhvm.

Change 459828 had a related patch set uploaded (by Thcipriani; owner: Thcipriani):
[operations/puppet@production] Scap: Update config to use PHP=hhvm -vEval.Jit=1

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

Seems scap learned to set the PHP environment variable for mwscript. I guess we can now try hhvm -d hhvm.stats.enable_hot_profiler=0 (per comment above T191921#4557854 ).

If I am not mistaken, Eval.Jit would not grant improvement since the HHVM bytecode cache is already filled with compiled code.

It's unclear to me why we're continuing to invest so much time in getting HHVM to work when we're going to switch to PHP 7 anyways. Is there a specific reason for that? Like I said in May, we should switch *this script* over to PHP 7 and re-evaluate its performance.

legoktm@deploy1001:~$ time PHP=php7.0 mwscript rebuildLocalisationCache.php --wiki=enwiki --outdir=/tmp/l10nstuff4
...
414 languages rebuilt out of 414

real	4m28.432s
user	3m31.656s
sys	0m56.376s

Does this need a patch like https://gerrit.wikimedia.org/r/459828 but pointing it at php7.0?

@Legoktm: There was some concern about incompatibilities between the mbstring in php7 vs hhvm and an assertion that php7 would not build the localization cache correctly. I was never convinced that is actually the case. Unfortunately I can't seem to find where that discussion is logged, most of it was in IRC as far as I remember.

Krinkle added a comment.EditedSep 12 2018, 2:41 AM

I share the same concern as what @mmodell remembers. Having said that, I believe at this point in time that we've dealt with any/all issues of the type that would cause cascading failure or hard-to-reverse corruption. That was mostly in the area of the php-memcached driver and those type of issues have been fixed.

The XML-generation infrastructure ("dump") has been running on PHP 7 for a while now from the command-line, doing "read" -type queries. And while many parts of MediaWiki do "writes" on "read" queries (mostly relating to caching), as mentioned, any bugs relating to cache corruption have been found and fixed, and I suspect that if there were more, we would have discovered them by now through the XML-generation scripts.

I think we should continue to refrain use of PHP 7 for HTTP requests, jobs and most cron jobs, but we can start considering individual maintenance scripts. rebuildLocalisationCache.php seems like a good one to try next.

As long as we switch it in a way that we can quickly reverse if/when we find issues, you have my support to switch it whenever you feel like.

I ran a script to diff the CDBs I just generated with PHP 7.0, and there's no functional diff (just some sorting issues).

legoktm@deploy1001:~$ php dump-cdb.php /tmp/l10nstuff4/l10n_cache-en.cdb > php7-en.json && php dump-cdb.php /srv/mediawiki/php-1.32.0-wmf.20/cache/l10n/l10n_cache-en.cdb > hhvm-en.json && diff php7-en.json hhvm-en.json

Looking at other languages there's a small diff, it looks like my build of l10n cache didn't pick up LU changes.

Change 460021 had a related patch set uploaded (by Thcipriani; owner: Thcipriani):
[operations/puppet@production] Scap: Update config to use PHP=php7.0

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

Change 460021 merged by Alexandros Kosiaris:
[operations/puppet@production] Scap: Update config to use PHP=php7.0

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

thcipriani closed this task as Resolved.Sep 20 2018, 5:45 PM
thcipriani claimed this task.

I ran a no-op scap sync using the patch above to use php7.0

17:32:12 Started l10n-update
17:32:12 Updating ExtensionMessages-1.32.0-wmf.22.php                                                                                                  
17:32:12 Updating LocalisationCache for 1.32.0-wmf.22 using 30 thread(s)                                                                               
17:33:17 Generating JSON versions and md5 files                                                                                                        
17:33:18 Finished l10n-update (duration: 01m 05s)

The whole sync (granted it wasn't syncing anything new) was 3m 7s: https://tools.wmflabs.org/sal/log/AWX4DK82oDEJc1hA8X9O

I backed up the old l10n cache for comparison, diffs show basically nothing:

[thcipriani@deploy1001 ~]$ diff /srv/mediawiki-staging/php-1.32.0-wmf.22/cache/l10n/upstream/l10n_cache-en.cdb.json ~/php-1.32.0-wmf.22-cache-l10n/upstream/l10n_cache-en.cdb.json                                                                                                                           
[thcipriani@deploy1001 ~]$ diff /srv/mediawiki-staging/php-1.32.0-wmf.22/cache/l10n/upstream/l10n_cache-he.cdb.json ~/php-1.32.0-wmf.22-cache-l10n/upstream/l10n_cache-he.cdb.json

Calling this resolved.

greg awarded a token.Sep 20 2018, 8:15 PM