# Logfile created on Mon Mar 03 17:32:51 +0900 2008  SQL (0.000112)   SET SQL_AUTO_IS_NULL=0
  SQL (0.000039)   BEGIN
  Product Load (0.012270)   SELECT * FROM `products` WHERE (`products`.`id` = 2) 
  SQL (0.000082)   ROLLBACK
  SQL (0.000053)   BEGIN
  Product Load (0.000056)   SELECT * FROM `products` WHERE (`products`.`id` = 2) 
  Product Load (0.000146)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
  SQL (0.000057)   ROLLBACK
  SQL (0.000038)   BEGIN
  SQL (0.000039)   ROLLBACK
  SQL (0.000038)   BEGIN
  SQL (0.000039)   ROLLBACK
  SQL (0.000039)   BEGIN
  Product Load (0.000143)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000050)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000050)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000049)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000051)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000050)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000049)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000049)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000049)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  SQL (0.000055)   ROLLBACK
  SQL (0.000040)   BEGIN
  Product Load (0.000124)   SELECT * FROM `products` WHERE (products.title IS NULL) LIMIT 1
  SQL (0.000051)   ROLLBACK
  SQL (0.000039)   BEGIN
  Product Load (0.000051)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000049)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  Product Load (0.000049)   SELECT * FROM `products` WHERE (products.title = 'My Book Title') LIMIT 1
  SQL (0.000048)   ROLLBACK
  SQL (0.000040)   BEGIN
  SQL (0.000039)   ROLLBACK
  SQL (0.000040)   BEGIN
  Product Load (0.000050)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
  Product Load (0.000128)   SELECT * FROM `products` WHERE (products.title = 'Programming Ruby') LIMIT 1
  SQL (0.000049)   ROLLBACK
  SQL (0.000040)   BEGIN
  Product Load (0.000050)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
  Product Load (0.000050)   SELECT * FROM `products` WHERE (products.title = 'Programming Ruby') LIMIT 1
  SQL (0.000049)   ROLLBACK
  SQL (0.000120)   SET SQL_AUTO_IS_NULL=0
  SQL (0.000039)   BEGIN
  User Columns (0.000471)   SHOW FIELDS FROM `users`
  User Load (0.000161)   SELECT * FROM `users` WHERE (users.name = 'u1') LIMIT 1
  User Create (0.000118)   INSERT INTO `users` (`name`, `salt`, `hashed_password`) VALUES('u1', '-6114594080.208039035410805', 'df084beb51cb842f0ca290921469be2feb954977')
  User Load (0.000104)   SELECT * FROM `users` WHERE (users.name = 'u2') LIMIT 1
  User Create (0.000084)   INSERT INTO `users` (`name`, `salt`, `hashed_password`) VALUES('u2', '-6114726580.381384300460964', 'c986ad838c6e9fbddb4f3c915dd3685300531f30')


Processing AdminController#new (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"new", "controller"=>"admin"}
  User Load (0.000147)   SELECT * FROM `users` WHERE (`users`.`id` IS NULL) LIMIT 1
