Rails log shows unexpected data as to the time spent on a DB stuff

Posted by Arhimed on Stack Overflow See other posts from Stack Overflow or by Arhimed
Published on 2010-05-11T19:13:02Z Indexed on 2010/05/11 19:14 UTC
Read the original article Hit count: 233

Filed under:

ruby-on-rails

|

logging

|

database

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.

Developer IT