I have an Instagram-like app, where users submit images to a public feed. I was checking server logs and I noticed there were occasionally POST requests with high response times.
Log:
437 <158>1 2016-11-06T15:21:26.974333+00:00 heroku router - - at=info method=PUT path="/api/users/678499625650172?ciOiJIUzI1NiJ9.eyJ1aWQiOiI2Nzg0OTk2MjU2NTAxNzIifQ.SwzWCphNtbW_WciaBgKieXbSLNrznN1EfD7HGZ4j-bw" host=website.com request_id=e77a92b4-bebb-40ad-9476-9d94071b1b9f" dyno=web.1 connect=0ms service=7623ms status=200 bytes=1300
439 <158>1 2016-11-06T15:45:55.783260+00:00 heroku router - - at=info method=PUT path="/api/users/1770954736492550?GciOiJIUzI1NiJ9.eyJ1aWQiOiIxNzcwOTU0NzM2NDkyNTUwIn0.HwT1Di67QLhaZD2jOnV-HMOyqoZUsgOj1PMwkW-JVzA" host=website.com request_id=27b9dfd6-5eea-4e73-a148-bc43149b59ea" dyno=web.1 connect=0ms service=7524ms status=200 bytes=2154
294 <158>1 2016-11-06T15:52:21.479434+00:00 heroku router - - at=info method=POST path="/api/posts" host=website.com request_id=5125b25f-2665-4ce0-9e7c-9410fcfe66b5" dyno=web.1 connect=1ms service=8369ms status=200 bytes=745
294 <158>1 2016-11-06T15:56:47.161275+00:00 heroku router - - at=info method=POST path="/api/posts" host=website.com request_id=59468957-e075-486a-98c4-47f784c3f3b4" dyno=web.1 connect=0ms service=7777ms status=200 bytes=751
294 <158>1 2016-11-06T16:19:47.559217+00:00 heroku router - - at=info method=POST path="/api/posts" host=website.com request_id=b59bee23-1020-4f45-a08f-ba0fd6c6c02c" dyno=web.1 connect=0ms service=6762ms status=200 bytes=936
438 <158>1 2016-11-06T16:24:49.776264+00:00 heroku router - - at=info method=PUT path="/api/users/1444768362206977?GciOiJIUzI1NiJ9.eyJ1aWQiOiIxNDQ0NzY4MzYyMjA2OTc3In0.zYJyQeoileWWYuge8p3rwVAJdgkHtuPyx8wepqjfc7o" host=website.com request_id=602176e6-93d6-485c-a192-2562301d34a4 dyno=web.1 connect=1ms service=5986ms status=200 bytes=2170
293 <158>1 2016-11-06T16:37:59.811535+00:00 heroku router - - at=info method=POST path="/api/posts" host=website.com request_id=aca06dff-8975-44e9-a88b-7b3d2436b529 dyno=web.1 connect=0ms service=6190ms status=200 bytes=809
438 <158>1 2016-11-06T17:18:00.812751+00:00 heroku router - - at=info method=PUT path="/api/users/1037160479734847?GciOiJIUzI1NiJ9.eyJ1aWQiOiIxMDM3MTYwNDc5NzM0ODQ3In0.FV5KynHyOQfn7DvGRm3YJ7DK9KHt_24wnzlUUjLQyvs" host=website.com request_id=fb64c800-d10d-4350-ae35-9f373980d4a2dyno=web.1 connect=1ms service=29888ms status=200 bytes=2157
436 <158>1 2016-11-06T20:38:14.512715+00:00 heroku router - - at=info method=PUT path="/api/users/367712420227701?ciOiJIUzI1NiJ9.eyJ1aWQiOiIzNjc3MTI0MjAyMjc3MDEifQ.fF_2kVeVNJWkbldACd6LDdgHFWQUTLaj3gt5zU5adMw" host=website.com request_id=669a7c34-1d73-49dc-89f0-545c025a27addyno=web.1 connect=1ms service=70156ms status=200 bytes=1584
292 <158>1 2016-11-06T22:19:33.247574+00:00 heroku router - - at=info method=POST path="/api/posts" host=website.com request_id=8b772cd0-ce91-4180-a0e8-980045697e1dyno=web.1 connect=0ms service=21110ms status=200 bytes=747
477 <158>1 2016-11-06T23:20:35.320688+00:00 heroku router - - at=warning code=H28 desc="Client Connection Idle" method=PUT path="/api/users/704013223107561?host=website.com request_id=caff0a18-c80c-4a4f-9e47-d0ee94134336 dyno=web.1 connect=0ms service=55054ms status=499 bytes=71
428 <158>1 2016-11-07T01:48:49.357164+00:00 heroku router - - at=info method=GET path="/api/posts?host=website.com request_id=13299069-adf1-45cb-b872-836b8ee958c9 dyno=web.1 connect=2ms service=7505ms status=200 bytes=29626
294 <158>1 2016-11-07T01:51:02.673770+00:00 heroku router - - at=info method=POST path="/api/posts" host=website.com request_id=548d556c-6bcb-4e4c-aac8-30208babeb5e dyno=web.1 connect=0ms service=40072ms status=200 bytes=743
428 <158>1 2016-11-07T02:01:54.350464+00:00 heroku router - - at=info method=GET path="/api/posts?host=website.com request_id=d6dc9f4f-11b4-4bbe-86ce-3c955b7c4850 dyno=web.1 connect=0ms service=5034ms status=200 bytes=28331
427 <158>1 2016-11-07T02:02:41.680396+00:00 heroku router - - at=info method=GET path="/api/posts?host=website.com request_id=ee08a0ac-a737-4f06-a25d-cfcc7bdfa949no=web.1 connect=0ms service=5747ms status=200 bytes=28432
479 <158>1 2016-11-07T02:25:18.336787+00:00 heroku router - - at=warning code=H28 desc="Client Connection Idle" method=PUT path="/api/users/1800664756874454?host=website.com request_id=a44038a2-0134-47df-94be-69e7dd2e4a90 dyno=web.1 connect=0ms service=310903ms status=499 bytes=0
When a user sends a POST request with text body and an image in a multi-part form, the server uploads the image to S3 and saves the post to DB, and responds to user. I suspect that when many users are uploading at the same time, the server process is busy uploading the image file to Amazon S3 and causes such high response time. However, it's only my speculation.
When people submit a post, should I save this post into DB without the image first, and upload the image inside a background job and update the post? Or is there something else that must be causing such high response time?
Update: New Relic report
