Creating a request database

RLA comes with an option to create an SQLite 3 database packed with all the data that is parsed from your log file. Creating a database is simple with the following command:

$ request-log-analyzer -d requests.db production.*.log

Because inserting the parsed information into the database consumes time, parsing will be slower than normal. However, the resulting database can be used for any number of queries, without having to re-parse to log file. So when you have a complete database, downdrilling is really fast.

Database contents

The database will include the following generic tables:

• requests: for every request, a record is inserted into this table. Use this table to combine the different lines that are parsed.
• warnings: every warning is logged as a separate record in this table.

For every line type that is defined in the file format, a table is created, using <line_type>_lines as table name. For example, a table called processing_lines will be created for all “Processing …” lines in Rails log files. This table contains the field request_id to link to the request-record and lineno, which contains the line number on which the line was found in the log file. Moreover, for every value that is captured a field is created.

For the Rails log file format, the following tables are created:

• processing_lines: controller, action, format, ip, timestamp and method.
• cache_hit_lines: no values are parsed for this line type.
• failure_lines: error, message, line, file, and stack_trace.
• completed_lines: duration, view, db, status and url.

Running SQL queries on the database

We are planning to develop a tool to easily query this database. For now, you can query the database by executing your own SQL queries.

You can simply open the database with the sqlite3 command line tool:

 $ sqlite3 requests.db

Use the command .tables to see what tables are in the database. .schema <tablename> will show what fields are in the tables. To get better readable output, issue the command .mode columns.

Example query: performance of XML requests

The following query returns what actions are requested as XML, how often these actions are called, and the average and cumulative server time for these actions.

SELECT p.controller || ‘#’ || p.action AS action, COUNT AS frequency,

        AVG AS average_server_time, SUM AS cumulative_server_time

  FROM requests r 

 INNER JOIN processing_lines p ON (r.id = p.request_id) 

 INNER JOIN completed_lines c ON (r.id = c.request_id)

 WHERE format = ‘xml’ 

 GROUP BY action

 ORDER BY frequency DESC;

The result will look something like this:
|. action |. frequency |. average_server_time |. cumulativeservertime |
| ProjectsController#show |>. 44 |>. 0.973 |>. 39.738 |
| ProjectsController#index |>. 12 |>. 2.740 |>. 32.114 |
| … |>. … |>. … |>. … |

Example query: cache hit frequency

The following query will determine how many requests can be served from cache. All my cached pages are actions of the CachedPageController.

SELECT p.controller || '#' || p.action AS action, (ch.id IS NOT NULL) AS cache_hit,
       COUNT(r.id) AS frequency
  FROM requests r 
 INNER JOIN processing_lines p ON (r.id = p.request_id) 
  LEFT JOIN cache_hit_lines ch ON (r.id = ch.request_id)
 WHERE p.controller = 'CachedPageController'
 GROUP BY action, cache_hit
 ORDER BY action, cache_hit;

The result will look something like this:

action	cache_hit	frequency
CachedPageController#index	0	328
CachedPageController#index	1	9863
CachedPageController#products	0	143
CachedPageController#products	1	1986
…	…	…

Rails development file format

Besides the default rails file format, rails_development exists as well. This file format parses some lines that are added to the log file if you are not running in production mode. Enable this format using the --format command line option:

$ request-log-analyzer --format rails_development --database requests.db log/development.log

Note that parsing will be slower and the resulting database will be bigger, because more lines are parsed. When r-l-a has finished parsing, the following tables will be available in your request database as well:

• rendered_lines: render_file and render_duration.
  These lines contain benchmarks of the partial rendering.
• query_completed_lines: query_class, query_duration and query_sql.
  Benchmarks of executed SQL queries.
• query_cached_lines: cached_duration and cached_sql.
  SQL queries cached by Rails.

Example query: slowest partials

The following query will find the partials that have the slowest average render time:

SELECT render_file, COUNT(render_file) AS frequency, 
       AVG(render_duration) AS average_render_time 
  FROM rendered_lines 
 GROUP BY render_file 
 ORDER BY average_render_time DESC;