blob: 2a34795b08ed26c61a32fdcebf448ac1e95d6013 (
plain) (
blame)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
|
== On The Road to Optimization ==
=== Looking at the log file in regards to optimization ===
You actually have been gathering data for benchmarking throughout your development cycle. Your log files are not just for error detection they also contain very useful information on how speedy your action is behaving.
.Regular Log Output
----------------------------------------------------------------------------
Processing MediaController#index (for 127.0.0.1 at 2008-07-17 21:30:21) [GET]
Session ID: BAh7BiIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo
SGFzaHsABjoKQHVzZWR7AA==--cb57dad9c5e4704f0e1eddb3d498fef544faaf46
Parameters: {"action"=>"index", "controller"=>"media"}
[4;35;1mProduct Columns (0.003187)[0m [0mSHOW FIELDS FROM `products`[0m
[4;36;1mProduct Load (0.000597)[0m [0;1mSELECT * FROM `products` WHERE (`products`.`name` = 'Escape Plane') LIMIT 1[0m
Rendering template within layouts/standard
Rendering media/index
[4;35;1mTrack Load (0.001507)[0m [0mSELECT * FROM `tracks` WHERE (`tracks`.product_id = 1) [0m
[4;36;1mTrack Columns (0.002280)[0m [0;1mSHOW FIELDS FROM `tracks`[0m
Rendered layouts/_header (0.00051)
*Completed in 0.04310 (23 reqs/sec) | Rendering: 0.00819 (19%) | DB: 0.00757 (17%) | 200 OK [http://localhost/media]*
----------------------------------------------------------------------------
What concerns us here is the last line of the action.
Completed in 0.04310 (23 reqs/sec) gives us the amount of requests this specific action can handle. 0.04310 is the total amount of time the process to complete and 23 reqs/sec is an estimation from this. As we will see this number is not strictly valid since is a single instance of the process. But it does give you a general feel as to how the action is performing.
Rendering: 0.00819 (19%) is the amount in milliseconds and the percentage of total time needed to complete the action for rendering the view
DB: 0.00757 (17%) is the amount in milliseconds and the percentage of total time needed to complete the action for querying the database
Pretty easy right. But wait 17+19 equals 36. 36%! where is the rest of the time going? The rest of the time is being spent processing the controller. It is not shown but it is easy to calculate. Usually there is where most of your time ends on well functions actions.
=== Why the Log File on it's Own is not Helpful ===
So why can't we just use this to test our rails application. Technically that could work, but would be very stressful and slow. You don't have time to view your log after every request to see if your code is running quickly. Also a request that runs 100 reqs/sec might simply be an outlier and really usually runs at 20 reqs/sec. It's simply not enough information to do everything we need it to do but it's a start.
But there is something else we must consider.
=== A Simple Question, a Complicated Answer ===
Is Completed in 0.04310 (23 reqs/sec) a good time. Seems like it doesn't it. 43 ms does not outrageous time for a dynamic page load. But is this a dynamic page load. Maybe it was all cached. In which case this is very slow. Or maybe I'm running on five year old equipment and this is actually blazing fast for my G3. The truth is that we can't answer the question given the data. This is part of benchmarking. We need a baseline. Through comparative analysis of all your pages in your app, and an simple dynamic page for a control we can determine how fast your pages are actually running and if any of them need to be optimized.
And now for something completely different a short statistic lesson.
|
