In depth analysis
A basic run of the request log analyzer will give you a good starting point of things that need to be optimized. But when all the major problems have been removed from you application and you are generating some real traffic, you really want to have a more in depth look in the requests.
In the future, requests-log-analyzer will have an interactive console that will allow you to do just that, using an SQLite database. In the meantime, the --select and --reject options and the --after and --before options can help you get a lot of insight.
Read on for some real world examples of the power of the request-log-analyzer.
As always, I started analyzing the application using the following command:
request-log-analyzer ./app.log
Everything was pretty normal, except our RssController was showing in the ProcessBlocker list. This is weird, as normally slow requests will show up in other lists as well, but this time it only showed up in the processblocker list. To get some more information, we will start to drill down using the request-log-analyzer. I am only interested in the RssController, so I run the following command:
request-log-analyzer ./app.log --select controller RssController
This gave me the following:
Rails action cache hits ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Cache hit ┃ 18147 hits (70.2%) ┃░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ No hit ┃ 7712 hits (29.8%) ┃░░░░░░░░░░░░░░░░ Request duration - top 20 by cumulative time ┃ Hits ┃ Sum. | Avg. ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ RssController#index.html [GET] ┃ 25840 ┃ 16883.51s ┃ 0.65s RssController#index.rss [GET] ┃ 19 ┃ 44.67s ┃ 2.35s Process blockers (> 1 sec duration) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ RssController#index.html [GET] ┃ 7172 hits (99.7%) ┃░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ RssController#index.rss [GET] ┃ 19 hits (0.3%) ┃
This explains a lot. When the RssController is hit, and we have a cache hit, there is no problem. But when we do not have a cache hit (7712 times) the regeneration of the rss feed is extremely slow. This does not show up in the initial request-log-analyzer run, as the average execution time of the total is pretty quick (0.65s).
After having deployed a fix of this slow behavior, I wanted to know if my fix had the desired effect. This can easily be done by running the same command again, but now with an included --after option so that only requests after the fix date (2009-01-10) are considered:
request-log-analyzer ./app.log --select controller RssController --after 2009-01-10
Sweet success :)!
Rails action cache hits ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Cache hit ┃ 889 hits (72.3%) ┃░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ No hit ┃ 340 hits (27.7%) ┃░░░░░░░░░░░░░░░░ Request duration - top 20 by cumulative time ┃ Hits ┃ Sum. | Avg. ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ RssController#index.html [GET] ┃ 1229 ┃ 405.57s ┃ 0.33s Process blockers (> 1 sec duration) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━