[00:54:51] YuviPanda, good news! [00:55:08] So, the staging server can barely keep up with precached since we added wikidate [00:55:28] BUT because of the queue limit, it was able to go over capacity for a period of a couple of hours and then come back. [00:55:32] Never missed a beat. [00:55:40] somehow my mind autocompleted 'good news!' followed by a pause to 'you are pregnant!' [00:55:40] Just missed pre-caching a few revisions. [00:55:47] probably too many movies [00:55:50] It's a boy! [00:55:50] halfak: yay! [00:56:03] halfak: and we got graphite metrics of the missed ones? [00:56:29] Yeah. Just realized to check on those a moment ago. [00:56:52] Hmmmm..... [00:56:57] Not seeing 'em [00:56:59] how many did we miss? [00:57:01] oh? [00:57:09] * halfak hmmms harder [00:59:38] Yeah... this doesn't make any sense. Could we have not actually over-loaded. [00:59:45] We do have another type of backpressure [01:00:00] We only let a job sit in the queue for a max of 15 seconds. [01:00:51] I'm going to try to force it to fill up the queue [01:01:59] WTF. [01:02:02] I can't :) [01:02:13] I need to somehow send more requests at this thing. [01:02:51] YuviPanda, got any good tricks for using up all the CPU on a machine? [01:02:59] halfak: 'apt-get install stress' [01:03:04] stress -c this is weird. [01:08:59] I'm stressing all 4 CPUs. [01:09:07] And I still can't get the queue to fill up. [01:09:59] halfak: stress -c 8! [01:10:05] Yeah I guess. [01:10:08] * halfak tries that [01:11:00] and -c 16 etc [01:12:49] Yeah. I don't think we're running the new code somehow. [01:12:57] We had problems with the server not restarting before. [01:12:58] ah [01:13:01] possibly [01:13:04] yes I remember this happening [01:13:15] I should still see items in the queue. [01:13:25] ores-staging-01 has redis on localhost, right? [01:13:34] It seems like that's where ores-redis is redirecting to [01:15:57] uWSGI listen queue of socket "0.0.0.0:8080" (fd: 3) full !!! [01:16:07] Looks like we might have a uwsgi queue that is getting full first. [01:16:25] Yup. [01:16:29] They have a limit of 100 [01:16:36] Still that should be plenty. [01:16:43] We have one worker with 16 processes [01:17:30] halfak: yeah should. [01:17:40] halfak: did you restart uwsgi? [01:17:55] I ran "fab stage" hours ago and let it finish [01:18:15] No new dependencies so I didn't screw around with updating requirements.txt [01:18:27] * halfak waits for uwsgi-ores-web to restart [01:25:24] Yeah. So I think the problem is that I can't find the queue -- not that it isn't filling up. [01:25:40] Gonna do dinner and come back to have a look later. [01:25:41] o/ [01:34:14] halfak: \o/ ok [01:37:48] Yeah... something is very weird. [01:37:57] Even flower agrees that there are no queued tasks [01:38:16] * halfak is ignoring dinner for a good mystery [01:39:48] I think it might be because we are specifying the name of the queue. [01:47:03] Yeah. I give up. [01:47:13] Maybe I'll be smarter in the AM. [14:19:52] OK. Now that it is AM, I think this is uwsgi being a limiting factor some way on the server that it is not on my laptop [14:51:06] YuviPanda, when you get in, we should talk about pushing the number of "processes" for uwsgi [14:52:01] If the # of processes is also the # of potential parallel requests, then I think we're limiting the number of requests to the number of potential workers (16) and therefore preventing any queuing. [15:15:49] Aha! I can replicate the weird behavior by running my dev server with 16 processes. HAHAHAHA [15:15:55] I think this is it! [15:16:04] We already have backpressure on the uwsgi servers! [15:16:16] It's just crappy backpressure that prevents a task from starting for a long time. [15:16:26] And doesn't 503 or some other useful error. [15:16:33] * halfak dances [16:10:25] YuviPanda, any chance you're alive and kicking? [16:10:43] I'm going to give a presentation on revscoring in 20 minutes. I figured you might like to join us for the call. [16:11:10] This won't be that different from the presentation I gave at the showcase though. [16:11:18] Some new arguments will be made. [16:11:25] Anyone else is welcome too ^ [16:11:35] Just let me know. [16:13:26] brb restarting [16:17:23] lol "google calendar is currently unavilable. [16:17:32] Might not be able to join the call! [18:53:39] halfak: apparently my body won't let me wake up before 10:30 no matter when I went to sleep [18:53:49] which meant I got 12h of sleep today and still feel like crap [18:53:51] * YuviPanda glares at body [18:55:35] * halfak glares at YuviPanda's body too [18:55:37] :D [19:23:25] YuviPanda, got time to chat about the queue stuff. [19:23:34] I have updates that go way back in the scroll. [19:23:41] I'm happy to re-hash them more simply [19:23:47] halfak: ah sure. if you give me about 2mins to get some tea going [19:24:18] Sure. I'll do the same [19:24:24] Oh wait. [19:24:26] Lunch [19:24:28] I need lunch [19:24:30] I'll do that [19:24:34] ~15mins [19:48:03] OK [19:48:07] YuviPanda, [19:48:31] I think our bottleneck is the number of processes assigned to each uwsgi server [19:49:01] yeah that'd be a hard limit on number of 'waiting' requests [19:49:03] do those not time out? [19:49:07] Right now, we have 16*4=64 worker threads. [19:49:17] But we only have 2*16=32 uwsgi processes [19:49:25] So uwsgi queues up requests until a process is ready [19:51:50] So, when make the workers slow (stress), then we just get a really big queue on the uwsgi servers. [19:52:01] The first thing to give is the 20 second timeout on uwsgi [19:52:18] ah [19:52:20] ok [19:52:24] we can configure that on the uwsgi level [19:52:31] So, I think we need to substantially boost the # of process or otherwise allow the processes to use multiple threads. [19:52:32] there's a param [19:52:35] called harakiri timeout [19:52:49] I think the timeout is just fine where it is. [19:53:13] I want our celery queue to fill up before the uwsgi has a chance. [19:53:29] ah I see. so you want this to just test? [19:53:46] Well, I' [19:53:56] think that we want that in prod [19:54:04] I'm not positive, so yes to testing [19:54:04] hmmm [19:54:14] But not just for the testing env if I'm right. [19:54:28] I'm trying to wrap my head around the bottlenecks now [19:54:52] --->[nginx]-->[32*uwsgi]-->[64*celery] [19:55:07] So, uwsgi is the bottleneck [19:55:25] I can replicate this with local uwsgi and playing around with the # of precesses. [19:55:27] nginx also probably has a 'max connections' param somewhere [19:55:52] Yeah... not using nginx locally, but you could definitely be right. [19:55:54] ok, so let's say we increase uwsgi to match number of celery workers [19:55:59] Na. [19:56:02] Need more [19:56:09] Otherwise, why do we have a queue in celery? [19:56:43] hmmm true! [19:56:52] so let's say we 2x uwsgi in celery [19:56:54] err [19:56:56] gah [19:57:02] err [19:57:05] ok, math [19:57:05] We should have at least 100 potential uwsgi threads beyond our number of workers [19:57:16] hmm so then we can have a hunderd uwsgi threads [19:57:22] that can potentially put things into the queue [19:57:26] Yeah [19:57:45] but our celery numbers should be based off CPUs [19:58:04] since otherwise context switching will kill everything and also if we hit swap (due to having too many processes) we are dead [19:58:22] so we figure out number of celery workers and then make the uwsgi worker count be derived from that [19:58:25] +1 YuviPanda [19:58:37] Right now, we assume that each worker gets access to 4 CPUs [19:58:53] And we want 4 worker processes per CPU [19:59:03] So we have 16 worker processes per worker [19:59:19] It seems this does good for our utilization. [19:59:24] right [19:59:31] Right now, we can't take advantage of it though [19:59:35] :/ [19:59:47] because of lower uwsgi numbers? [19:59:49] We're only using 32 of our 64 worker-processes at a time! [19:59:51] Yeah [20:00:00] we an bump it up and see what happens [20:00:05] This is also probably why I don't see celery's queue ever fill up. [20:00:37] halfak: ok so currently it is set to [20:00:42] processorcount * 4 [20:00:49] +1 [20:00:51] which is the same as celery [20:00:53] except [20:00:56] we have more celery machines [20:00:56] Oh in uwsgi [20:00:58] yeah [20:01:01] Yeah [20:01:38] halfak: ok how about I make both those multipliers tuneable [20:01:42] and then we can play around with it [20:01:53] Sounds good. [20:02:00] let me do so [20:04:28] halfak: hmm, celery process multiplier isn't controlled in puppet [20:04:33] is in ores-wikimedia-config maybe? [20:04:37] Yes [20:04:42] kk [20:05:03] ok I've a patch up [20:06:03] halfak: ok, so you can tune it by doing [20:06:29] 'ores::web::workers_per_core: 8' [20:06:31] or whatever number [20:06:35] in Hiera:ores [20:06:37] on wikitech [20:06:43] if you just want to tune it for a particular host [20:06:46] then it's page [20:06:50] Hiera:Ores/host/ [20:07:02] and then you have to run puppet (sudo puppet agent -tv) or wait 20min [20:08:29] YuviPanda, it looks like "threads" and "workers" are independent settings. [20:08:47] I don't know if we need more workers -- just more threads to block on IO with celery. [20:08:50] yeah but we don't have threads enabled [20:08:57] We don't need to [20:09:03] and we're using it in workers mode, no? and not threading mode [20:09:07] It looks like 'enable-threads' and 'threads' don't talk [20:09:31] http://uwsgi-docs.readthedocs.org/en/latest/WSGIquickstart.html#adding-concurrency-and-monitoring [20:10:19] interesting [20:10:23] right now we're using only processes [20:10:25] afaict [20:10:27] and not threads [20:10:37] It seems like threads should be cheaper [20:10:45] hmm [20:10:50] processes are just vastly simpler to reason about [20:11:06] and I'd say we shouldn't enable threads unless we're going to solve a specific problem with them [20:11:16] No. Don't "enable-threads" [20:11:23] That's a problem, i agree. [20:11:24] no I know. I'm talking about --threads too [20:11:28] Let uwsgi have threads itself. [20:11:32] since that is still threads, just not python threads [20:11:37] Yeah [20:11:47] Threads have way less overhead than processes [20:11:53] yes, it's not just python threads that are a problem :D they make things like stracing difficult [20:12:00] sure, but we aren't maxing out on anything yet [20:12:09] so I'd say we should tune processes first [20:12:14] and see if we can do what we want with them [20:12:18] and if not then use threads [20:12:25] We're going to have a lot of idle processes :P [20:12:28] that's ok [20:12:38] If you're prefer, I'm OK with it. [20:12:43] +1 [20:13:27] ok so I'm going to go get ready and bike to the office (yay!) [20:13:31] anything you want me to do before that? [20:13:48] Na. Seems like I can do the heira stuff. [20:13:54] Will this just affect staging? [20:14:01] you can make it just affect staging [20:14:07] by changing that variable only for the staging host [20:14:14] Hiera:Ores/host/ores-staging-01 [20:14:33] but if you put it in Hiera:Ores [20:14:36] it'll affect everything [20:14:47] Just copy-paste Heira:Ores into a new page at that location? [20:14:55] Or maybe just that one line? [20:14:59] just that one line [20:15:01] they're hierarchical [20:15:03] kk will do [20:15:04] and override each other [20:15:07] Thanks! [20:15:09] so the host specific one [20:15:13] will override the general one [20:15:30] DO I need to kick the server to get it to read this? [20:16:36] sudo puppet agent -tv [20:16:46] or wait 20min (upto - it runs in a cron every 20min) [20:17:07] ok off now [20:17:18] o/ [20:17:31] halfak: thanks for thinking this through! [20:17:44] * YuviPanda hires halfak for full stack engineer position :P [20:17:51] \o/ [20:17:57] * halfak prepares the cloning device [20:30:51] Hmmm... Not working as expected. [20:31:20] Looks like we do have 32 workers [20:31:38] Maybe I should bump it up to 16 per core. [20:41:23] YuviPanda, when you get back, we should add a "stats socket" for uwsgi [20:47:30] o/ Amir1 [20:54:51] Arg.. Still not seeing anything in the queue. What is going on!? [20:55:08] But wait... flower reports on time in queue as non-zero [20:55:10] WAT [21:00:44] This is really weird. [21:00:53] I don't see the items in the celery queue either. [21:00:54] BAH! [21:01:06] I'm going to lose my full-stack engineer job [21:01:09] * halfak figures harder [21:02:12] All the workers are using CPU [21:22:56] PUT MY TASKS IN THE QUEUE, CELERY [21:23:07] or else I'm getting the hose! [21:24:51] OK. Time to sanity check locally again. [21:36:31] Can get the queue to fill up locally. [21:36:45] But not write wsgi conf in ores-wikimedia-config [21:36:48] Might be on to something [21:39:33] (03PS2) 10Paladox: build: Updating development dependencies [extensions/ORES] - 10https://gerrit.wikimedia.org/r/248535 (owner: 10Legoktm) [21:40:11] (03CR) 10Paladox: [C: 031] build: Updating development dependencies [extensions/ORES] - 10https://gerrit.wikimedia.org/r/248535 (owner: 10Legoktm) [21:41:36] (03PS1) 10Paladox: Update packages [extensions/ORES] - 10https://gerrit.wikimedia.org/r/251131 [22:07:41] When I start the uwsgi server with 10 processes and the celery server with 1 process, the maximum number of items I can get in the queue is 5 [22:07:46] * halfak thinks [22:08:20] There must be something between uwsgi accepting a request and the task appearing in the queue. [22:10:06] It looks like we might have an overhead of 5 processes for uwsgi compared to the celery queue in general [22:10:20] 10 processes can put a max of 5 in the queue [22:10:26] 15 can put 10 in the queue [22:11:11] * halfak starts up uwsgi with 100 processes to see what happens [22:11:21] Ha. We run into the celery queue right away [22:11:27] Also, my machine doesn't seem to care. [22:12:45] So, let's try pushing the processes *way* higher on staging :) [22:14:16] Go, puppet, go! [22:14:20] Do your thing [23:13:22] So.. good news and bad news [23:13:56] The good news is that when we substantially push the number of uwsgi workers, we get better performance all around. [23:14:05] The bad news is that the queue still isn't filling up. [23:15:23] Wait. There it goes! [23:15:30] FLOWER sees it too! [23:15:32] WOOO [23:19:36] Yeah... now we're hitting the cache when the server is overloaded rather than waiting on uwsgi's queue [23:21:25] And when we turn `stress` off the queue goes back down. [23:21:26] Good [23:28:55] * halfak hits the staging server with 4 parallel [23:28:59] precached [23:29:12] * halfak bumps the server up to 256 processes [23:29:17] We'll see how this goes [23:29:26] I think we're going to run out of memory [23:29:28] weee [23:31:09] * halfak tries [23:37:36] Well... we didn't run out of memory. [23:37:48] But I can't seem to get the celery queue to fill up again., [23:38:21] And I seem to have broken flower [23:40:13] (03CR) 10Awight: [C: 032] build: Updating development dependencies [extensions/ORES] - 10https://gerrit.wikimedia.org/r/248535 (owner: 10Legoktm) [23:40:13] maybe redis needs it's max connections boosted [23:40:34] (03CR) 10Awight: [C: 032] Update packages [extensions/ORES] - 10https://gerrit.wikimedia.org/r/251131 (owner: 10Paladox) [23:42:22] Looks like the max redis connections is set to 10k, so that's not it. [23:42:45] Hey! Flower magically came back! [23:43:21] Time for some more stress [23:44:36] Still not filling up celery's queue. [23:44:48] We're having processes that wait 20 seconds and hit uwsgi's limit. [23:44:51] wat [23:45:00] YuviPanda, ^ I'm at a loss [23:45:05] Happy to produce a TL;DR: [23:45:21] hey! [23:45:26] yes TL;DR: plz! [23:45:52] 256 processes for uwsgi, stress is high enough that most of my precaching requests are timing out at the 20s limit [23:46:05] We're barely pushing celery's queue at all. [23:46:09] 10-20 itmes [23:46:22] So, the tasks are sitting somewhere other than celery's queue [23:46:33] interesting [23:46:42] They'd be killed at 15s with a nice error message if they went right to celery's queue [23:46:42] do we have logging turned up? [23:46:54] to see if they get queued? [23:47:12] How would be know that other than looking at the queue? [23:47:25] The task doesn't get executed until it is pulled out of the queue. [23:47:32] So we couldn't execute the logging code. [23:47:41] I suppose we can log when uwsgi starts processing [23:47:48] oh sure, but do we have logs for being put in queue [23:47:50] yeah [23:48:08] also do we not do some special casing for single requests? [23:48:13] where we do the API call in the uwsgi process? [23:48:19] We do. They go straight to celery [23:48:24] No work is done in uwsgi [23:48:36] In the multi-revision case, we do some io blocking [23:48:40] ah I see [23:48:50] (03Merged) 10jenkins-bot: build: Updating development dependencies [extensions/ORES] - 10https://gerrit.wikimedia.org/r/248535 (owner: 10Legoktm) [23:48:50] We're hitting the right task too [23:48:53] (03Merged) 10jenkins-bot: Update packages [extensions/ORES] - 10https://gerrit.wikimedia.org/r/251131 (owner: 10Paladox) [23:48:53] According to flower [23:48:57] so in our case we don't have any special casing that'd increase time in uwsgi [23:49:07] That's right. [23:49:14] Only decreases time in uwsgi [23:49:34] ok so strace!!! [23:49:49] well, look at logs first. do we have a log for uwsgi attempting to put things into celery? [23:50:05] * halfak checks [23:51:10] Yeah... we'll have a log event checking the cache. [23:51:16] So there could be a redis hit that blocks? [23:51:27] We'll need to turn up logging. [23:51:42] Should I do that in the repo and then fab stage -- or just do it on staging? [23:51:42] yeah [23:51:47] there's a way I think [23:51:50] let me check [23:52:14] ah there's one for celery but not for uwsgi [23:52:29] halfak: I think we need to fab stage. you generalized out the logging config at some point, right? [23:52:51] Yup [23:52:55] separate file [23:53:15] https://github.com/wiki-ai/ores-wikimedia-config/blob/master/logging_config.yaml [23:54:26] halfak: kk, you shold do that [23:54:34] I'll work it out quick [23:58:08] Were going to have a cacophony of log messages with our 265 workers [23:58:15] I'm not sure how you plan to track this. [23:58:24] But the log messages will have some ids we can use.