Rails log shows unexpected data as to the time spent on a DB stuff
- by Arhimed
I'm running on WinXP + Ruby 1.8.6 + Rails 2.3.5 (frozen to the project) in development environment.
Looking at development.log I observe inconsistent data as to the time spent on a database stuff.
Example #1 (good):
Processing PagesController#index (for 127.0.0.1 at 2010-05-11 12:15:54) [GET]
Parameters: {"action"=>"index", "controller"=>"pages"}
City Columns (563.0ms) SHOW FIELDS FROM `cities`
City Load (15.0ms) SELECT * FROM `cities` WHERE (`cities`.`short_name` = 'NY') LIMIT 1
Redirected to http://xyz:3000/sightings
Completed in 953ms (DB: 578) | 302 Found [http://xyz/]
Example #2 (unexpected):
Processing PagesController#index (for 127.0.0.1 at 2010-05-11 12:15:36) [GET]
Parameters: {"action"=>"index", "controller"=>"pages"}
City Columns (0.0ms) SHOW FIELDS FROM `cities`
City Load (0.0ms) SELECT * FROM `cities` WHERE (`cities`.`short_name` = 'NY') LIMIT 1
Redirected to http://xyz:3000/sightings
Completed in 47ms (DB: 32) | 302 Found [http://xyz/]
Example #2 shows 32ms were spent on DB while there were just 2 sql querries and both of zero time spent.
Example #3 (unexpected):
Processing PagesController#index (for 127.0.0.1 at 2010-05-11 11:21:24) [GET]
Parameters: {"action"=>"index", "controller"=>"pages"}
City Columns (63.0ms) SHOW FIELDS FROM `cities`
City Load (62.0ms) SELECT * FROM `cities` WHERE (`cities`.`short_name` = 'NY') LIMIT 1
Redirected to http://xyz:3000/sightings
Completed in 1187ms (DB: 297) | 302 Found [http://xyz/]
Example #3 shows 297ms while there were querries of 63ms and 62ms (125ms in total).
Can't understand it. Could someone explain?
Thanks in advance.
