Slow rails performance when POSTing specific JSON

Question

I've been testing my app's performance and found out that it takes 1 second from the time that data was posted to executing first line of action method. I'm testing this on empty rails 4 app (created using rails new app_name) and ruby 1.9.3-p448. I've only added one controller:

class TestController < ApplicationController
  skip_before_filter :verify_authenticity_token

  def testt
    render json: {new: true}
  end
end

and a route:

post "api/v1/tt" => "test#testt"

Here's the JSON that I'm posting:

{
  "params": {
    "updatedBy": "f092d32a-1e38-4f07-8b76-185393138d86",
    "data": [
      {
        "typeName": "test",
        "total": 995,
        "timeOffset": 13,
        "timestamp": 1404323549565,
        "hidden": false,
        "guid": "9fc91203-e558-43e1-b585-aefbd281c5f5",
        "modificationDate": 1404316375054,
        "deleted": false
      },
      {
        "typeName": "test",
        "total": 995,
        "timeOffset": 13,
        "timestamp": 1404323549565,
        "hidden": false,
        "guid": "9fc91203-e558-43e1-b585-aefbd281c5f5",
        "modificationDate": 1404316375054,
        "deleted": false
      },
      {
        "typeName": "test",
        "total": 995,
        "timeOffset": 13,
        "timestamp": 1404323549565,
        "hidden": false,
        "guid": "9fc91203-e558-43e1-b585-aefbd281c5f5",
        "modificationDate": 1404316375054,
        "deleted": false
      },
      {
        "typeName": "test",
        "total": 995,
        "timeOffset": 13,
        "timestamp": 1404323549565,
        "hidden": false,
        "guid": "9fc91203-e558-43e1-b585-aefbd281c5f5",
        "modificationDate": 1404316375054,
        "deleted": false
      },
      {
        "typeName": "test",
        "total": 995,
        "timeOffset": 13,
        "timestamp": 1404323549565,
        "hidden": false,
        "guid": "9fc91203-e558-43e1-b585-aefbd281c5f5",
        "modificationDate": 1404316375054,
        "deleted": false
      }
    ]
  }
}

using this command:

curl -H "Content-Type: application/json" -b cookies -c cookies --request POST "http://localhost/api/v1/tt" --data "@upload.json" -w "@timings-format.txt"

timings-format.txt contains:

    time_namelookup:  %{time_namelookup}\n
       time_connect:  %{time_connect}\n
    time_appconnect:  %{time_appconnect}\n
   time_pretransfer:  %{time_pretransfer}\n
      time_redirect:  %{time_redirect}\n
 time_starttransfer:  %{time_starttransfer}\n
                    ----------\n
         time_total:  %{time_total}\n

When I run the command, I get something like this:

{"new":true}
    time_namelookup:  0,001
       time_connect:  0,001
    time_appconnect:  0,000
   time_pretransfer:  0,001
      time_redirect:  0,000
 time_starttransfer:  1,003
                    ----------
         time_total:  1,010

If I minify the JSON like this:

{"params":{"updatedBy":"f092d32a-1e38-4f07-8b76-185393138d86","data":[{"typeName":"test","total":995,"timeOffset":13,"timestamp":1404323549565,"hidden":false,"guid":"9fc91203-e558-43e1-b585-aefbd281c5f5","modificationDate":1404316375054,"deleted":false},{"typeName":"test","total":995,"timeOffset":13,"timestamp":1404323549565,"hidden":false,"guid":"9fc91203-e558-43e1-b585-aefbd281c5f5","modificationDate":1404316375054,"deleted":false},{"typeName":"test","total":995,"timeOffset":13,"timestamp":1404323549565,"hidden":false,"guid":"9fc91203-e558-43e1-b585-aefbd281c5f5","modificationDate":1404316375054,"deleted":false},{"typeName":"test","total":995,"timeOffset":13,"timestamp":1404323549565,"hidden":false,"guid":"9fc91203-e558-43e1-b585-aefbd281c5f5","modificationDate":1404316375054,"deleted":false},{"typeName":"test","total":995,"timeOffset":13,"timestamp":1404323549565,"hidden":false,"guid":"9fc91203-e558-43e1-b585-aefbd281c5f5","modificationDate":1404316375054,"deleted":false}]}}

and the run the command again, I get:

{"new":true}
    time_namelookup:  0,001
       time_connect:  0,002
    time_appconnect:  0,000
   time_pretransfer:  0,002
      time_redirect:  0,000
 time_starttransfer:  0,008
                    ----------
         time_total:  0,008

Does anyone have an idea of what is going on? I also have larger JSON that is minified but it still takes 1 second to execute empty action...

score 0 · Answer 1 · answered Jul 03 '14 at 13:52

0

Your are in development mode and things are just slower by nature on it. Also your are probably using Webrick as development server and it is slow too. Check on real production deployment in production mode with nginx + unicorn or nginx + passenger. Perform several requests, as it needs also to warm up.

And i really would grab rvm and get ruby-2.1.2, the most rock solid MRI Ruby implementation ever

answered Jul 03 '14 at 13:52

dre-hh

7,840
2
33
44

Yes, I'm using WEBrick and development env. I'm also performing several requests to warm it up. But if this is dev vs production problem, why does this 1 second delay happen only on some JSON data, while other works perfectly fine? – xx77aBs Jul 03 '14 at 13:55
check out thin as development server. Just include `gem thin` in development group – dre-hh Jul 03 '14 at 14:02

score 0 · Accepted Answer · edited May 23 '17 at 12:11

0

Turns out the problem was in cURL. After implementing the same thing in ruby (just reading file and POSTing the date), I get saner times (cca 20-30ms). Here is detailed explanation:

https://stackoverflow.com/a/17390776/579843

edited May 23 '17 at 12:11

Community

1
1

answered Jul 03 '14 at 16:58

xx77aBs

4,678
9
53
77

Slow rails performance when POSTing specific JSON

2 Answers2