willtrking/thumbor_aws — pull request #14 by pda (2014-11-18 02:07:46+00:00)
Title: async S3 HTTP with botornado

Summary: [thumbor] runs on [tornado] which is async, but [thumbor_aws] uses [boto] for HTTP to S3 which is blocking, causing awful performance. This patch uses [botornado], a tornado async partial port of boto, to make S3 requests non-blocking.

Test material at https://gist.github.com/pda/5dcf54410b696072fcbd

[thumbor]: https://github.com/thumbor/thumbor
[thumbor_aws]: https://github.com/willtrking/thumbor_aws
[tornado]: http://www.tornadoweb.org/en/stable/
[boto]: https://github.com/boto/boto
[botornado]: https://github.com/yyuu/botornado

---

In production we have an ELB load balancer in front of two EC2 instances each running thumbor + thumbor_aws inside a docker container. We had reports of blank images, and then hints that they were HTTP 503 errors, but it wasn't reproducible. Our logs shows that the load balancer frequently marking either of the instances as unhealthy, meaning it's failed to respond to a health check. The thumbor processes had been up and running for many days, and had no suspicious log entries.

I suspected that something was blocking inside the thumbor event loop, and narrowed it down to boto in thumbor_aws.

Using a controllably slow backend behind thumbor_aws, I was able to demonstrate the single-concurrency of boto by showing slow requests blocking fast requests:

```
$ ./race.rb http://localhost:8888/unsafe/sleep/{10,1000,100,10000,500}

dispatching http://localhost:8888/unsafe/sleep/10
dispatching http://localhost:8888/unsafe/sleep/1000
dispatching http://localhost:8888/unsafe/sleep/100
dispatching http://localhost:8888/unsafe/sleep/10000
dispatching http://localhost:8888/unsafe/sleep/500
78 ms for http://localhost:8888/unsafe/sleep/10
2030 ms for http://localhost:8888/unsafe/sleep/1000
2168 ms for http://localhost:8888/unsafe/sleep/100
22108 ms for http://localhost:8888/unsafe/sleep/10000
23051 ms for http://localhost:8888/unsafe/sleep/500
```

Switching `s3_loader.py` from `boto` to `botornado` fixes that:

```
$ ./race.rb http://localhost:8888/unsafe/sleep/{10,1000,100,10000,500}

dispatching http://localhost:8888/unsafe/sleep/10
dispatching http://localhost:8888/unsafe/sleep/1000
dispatching http://localhost:8888/unsafe/sleep/100
dispatching http://localhost:8888/unsafe/sleep/10000
dispatching http://localhost:8888/unsafe/sleep/500
89 ms for http://localhost:8888/unsafe/sleep/10
228 ms for http://localhost:8888/unsafe/sleep/100
1024 ms for http://localhost:8888/unsafe/sleep/500
2028 ms for http://localhost:8888/unsafe/sleep/1000
20024 ms for http://localhost:8888/unsafe/sleep/10000
```

(The double times in the benchmarks are due to the test server sleeping `n milliseconds` for both the HEAD and GET requests. Perhaps that HEAD request should be eliminated from thumbor_aws, but that's a separate issue).

---

This fix uses botornado to do async HTTP requests to S3 in a way that fits the tornado event loop model, without blocking other requests.

I've only applied it to the `loaders` module, as that's the only component that we're using. It should probably also be applied to the `storages` and `result_storages` modules. Perhaps we can ship this fix first, though?