I was experimenting on how can we improve a page loading time which has loads of JS and image files. It turns out that we can optimize it by including JS files in the end of HTML content. That gives the flexibility to browser to render images and JS files in parallel.
The technical point of why should we include javascripts in the end, is that JS has the capability to alter the properties of HTML elements. Hence if the web developer has included JS earlier (say in the <head>), then this JS file might be modifying the HTML elements that are gonna get included in the <body>. In this case, browser first needs to know the properties that JS is applying on elements and only then it can fetch and load the elements. This halts the process of loading HTML elements when a JS is getting loaded.
Following are two screenshots where the same has been depicted. Please observe the network request for get_top_menu.js that has been highlighted. I have moved its position from <head> (screenshot 1) to <footer> (screenshot 2).
-
- When JS is included in the beginning
-
- When JS is included in the end
With fragment caching floating around it always remain to decide how small piece of code should I cache. Is it worth caching a code as it renders a partial, or just because it has a few lines of HTML/ JS / Ruby code, or it makes a few DB calls to fetch data.
This blog is dedicated to my findings and observations regarding the same. I am using Rails 3 + Memcachedb + Ubuntu for my experiments. Please note that I have mentioned average response time after coupling a few requests.
1. Small partials – caching not needed
About partial: Few lines of HTML / CSS and JS code (Around 10 lines)
- Response Time when cache was set:
Started GET “/get_top_menu.js” for 127.0.0.1 at 2011-04-20 11:58:58 +0530
Processing by HomeController#get_top_menu as JS
User Load (9.9ms) SELECT `users`.* FROM `users` WHERE (`users`.`id` = 1) LIMIT 1
Exist fragment? views/logged_in-true (1.9ms)
Read fragment views/logged_in-true (0.1ms)
Rendered home/get_top_menu.js.erb (1201.0ms)
Completed 200 OK in 1259ms (Views: 1247.3ms | ActiveRecord: 9.9ms | Sphinx: 0.0ms) - Response time when cache was not set:
Rails.cache.delete(‘views/logged_in-true’)
Started GET “/get_top_menu.js” for 127.0.0.1 at 2011-04-20 12:07:53 +0530
Processing by HomeController#get_top_menu as JS
User Load (1.5ms) SELECT `users`.* FROM `users` WHERE (`users`.`id` = 1) LIMIT 1
Exist fragment? views/logged_in-true (6.7ms)
Rendered devise/menu/_logged_in_menu.html.erb (7.7ms)
Rendered devise/menu/_logged_in.html.erb (19.2ms)
Write fragment views/logged_in-true (1.2ms)
Rendered home/get_top_menu.js.erb (1225.8ms)
Completed 200 OK in 1284ms (Views: 1281.5ms | ActiveRecord: 1.5ms | Sphinx: 0.0ms)Please observe there was no time saved with cache here. Probably because sending a tcp request to memcachedb (even on localhost) is itself time consuming. Here we made 2 such requests, one to check if cache exists and second to actually fetch it. This nullifies the time we saved on rendering a small partial.
- Response time when we did not implement any cache:
Started GET “/get_top_menu.js” for 127.0.0.1 at 2011-04-20 12:14:25 +0530
Processing by HomeController#get_top_menu as JS
User Load (3.3ms) SELECT `users`.* FROM `users` WHERE (`users`.`id` = 1) LIMIT 1
Rendered devise/menu/_logged_in_menu.html.erb (1.3ms)
Rendered devise/menu/_logged_in.html.erb (7.6ms)
Rendered home/get_top_menu.js.erb (425.6ms)
Completed 200 OK in 462ms (Views: 457.6ms | ActiveRecord: 3.3ms | Sphinx: 0.0ms)Please observe there we got a faster response when cache was not at all used. Probably because sending a tcp request to memcachedb (even on localhost) is itself time consuming.
I guess results are pretty self explanatory and make sure that you use fragment cache when there is a need and not for every small request. The need arises when there are sql queries (they will anyway make tcp requests to db) or heavy computation in ruby code. You will also save memory by not dumping in huge contents (HTML / CSS / JS) which do not require much time to render.
- Use escape_javascript: When you are making an ajax call and in response sending JS that will insert the content in an HTML element, make sure you run escape_javascript on the content. For e.g. $(“#div”).html(‘<%= variable %>’). In this case if variable’s value contains a quote ‘, the resulting JS that would be rendered in browser: $(“#div”).html(‘value_’_with_quote’). This will result in error on client’s browser and since server is not aware of the error, you do not get any notification. That makes this error worse. If you use $(“#div”).html(‘<%= escape_javascript (variable) %>’); the resulting safe js would be: $(“#div”).html(‘value_\’_with_quote’)
- addition of a nil string: Many a times I need to do an addition involving a ruby variable. For e.g. Post.first.name + ” extra string”. In case Post.first.name is not set, this statement gives an exception and errors out on the account that + operator does not accept a nil operand. You can either run a check on each variable if it is a nil, or you can simple add .to_s to save from the error. It becomes: Post.first.name.to_s + ” extra string”. ps: nil.to_s => “”
- Keep all css files directly under /public/stylesheets: Most of us use :cache => true when specifying css files in our layout. This helps us in many ways by consolidating all css files in /public/stylesheets/all.css and thus saving from multiple requests from browser when loading css files. However this has a problem, whey you deposit your css under a sub folder. Eg. you have a plugin css file /public/stylesheets/category/some.css and it refers to images which are also kept in /public/stylesheets/category/images. Now when some.css gets included in /public/stylesheets/all.css, it is not able to refer to images in /public/stylesheets/category/images. It will try to find those images in /public/stylesheets/images folder. You may change some.css to refer images from a different folder but then if you upgrade plugin, you do this every time! It is better to discard the folder “category” and keep some.css under /public/stylesheets. Have a common folder of all the ‘images’ of all the css files.
- Caching – Pitfalls: Once you enable caching in your code, there are various pitfalls that you need to take care off:
- content_for no longer works if called from a cached block. If you are setting your page title in layout and running a content_for in each view file to populate the title, you need to step back. If you action cache your page, content_for being a ruby code will run only once after setting up cache it won’t run and hence no title set hereon.
- caches_action => :index, :layout => false. With this your content_for code will not run even for first time. Seems rails does some fancy stuff to enable layout => false
- No more protect_from_forgery. Your rails form contains the authenticity_token cached during the first call. So for subsequent calls, stale authenticity_token is served which breaks the code
- Railcast 169: Describes a nice way to run dynamic pages with page caches enabled.
Stuck with Rails debugging? Here are some useful Commands that you should know and will help you in diagnose your system. First few commands are in general for any production environment. Last few ones are specific to ruby on rails. This is basic diagnose and my next post will elaborate more on the various tools you can use to fix things up.
- last – Checkout out who all last logged in on the machine. This helps a little to get an idea whether the issue was self triggered or due to someone’s mischief.
- who – Who all are logged in right now? Is someone else experimenting on the machine?
- pstree -ap -u <user> – Let us dive into more serious debugging. This command will give you various processes running under a user’s name. It shows the processes in a tree format so that you know which process spawned subsequent children processes. By default you will observe that there are x number of ruby processes spawned by init. This x is the configuration specified to nginx for how many processes to spawn in parallel. Here is the output that I caught on a stable production m/c:
- ps -ef – This command will give you long list of processes, their parent processes and the commands with which they were invoked. We can do a grep to find out the details about a particular process. Here is the output of the process we are interested in (pid: 12368 – as mentioned by pstree output).
$ ps -ef | grep 12368
ubuntu 12368 1 0 Apr05 ? 00:01:18 Rack: /home/ubuntu/github/trips3m
ubuntu 27806 27651 0 11:04 pts/0 00:00:00 grep –color=auto 12368Usually, the parent process of this ruby child is 1 (init). The reason is that any process spawned by a demon (here nginx/passenger) will get its parent id as that of init, 1. This is to save the process by getting killed in case its parent process was killed. init lives in your system untill you reboot. Another observation is that is shows the time when it was spawned (here Apr 05). This is the date when you restarted your server!
Finally the command with which the process was spawned: Rack. This command is provided by rails so that 3rd party servers or scripts can invoke rails and serve the query to browser. So this is a very generic command. - top - Ok, so we now know about the processes running on our system and their utility. How do we debug if we are not getting a timely response or nothing is showing up in logs. Well, if for a web request you are seeing that browser is just waiting for data from your server, first check if any entry is getting populated in:
- logs/production.log, or
- /opt/nginx/logs/error.log
The entries in these files are populated when the request gets completed by the web server (rails). If nothing is getting populated, it means that rails is still stuck while resolving the response for your request. There are high chances that your web request is still running on the server due to one of many possible issues. (may be in infinite loop, or is hanging somewhere, etc.). Check out this command (top) to know what exactly is happening on system now. This will give you leads on CPU usage, memory usage and which process is eating how much resources. See for following symptoms:
- High CPU consumption – This means one of your process is in infinite loop or running some complex algorithms which you need to fix. Normally when a web request comes to your server, the ruby processes consumes 90% cpu for couple of seconds and then chills down. If this is eating high CPU for long, you need to improve your code. Check out the controller and other ruby functions you invoked while serving for this particular action.
- High Memory consumption - Memory Leaks! You are doomed. Resort to one of the memory debugger tools or take a careful look at your code again.
- lsof – It talks about the files that are being handled by a running process. Not sure what you can make out of it, but at times it may be useful.
- /proc/$pid/ – Contains all the information about any running process. All the commands derive their data from this virtual filesystem. So hack it down if you are searching for any answers related to a process.
pstree -ap -u ubuntu
redis-server,2725 redis.conf
ruby,12368
—{ruby},12370
ruby,12376
—{ruby},26025
searchd,5346 –pidfile –config /home/ubuntu/github/trips3m/config/production.sphinx.conf
sshd,27650
—bash,27651
——pstree,27804 -ap -u ubuntu
It is easy to note that the two processes of ruby were started by nginx and they will serve to the requests made by the client. They work as pool threads and nginx keeps them up even if there is no current request to be served.
System information: I am using nginx + Passenger on Rails 3 on Ubuntu.
