See T333445#12095903
TLDR: Thumbor provides ways to do offload expensive work into sub-processes and handle the new request while the current one is being transformed. We are not taking advantage of that. We should.
Description
Description
Details
Details
Related Changes in Gerrit:
Customize query in gerrit
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Open | JTweed-WMF | T431141 FY26-27 PP3.6: Image thumbnailing | |||
| Open | Cparle | T431718 PP3.6.1: Thumbor performance | |||
| Open | Ladsgroup | T431767 Migrate I/O bound parts of thumbor to asyncio |
Event Timeline
Comment Actions
I'm 50-70% sure the whole asyncio setup is broken. The change we made didn't make any difference which is fishy. Like if it worked a bit, I could understand it but not at all probably means the event loop is not set up (task manager, etc.) correctly or something is making everything go synchronous.
Comment Actions
Random guess. Could it be that haproxy is not forwarding more requests until the current one is responded? That would make sense back then but not since thumbor 7.0 onwards (2022). I'll investigate 🕵
Comment Actions
Change #1309832 had a related patch set uploaded (by Ladsgroup; author: Ladsgroup):
[operations/deployment-charts@master] thumbor: Allow 2 connection per worker
Comment Actions
Change #1309832 merged by jenkins-bot:
[operations/deployment-charts@master] thumbor: Allow 2 connection per worker
Comment Actions
The haproxy in front of thumbor emits a treasure trove of metrics.
Right after deploy, average total time requests are spending (in the queue, being processed, etc.) has gone slightly down. The data is quite stable in short time so I think it reduced ~5% of the total response time. It's small since we haven't moved the actual heavy lifting to asyncio yet.
Average of max queue time (per container) has gone down a bit: https://grafana-rw.wikimedia.org/goto/bfs0zvanrwsn4a?orgId=default
Average response time (time spent in thumbor) hasn't changed much or it has gotten a bit higher but the rate of requests to thumbor has gone up (scraping, etc.)
https://grafana-rw.wikimedia.org/goto/bfs0zzqahb6rke?orgId=default
(This the rate of increase of requests to thumbor as a point of comparison):
Comment Actions
Change #1310618 had a related patch set uploaded (by Ladsgroup; author: Ladsgroup):
[operations/software/thumbor-plugins@master] swift: Migrate storage of results to asyncio
Comment Actions
Change #1310623 had a related patch set uploaded (by Ladsgroup; author: Ladsgroup):
[operations/software/thumbor-plugins@master] images: Move loading of memcached key to asyncio
Comment Actions
Change #1310618 merged by jenkins-bot:
[operations/software/thumbor-plugins@master] swift: Migrate storage of results to asyncio
Comment Actions
Change #1310623 merged by jenkins-bot:
[operations/software/thumbor-plugins@master] images: Move loading of memcached key to asyncio
Comment Actions
Change #1318677 had a related patch set uploaded (by Ladsgroup; author: Ladsgroup):
[operations/deployment-charts@master] thumbor: Move more operations to asyncio
Comment Actions
Change #1318677 merged by jenkins-bot:
[operations/deployment-charts@master] thumbor: Move more operations to asyncio
Comment Actions
It was a bit hard to find but I think delegating shell part of thumbnailing to asyncio happens by upstream thumbor already. It's a bit convoluted but here is the call stack:
https://github.com/thumbor/thumbor/blob/05449d0d7be4f9add1749ca69d1afc63396f10a5/thumbor/handlers/__init__.py#L633
-> BaseHandler::finish_request()
-> self._load_results()
-> context.request.engine.read()
-> wikimedia_thumbor.engines.proxy.Engine::read()
-> wikimedia_thumbor.engines.imagemagik.Engine::read()
-> self.run_operators()
-> ShellRunner.command()