Redirected to http://test.host/login/login
Filter chain halted as [#<ActionController::Filters::ClassMethods::SymbolFilter:0xb78fa464 @filter=:authorize>] rendered_or_redirected.
Completed in 0.00096 (1038 reqs/sec) | DB: 0.00124 (129%) | 302 Found [http://test.host/admin/new]
  User Load (0.000128)   SELECT * FROM `users` WHERE (`users`.`name` = 'u1') LIMIT 1


Processing AdminController#edit (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"edit", "id"=>"1", "controller"=>"admin"}
  User Load (0.000124)   SELECT * FROM `users` WHERE (`users`.`id` = 1) LIMIT 1
  Product Load (0.000124)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
Rendering template within layouts/admin
Rendering admin/edit
Rendered admin/_form (0.01419)
Completed in 0.04391 (22 reqs/sec) | Rendering: 0.04044 (92%) | DB: 0.00038 (0%) | 200 OK [http://test.host/admin/new]


Processing AdminController#edit_erb (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"edit_erb", "id"=>"1", "controller"=>"admin"}
  User Load (0.000235)   SELECT * FROM `users` WHERE (`users`.`id` = 1) LIMIT 1
  Product Load (0.000050)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
Rendering template within layouts/admin
Rendering admin/edit.html.erb
Rendered admin/_form.html.erb (0.00163)
Completed in 0.00646 (154 reqs/sec) | Rendering: 0.00549 (84%) | DB: 0.00029 (4%) | 200 OK [http://test.host/admin/new]
  SQL (0.000218)   ROLLBACK
  SQL (0.000051)   BEGIN
  User Load (0.000163)   SELECT * FROM `users` WHERE (users.name = 'u1') LIMIT 1
  User Create (0.000111)   INSERT INTO `users` (`name`, `salt`, `hashed_password`) VALUES('u1', '-6119181980.308624885039377', '3cfd71a1d5f7ba3b927a5f1a9503573297c30bee')
  User Load (0.000102)   SELECT * FROM `users` WHERE (users.name = 'u2') LIMIT 1
  User Create (0.000082)   INSERT INTO `users` (`name`, `salt`, `hashed_password`) VALUES('u2', '-6119229680.21105499402099', 'f1ee1d0843f3f424c3cca8399aa1272ae66577b2')


Processing AdminController#new (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"new", "controller"=>"admin"}
  User Load (0.000089)   SELECT * FROM `users` WHERE (`users`.`id` IS NULL) LIMIT 1
Redirected to http://test.host/login/login
Filter chain halted as [#<ActionController::Filters::ClassMethods::SymbolFilter:0xb78fa464 @filter=:authorize>] rendered_or_redirected.
Completed in 0.00065 (1543 reqs/sec) | DB: 0.00082 (125%) | 302 Found [http://test.host/admin/new]
  User Load (0.000104)   SELECT * FROM `users` WHERE (`users`.`name` = 'u1') LIMIT 1


Processing AdminController#list (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"list", "controller"=>"admin"}
  User Load (0.000103)   SELECT * FROM `users` WHERE (`users`.`id` = 3) LIMIT 1
  Product Load (0.000109)   SELECT * FROM `products` LIMIT 0, 30
Rendering template within layouts/admin
Rendering admin/list
Completed in 0.02093 (47 reqs/sec) | Rendering: 0.02003 (95%) | DB: 0.00032 (1%) | 200 OK [http://test.host/admin/new]


Processing AdminController#list_erb (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"list_erb", "controller"=>"admin"}
  User Load (0.000221)   SELECT * FROM `users` WHERE (`users`.`id` = 3) LIMIT 1
  Product Load (0.000057)   SELECT * FROM `products` LIMIT 0, 30
Rendering template within layouts/admin
Rendering admin/list.html.erb
Completed in 0.00627 (159 reqs/sec) | Rendering: 0.00522 (83%) | DB: 0.00028 (4%) | 200 OK [http://test.host/admin/new]
  SQL (0.000285)   ROLLBACK
  SQL (0.000057)   BEGIN
  User Load (0.000186)   SELECT * FROM `users` WHERE (users.name = 'u1') LIMIT 1
  User Create (0.000116)   INSERT INTO `users` (`name`, `salt`, `hashed_password`) VALUES('u1', '-6112362080.152167807918847', '99a23139a1f15c9600f01aaf07d216cd12bb9b26')
  User Load (0.000104)   SELECT * FROM `users` WHERE (users.name = 'u2') LIMIT 1
  User Create (0.000085)   INSERT INTO `users` (`name`, `salt`, `hashed_password`) VALUES('u2', '-6112409780.908469054730733', 'beff384038396f842c1e655ce8355dc067dbcd1d')


Processing AdminController#new (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"new", "controller"=>"admin"}
  User Load (0.000092)   SELECT * FROM `users` WHERE (`users`.`id` IS NULL) LIMIT 1
Redirected to http://test.host/login/login
Filter chain halted as [#<ActionController::Filters::ClassMethods::SymbolFilter:0xb78fa464 @filter=:authorize>] rendered_or_redirected.
Completed in 0.00069 (1457 reqs/sec) | DB: 0.00093 (134%) | 302 Found [http://test.host/admin/new]
  User Load (0.000114)   SELECT * FROM `users` WHERE (`users`.`name` = 'u1') LIMIT 1


Processing AdminController#new (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"new", "controller"=>"admin"}
  User Load (0.000106)   SELECT * FROM `users` WHERE (`users`.`id` = 5) LIMIT 1
Rendering template within layouts/admin
Rendering admin/new
Rendered admin/_form (0.00037)
Completed in 0.01032 (96 reqs/sec) | Rendering: 0.00971 (94%) | DB: 0.00022 (2%) | 200 OK [http://test.host/admin/new]


Processing AdminController#new_erb (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"new_erb", "controller"=>"admin"}
  User Load (0.000203)   SELECT * FROM `users` WHERE (`users`.`id` = 5) LIMIT 1
Rendering template within layouts/admin
Rendering admin/new.html.erb
Rendered admin/_form.html.erb (0.00064)
Completed in 0.00500 (199 reqs/sec) | Rendering: 0.00430 (86%) | DB: 0.00020 (4%) | 200 OK [http://test.host/admin/new]
  SQL (0.000214)   ROLLBACK
  SQL (0.000054)   BEGIN
  User Load (0.000164)   SELECT * FROM `users` WHERE (users.name = 'u1') LIMIT 1
  User Create (0.000119)   INSERT INTO `users` (`name`, `salt`, `hashed_password`) VALUES('u1', '-6114500980.997548771305529', '74160a4c5ff040525b91609bb8c40b904f80193b')
  User Load (0.000103)   SELECT * FROM `users` WHERE (users.name = 'u2') LIMIT 1
  User Create (0.000082)   INSERT INTO `users` (`name`, `salt`, `hashed_password`) VALUES('u2', '-6114556480.621357089109058', '44cee760ed159a288ab16cc5c850c90c8cf0ca2c')


Processing AdminController#new (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"new", "controller"=>"admin"}
  User Load (0.000088)   SELECT * FROM `users` WHERE (`users`.`id` IS NULL) LIMIT 1
Redirected to http://test.host/login/login
Filter chain halted as [#<ActionController::Filters::ClassMethods::SymbolFilter:0xb78fa464 @filter=:authorize>] rendered_or_redirected.
Completed in 0.00066 (1524 reqs/sec) | DB: 0.00082 (125%) | 302 Found [http://test.host/admin/new]
  User Load (0.000106)   SELECT * FROM `users` WHERE (`users`.`name` = 'u1') LIMIT 1


Processing AdminController#show (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"show", "id"=>"1", "controller"=>"admin"}
  User Load (0.000103)   SELECT * FROM `users` WHERE (`users`.`id` = 7) LIMIT 1
  Product Load (0.000050)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
Rendering template within layouts/admin
Rendering admin/show
Completed in 0.01027 (97 reqs/sec) | Rendering: 0.00947 (92%) | DB: 0.00026 (2%) | 200 OK [http://test.host/admin/new]


Processing AdminController#show_erb (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"show_erb", "id"=>"1", "controller"=>"admin"}
  User Load (0.000196)   SELECT * FROM `users` WHERE (`users`.`id` = 7) LIMIT 1
  Product Load (0.000050)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
Rendering template within layouts/admin
Rendering admin/show.html.erb
Completed in 0.00452 (221 reqs/sec) | Rendering: 0.00359 (79%) | DB: 0.00025 (5%) | 200 OK [http://test.host/admin/new]
  SQL (0.000235)   ROLLBACK
  SQL (0.000043)   BEGIN
  SQL (0.000040)   ROLLBACK
  SQL (0.000037)   BEGIN
  User Load (0.000138)   SELECT * FROM `users` WHERE (`users`.`id` = 1) 


Processing LoginController#login (for 0.0.0.0 at 2008-03-03 17:33:30) [POST]
  Session ID: 
  Parameters: {"name"=>"dave", "action"=>"login", "controller"=>"login", "password"=>"wrong"}
  User Load (0.000136)   SELECT * FROM `users` WHERE (`users`.`name` = 'dave') LIMIT 1
Rendering template within layouts/admin
Rendering login/login
Completed in 0.00697 (143 reqs/sec) | Rendering: 0.00386 (55%) | DB: 0.00063 (9%) | 200 OK [http://test.host/login/login?name=dave&password=wrong]
  SQL (0.000075)   ROLLBACK
  SQL (0.000053)   BEGIN
  User Load (0.000053)   SELECT * FROM `users` WHERE (`users`.`id` = 1) 


Processing LoginController#index (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"index", "controller"=>"login"}
  User Load (0.000146)   SELECT * FROM `users` WHERE (`users`.`id` = 1) LIMIT 1
  Order Columns (0.000454)   SHOW FIELDS FROM `orders`
  SQL (0.008319)   SELECT count(*) AS count_all FROM `orders` 
Rendering template within layouts/admin
Rendering login/index
Completed in 0.01554 (64 reqs/sec) | Rendering: 0.00296 (19%) | DB: 0.00910 (58%) | 200 OK [http://test.host/login]
  SQL (0.000071)   ROLLBACK
  SQL (0.000041)   BEGIN


Processing LoginController#index (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"index", "controller"=>"login"}
  User Load (0.000121)   SELECT * FROM `users` WHERE (`users`.`id` IS NULL) LIMIT 1
Redirected to http://test.host/login/login
Filter chain halted as [#<ActionController::Filters::ClassMethods::SymbolFilter:0xb721d2cc @filter=:authorize>] rendered_or_redirected.
Completed in 0.00069 (1451 reqs/sec) | DB: 0.00023 (33%) | 302 Found [http://test.host/login]
  SQL (0.000057)   ROLLBACK
  SQL (0.000040)   BEGIN
  User Load (0.000051)   SELECT * FROM `users` WHERE (`users`.`id` = 1) 


Processing LoginController#login (for 0.0.0.0 at 2008-03-03 17:33:30) [POST]
  Session ID: 
  Parameters: {"name"=>"dave", "action"=>"login", "controller"=>"login", "password"=>"secret"}
  User Load (0.000050)   SELECT * FROM `users` WHERE (`users`.`name` = 'dave') LIMIT 1
Redirected to http://test.host/login
Completed in 0.00060 (1680 reqs/sec) | DB: 0.00020 (33%) | 302 Found [http://test.host/login/login?name=dave&password=secret]
  SQL (0.000051)   ROLLBACK
  SQL (0.000039)   BEGIN
  SQL (0.000038)   ROLLBACK
  SQL (0.000039)   BEGIN
  Product Load (0.000052)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 


Processing StoreController#index (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"index", "controller"=>"store"}
  Product Load (0.001407)   SELECT * FROM `products` ORDER BY title
Rendering template within layouts/store
Rendering store/index
Rendered store/_cart (0.01173)
Completed in 0.06363 (15 reqs/sec) | Rendering: 0.05723 (89%) | DB: 0.00163 (2%) | 200 OK [http://test.host/store]


Processing StoreController#add_to_cart (for 0.0.0.0 at 2008-03-03 17:33:30) [POST]
  Session ID: 
  Parameters: {"action"=>"add_to_cart", "id"=>"1", "controller"=>"store"}
  Product Load (0.000101)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
Redirected to http://test.host/store
Completed in 0.00262 (381 reqs/sec) | Rendering: 0.05723 (2181%) | DB: 0.00173 (65%) | 302 Found [http://test.host/store]


Processing StoreController#checkout (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"checkout", "controller"=>"store"}
Rendering template within layouts/store
Rendering store/checkout
Rendered store/_cart_item (0.01060)
Rendered store/_cart (0.01153)
Completed in 0.08143 (12 reqs/sec) | Rendering: 0.08123 (99%) | DB: 0.00000 (0%) | 200 OK [http://test.host/store]


Processing StoreController#checkout_erb (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"checkout_erb", "controller"=>"store"}
Rendering template within layouts/store.rhtml
Rendering store/checkout.html.erb
Rendered store/_cart_item (0.00051)
Rendered store/_cart.html.erb (0.00232)
Completed in 0.00856 (116 reqs/sec) | Rendering: 0.00840 (98%) | DB: 0.00000 (0%) | 200 OK [http://test.host/store]
  SQL (0.000115)   ROLLBACK
  SQL (0.000052)   BEGIN


Processing StoreController#index_erb (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"index_erb", "controller"=>"store"}
  Product Load (0.000065)   SELECT * FROM `products` ORDER BY title
Rendering template within layouts/store.rhtml
Rendering store/index.html.erb
Rendered store/_cart.html.erb (0.00058)
Completed in 0.00493 (202 reqs/sec) | Rendering: 0.00451 (91%) | DB: 0.00023 (4%) | 200 OK [http://test.host/store/index_erb]


Processing StoreController#index (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"index", "controller"=>"store"}
  Product Load (0.000071)   SELECT * FROM `products` ORDER BY title
Rendering template within layouts/store
Rendering store/index
Rendered store/_cart (0.00072)
Completed in 0.00445 (224 reqs/sec) | Rendering: 0.00405 (91%) | DB: 0.00007 (1%) | 200 OK [http://test.host/store/index_erb]
  SQL (0.000093)   ROLLBACK
  SQL (0.000083)   BEGIN


Processing StoreController#index (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"index", "controller"=>"store"}
  Product Load (0.000060)   SELECT * FROM `products` ORDER BY title
Rendering template within layouts/store
Rendering store/index
Rendered store/_cart (0.00072)
Completed in 0.00446 (224 reqs/sec) | Rendering: 0.00406 (91%) | DB: 0.00024 (5%) | 200 OK [http://test.host/store]
  Product Load (0.000070)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 


Processing StoreController#add_to_cart (for 0.0.0.0 at 2008-03-03 17:33:30) [POST]
  Session ID: 
  Parameters: {"action"=>"add_to_cart", "id"=>"1", "controller"=>"store"}
  Product Load (0.000061)   SELECT * FROM `products` WHERE (`products`.`id` = 1) 
Redirected to http://test.host/store
Completed in 0.00060 (1677 reqs/sec) | Rendering: 0.00406 (680%) | DB: 0.00037 (61%) | 302 Found [http://test.host/store]


Processing StoreController#index_erb (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"index_erb", "controller"=>"store"}
  Product Load (0.000052)   SELECT * FROM `products` ORDER BY title
Rendering template within layouts/store.rhtml
Rendering store/index.html.erb
Rendered store/_cart_item (0.00050)
Rendered store/_cart.html.erb (0.00114)
Completed in 0.00385 (259 reqs/sec) | Rendering: 0.00349 (90%) | DB: 0.00005 (1%) | 200 OK [http://test.host/store]


Processing StoreController#index (for 0.0.0.0 at 2008-03-03 17:33:30) [GET]
  Session ID: 
  Parameters: {"action"=>"index", "controller"=>"store"}
  Product Load (0.000069)   SELECT * FROM `products` ORDER BY title
Rendering template within layouts/store
Rendering store/index
Rendered store/_cart_item (0.00044)
Rendered store/_cart (0.00126)
Completed in 0.00521 (191 reqs/sec) | Rendering: 0.00482 (92%) | DB: 0.00007 (1%) | 200 OK [http://test.host/store]
  SQL (0.000096)   ROLLBACK