[16:31:15] _joe_: thanks for poking at the php7.2 stuff on the labweb hosts :) [16:31:33] <_joe_> bd808: that's a thorny thing to do [16:31:54] <_joe_> I did some choices (that packages need downgrading) so that we won't mess up accidentally other installations [16:32:35] I'll be glad when we can move wikitech into the main mediawiki cluster and stop having those snowflake servers [16:32:55] we've got a few more things to replace there to make that viable [17:11:05] _joe_: one of the things we store in apcu is localisation cache - big amount data fore each combination of lang code and wiki-id. It's among the things relatively expensive to compute, but cheap to store, might be something where we lose some long tail perf on php 72 if we can't store all combos in cache at once. Nothing concrete right now, just something I'm thinking about. [17:11:50] We might want to do more multi-tiering with that kind of data in both memc and apcu, although we previously didn't have to. [17:11:54] <_joe_> Krinkle: I have some new data from mw1348, where we're serving all requests with php7 currently (API) [17:12:08] <_joe_> and I think we're going to allot 4G [17:12:12] <_joe_> maybe in 2 segments [17:12:33] <_joe_> the cache hit ratio doesn't improve much, but we spend way less time in LRU [17:12:36] ok, that sounds high and close enough to HHVM that I won't bother looking at it for a while. [17:13:01] _joe_: what changed your mind? also, where can I read more about its LRU logic? [17:14:03] <_joe_> https://grafana.wikimedia.org/d/GuHySj3mz/php7-transition?refresh=30s&orgId=1&panelId=18&fullscreen&var-datasource=eqiad%20prometheus%2Fops&var-cluster=api_appserver [17:14:09] <_joe_> select mw1348 [17:14:17] <_joe_> it's doing LRU every 20 minutes or so [17:14:26] <_joe_> I checked the cache hit ratio, it's very good [17:14:33] <_joe_> but still, that seems way too frequent [17:14:46] <_joe_> OTOH, opcache memory protection is completely unviable [17:15:10] <_joe_> rendering times increase by 300% even at low concurrencies [17:16:02] Aye, yeah. that's no good [17:16:35] _joe_: so mw1348 shows a shorter fill-clear cycle, am I reading that right? And the others have 500 M alotted, and 1348 4G ? [17:16:51] <_joe_> no, still 512M [17:16:58] <_joe_> I want to move it to 4G [17:17:03] right [17:17:24] <_joe_> this is where I loathe we don't have a per-server latency measurement [17:17:30] I read on older posts that apcu is known for not doing LRU It just resets completely whenever limit is reached and sstarts fresh. [17:17:39] I guess php 7-7.2 improved that? [17:18:00] <_joe_> that's what I remembered, but maybe I'm wrong? [17:18:25] _joe_: https://grafana.wikimedia.org/d/000000580/apache-backend-timing?orgId=1 might be able to help, would need some wiggling but in theory the data is there between backend-timing from varnish-be + 'server' header. [17:18:42] _joe_: the sharp drops between 0 and 500 M for the others suggests it's not doing LRU. [17:18:50] given nothing remains? [17:19:05] but I'm not sure. the "available" metric is confusing to me, I'd like to see what's used, not what's available. [17:19:47] anyway, no problem - I'm not the one monitoring and tuning it, so np if this makes more sense, I'll get used to it [17:20:32] <_joe_> it makes sense for now, because I want to see how much space we have available to tune it max [17:20:42] <_joe_> but I am open to changing it :) [17:21:25] another thing we lean heavily on apc for is etcdconfig which we put into the critical path in wmf-config [17:21:49] on the idea that it would never just fall out, e.g. no fallback other than to refetch from the network, with desire to serve stale meanwhile if needed. [17:21:55] <_joe_> Krinkle: "If APCu is working, the Cache full count number (on the left) will display the number of times the cache has reached maximum capacity and has had to forcefully clean any entries that haven't been accessed in the last apc.ttl seconds" [17:22:00] we may want to monitor that as well, I don't knwo if we have metrics on that. [17:22:11] <_joe_> so it does a very crude form of LRU [17:22:34] <_joe_> so I thought about it and [17:22:38] <_joe_> given the above [17:22:46] <_joe_> config values get accessed by every request [17:23:23] <_joe_> but ofc I did miss one thing. [17:24:00] <_joe_> I should set apc.ttl to like 10 minutes [17:24:09] ah, right. I remember from running MW on a shared host some years ago. when APC filled up there, it would stay full with whatever it had, and reject new values (unless key ttl expired them). [17:24:23] <_joe_> that's what HHVM does [17:24:25] That's how it used to be by default. [17:24:32] <_joe_> well no [17:24:38] <_joe_> hhvm would go OOM [17:24:42] I guess the "clear everything" feature upon reaching capacity is new-ish [17:24:50] yeah, hhvm just stores everything until the server dies. [17:24:56] and never forgets except by ttl. [17:25:00] <_joe_> yes [17:25:07] <_joe_> which in a way is a good thing [17:25:09] <_joe_> but [17:25:26] <_joe_> on mw1348 we didn't see more requests to memcached once we swtiched to ph7 [17:25:29] <_joe_> *php7 [17:25:40] <_joe_> so I guess overall the cache hit ratio is very good [17:25:54] <_joe_> interestingly we discovered an HHVM bug :D [17:26:11] well, there's close to nothing both in apc and memc to my knowledge. [17:26:17] <_joe_> oh [17:26:20] we mostly stopped doing that [17:26:25] <_joe_> so it would be where? [17:26:37] <_joe_> what I would notice on that server? more db queries? [17:26:41] <_joe_> more cpu use? [17:26:42] database, disk, and cpu [17:26:53] <_joe_> ok, I can exclude the latter two [17:27:15] minification cache for RL have a very long tail, and is read from disk and stored in apcu only. [17:27:57] and due to the way we use varnish, the important stuff is not "popular" [17:28:07] <_joe_> https://grafana.wikimedia.org/d/000000377/host-overview?refresh=5m&orgId=1&var-server=mw1348&var-datasource=eqiad%20prometheus%2Fops&var-cluster=api_appserver&from=now-6h&to=now [17:28:11] <_joe_> I see [17:28:36] it's a nightmare from your perspective I imagine :/ - very little signal to go on [17:29:09] <_joe_> yeah so, you had some graphs where we saw the effect [17:29:17] <_joe_> on 95th percentile of rendering, but [17:29:21] <_joe_> this is an api server [17:29:31] <_joe_> so I guess not much data about load.php :P [17:30:04] <_joe_> I think I'll migrate one appserver as well to full php7 to tune these parameters [17:30:27] <_joe_> Krinkle: also, I have looked a bit at the opcache problem and I hope we can mitigate it even more [17:30:45] _joe_: maybe try api.log on mwlog1001 and correlate times with server and see if it's better/worse? [17:30:49] <_joe_> but I still have to find a way to detect it that doesn't involve probes [17:30:52] it records latency [17:31:26] <_joe_> we have it in apache too, so yeah I'm going to need to do some log-munging [17:31:53] so yeah, we have api times in mwlog/api.log (per server) [17:31:54] load.php times for module build times and minification hit ratio in Graphite/Grafana (not per server) [17:32:17] we have page view response time in Graphite (viewResponseTime), not per-server. [17:32:38] and overall backend timing from apache is emitted as header and could be aggregated by server from varnish-be logging maybe [17:32:50] not currently recorded in Prometheus with server label, but could be done manually [17:33:16] also flame graphs will become more useful as we increase sampling [17:34:23] Looking at https://performance.wikimedia.org/arclamp/svgs/daily/2019-05-29.api.svgz and https://performance.wikimedia.org/arclamp/svgs/daily/2019-05-29.excimer.api.svgz for example. [17:35:20] * Krinkle removes {GET}/{POST} fragmentation from hhvm metrics so that we can better compare the two [17:40:03] _joe_: from an infra perspective, the reversed flame graphs can be a useful way to see where time is spent overall in DB, disk, memc etc. Because it groups together the leaf nodes. [17:40:07] e.g. https://performance.wikimedia.org/arclamp/svgs/daily/2019-05-29.excimer.api.reversed.svgz and https://performance.wikimedia.org/arclamp/svgs/daily/2019-05-29.api.reversed.svgz [17:43:50] <_joe_> uhm yeah it can help indeed [17:43:55] <_joe_> thanks [17:45:01] <_joe_> so I see an interesting thing here, apcu takes more time than in hhvm indeed [17:46:11] _joe_: yeah, Apc_get doesn't show up at all in hhvm data. in PHP 7 it shows up a lot. [17:46:14] But, I don't see apc_set anywhere [17:46:34] <_joe_> it's a bit strange it doesn't appear at all in hhvm data though [17:46:36] The APC_get time in PHP 7 is almost exclusively from extension registration initialisation [17:46:48] which is likely due to do not having the built-in filestat? [17:47:13] fs cache thingy [17:47:18] <_joe_> stat cache [17:47:29] <_joe_> yeah but I thought stat cache only applied to code [17:47:45] <_joe_> so opcache is where bytecode is saved [17:48:13] <_joe_> anyways, php has some form of stat cache IIRC [17:48:57] <_joe_> https://www.php.net/manual/en/function.clearstatcache.php yep [17:51:33] interesting, that's not new either. but there was definitely something special about hhvm's filestat cache. I don't recall what, though. [17:52:24] So looking at it normally (not reversed). api.php on hhvm for that day has 23K samples from WebStart.php setup, of which 2K samples are in ExtensionRegistry::loadFromQueue (which does the apc lookups). [17:52:56] api.php on php7 for that day has 6.5K samples from WebStart.php setup, and 2.3K samples within that spent in ExtensionRegistry::loadFromQueue and APC get [17:53:20] I don't know how the scaling behaviour is for this, but as-is, it's 10% time spent in apc vs only 30% time spent in apc. [17:53:42] Doesn't tell us anything about whether that's file stat cache, apc latency overall, or whether it;s cache computations itself cache/hit etc. [17:54:03] <_joe_> ok tomorrow I'll will bump the apcu cache size and we'll see if that value changes [17:54:21] <_joe_> this is very useful data, thanks [17:54:38] <_joe_> I'm now off for dinner, see you tomorrow! [17:55:22] o/ [19:56:52] Resolved 'RELEASE-NOTES-1.31' using previous resolution. [19:57:00] <3 git rerere