One of the features of production mode is that error messages are suppressed or greatly simplified at the browser. As some errors only manifest at the server, it is important that you are able to identify the cause of errors, so as to fix them. The best resource for doing this is the production.log, which is located in the log folder of your application.
Providing an in-depth description of all error types and resultant logs is beyond the scope of this book. Therefore, instead, I have decided to use a couple of examples of problems I have found recently in a live application. These examples show the production log and describe the symptoms, cause, and fix for each problem. They demonstrate the type of log entry that a problem can generate, and how I was able to use that information to correct the problem.
This example shows how adding additional processing within the loop building lines in a list view table, negatively impacted the performance of the application. It also shows how this problem was highlighted by information within the production log.
The code for rendering a list of job codes had been simplified to make it easier to maintain. However, on putting into production, the list page became very slow. I investigated the production log and found this:
Processing JobcodeController#list (for 192.168.0.234 at 2006-12-19 11:42:59) [GET]
Session ID: 34901004e225fb2b8c43d3933b021049
Parameters: {"action"=>"list", "controller"=>"jobcode"}
Rendering within layouts/jobcode
Rendering jobcode/list
Completed in 8.42200 (0 reqs/sec) | Rendering: 0.24800 (2%) | DB: 8.14200 (96%) | 200 OK [http://miggins.bromyard.local/jobcode]
The key information from the log was that the list action was taking almost eight and half seconds to complete, and that 96% of this time was taken up accessing the database (last line).
I had created a new class method and instance method to identify whether an item was live—that is its timestamp matched the current timestamp. The code for these methods was in the Jobcode model method:
#When new job codes are added to the database or updated they are given a timestamp #The current timestamp is the most recent one used. def Jobcode.current_timestamp last_timestamp = Jobcode.find(:first, :order => 'timestamp desc'). timestamp end #Job numbers are only live if they have been updated #or added during the last update def is_live? self.timestamp == Jobcode.current_timestamp end
I then used the is_live? method, to highlight the inactive job codes with an alternative style in the list view table:
<% @jobcodes.each do |code| -%> <% if code.is_live? class_name = "no_alert" else class_name = "alert" end -%> <tr class=<%= class_name %>>
This meant that when listing each job code, the current_timestamp method was run. So, each line resulted in a query to the database. It was all these calls to the database that was taking up most of the eight and a half seconds.
I added"@lastest_timestamp = Jobcode.current_timestamp" to the controller's list method as the latest timestamp only needed to be ascertained once. I then tested against @latest_timestamp on each line:
<% @jobcodes.each do |code| -%> <% if code.timestamp == @lastest_timestamp class_name = "no_alert" else class_name = "alert" end -%> <tr class=<%= class_name %>>
This meant that each test was made against a single variable held in memory rather than a new call to the database. The result was a significant performance improvement:
Processing JobcodeController#list (for 192.168.0.234 at 2006-12-19 11:52:34) [GET]
Session ID: 34901004e225fb2b8c43d3933b021049
Parameters: {"action"=>"list", "controller"=>"jobcode"}
Rendering within layouts/jobcode
Rendering jobcode/list
Completed in 0.29600 (3 reqs/sec) | Rendering: 0.11000 (37%) | DB: 0.15400 (52%) | 200 OK [http://miggins.bromyard.local/jobcode]
This example demonstrates how page completion statistics in the production log can be used to identify bottlenecks in the application. Removing such bottlenecks can be one of the best performance boosts you can make to an application.
The main cause of this problem was poor coding, rather than an inherent Rails problem. However, a key reason for presenting it here is that it demonstrates the impact of poor coding decisions vary depending on where the code is put. It is very easy to put poorly-thought-through-functionality within a loop, and as a result, for the impact of poor coding decisions to be greatly amplified.
In particular, list views by their nature are places where additional processing on each loop through the data can greatly slow down the page load. For this reason it is usually a best practice to get the data as close as possible to the final output within the controller method. Ideally, looping through the data in the view should only involve placement of data within the page and not additional processing of the data.
This is an example of an error seen at the server, but not on the development system. The problem occurred due to a simple oversight, but such oversights can be difficult to track down. Fortunately, the information need to track down the problem was present within the production log.
This problem manifested in production, so the only error message at the browser was "Application Error". Returning to the development system and following exactly the same steps produced no error. However, the production log showed a long error message, within which was a key piece of information.
The key entry in the log that led me to the cause of the problem was this line:
ActionView::TemplateError (No rhtml, rxml, rjs or delegate template found for jobcode/_list_table) on line #17 of app/views/jobcode/list.rhtml:
One of the modifications I had made recently was to extract the list code from one view and create a partial based on that code. I then used the partial in two different views. However, I forgot to add the new partial file to the Subversion repository. When I updated the production code, the file was omitted because it was not in the repository.
I added the partial file to the repository and ran svn update again on the server. This uploaded the file to the production system.
This problem demonstrates that it is possible to have errors in the production systems that are not in the development system. Therefore, you need to be able to test and bug track in the production environment. A second point is that errors can result in long entries into the log. In my experience, the most useful information is in the first few lines of the log entry (that is, near the top of the log). Do not be overwhelmed by long log entries. Start from the top and work down through each line. You will often find the root cause in the first few lines.