spree/spree — pull request #4802 by jhawthorn (2014-06-08 01:35:50+00:00)
Title: Instrumentation

Spree is (understandably) a complex application and it can be tough to understand what it is doing and where it is spending it's time. I'm proposing a `Spree.instrument` method to wrap slow or complex logic and has pluggable behaviour. This adds additional logging in the development environment, and does nothing in others.

Consider as an example `GET /checkout/delivery` for a simple cart

```
Started GET "/checkout/delivery" for 127.0.0.1 at 2014-06-07 18:28:10 -0700
Processing by Spree::CheckoutController#edit as HTML
Parameters: {"state"=>"delivery"}
Spree::Preference Load (0.1ms) SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = 'spree/frontend_configuration/locale' LIMIT 1
Spree::User Load (0.1ms) SELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 ORDER BY "spree_users"."id" ASC LIMIT 1
Spree::Order Load (0.1ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."user_id" = ? AND "spree_orders"."completed_at" IS NULL AND "spree_orders"."created_by_id" = 1 ORDER BY created_at DESC LIMIT 1 [["user_id", 1]]
Spree::Order Load (0.2ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = 4 AND "spree_orders"."currency" = 'USD' LIMIT 1
Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_type" = 'Spree::Order' AND "spree_adjustments"."adjustable_id" IN (4) ORDER BY spree_adjustments.created_at ASC
Spree::Shipment Exists (0.0ms) SELECT 1 AS one FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? LIMIT 1 [["order_id", 4]]
Spree::Shipment Load (0.0ms) SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::Adjustment Load (0.0ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
SQL (86.5ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:28:11.066136' WHERE "spree_shipments"."id" = 8
(0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
SQL (84.3ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:28:11.154191' WHERE "spree_orders"."id" = 4
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
SQL (76.8ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:28:11.242524' WHERE "spree_shipments"."id" = 8
(0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
SQL (80.5ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:28:11.320835' WHERE "spree_orders"."id" = 4
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
SQL (84.8ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:28:11.404899' WHERE "spree_shipments"."id" = 8
(0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
SQL (76.6ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:28:11.491216' WHERE "spree_orders"."id" = 4
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
SQL (82.6ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:28:11.571410' WHERE "spree_shipments"."id" = 8
(0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
SQL (78.5ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:28:11.655495' WHERE "spree_orders"."id" = 4
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
(0.1ms) SELECT COUNT(*) FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? [["order_id", 4]]
Spree::LineItem Load (0.1ms) SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? ORDER BY created_at ASC [["order_id", 4]]
Spree::Variant Load (0.1ms) SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? LIMIT 1 [["id", 2]]
(0.2ms) SELECT SUM("spree_stock_items"."count_on_hand") AS sum_id FROM "spree_stock_items" INNER JOIN "spree_stock_locations" ON "spree_stock_locations"."id" = "spree_stock_items"."stock_location_id" WHERE "spree_stock_items"."deleted_at" IS NULL AND "spree_stock_items"."variant_id" = 2 AND "spree_stock_locations"."active" = 't'
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
SQL (77.9ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:28:11.741571' WHERE "spree_shipments"."id" = 8
(0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
SQL (82.3ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:28:11.821048' WHERE "spree_orders"."id" = 4
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::User Load (0.1ms) SELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = ? LIMIT 1 [["id", 1]]
Spree::StockLocation Load (0.1ms) SELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? LIMIT 1 [["id", 1]]
Spree::InventoryUnit Load (0.1ms) SELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ? [["shipment_id", 8]]
Spree::LineItem Load (0.2ms) SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."id" IN (4)
Spree::Variant Load (0.1ms) SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? LIMIT 1 [["id", 2]]
(0.1ms) SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = ? AND "spree_roles"."name" = 'admin' [["user_id", 1]]
Rendered /home/jhawthorn/src/spree/core/app/views/spree/shared/_error_messages.html.erb (0.1ms)
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::Adjustment Load (0.0ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
SQL (75.9ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:28:11.945606' WHERE "spree_shipments"."id" = 8
(0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
SQL (81.4ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:28:12.022999' WHERE "spree_orders"."id" = 4
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::InventoryUnit Load (0.0ms) SELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ? [["shipment_id", 8]]
Spree::LineItem Load (0.0ms) SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."id" = ? LIMIT 1 [["id", 4]]
Spree::Variant Load (0.0ms) SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? LIMIT 1 [["id", 2]]
Spree::Image Exists (0.1ms) SELECT 1 AS one FROM "spree_assets" WHERE "spree_assets"."type" IN ('Spree::Image') AND "spree_assets"."viewable_id" = ? AND "spree_assets"."viewable_type" = ? LIMIT 1 [["viewable_id", 2], ["viewable_type", "Spree::Variant"]]
Spree::Image Load (0.1ms) SELECT "spree_assets".* FROM "spree_assets" WHERE "spree_assets"."type" IN ('Spree::Image') AND "spree_assets"."viewable_id" = ? AND "spree_assets"."viewable_type" = ? ORDER BY "spree_assets"."position" ASC LIMIT 1 [["viewable_id", 2], ["viewable_type", "Spree::Variant"]]
Spree::Product Load (0.0ms) SELECT "spree_products".* FROM "spree_products" WHERE "spree_products"."id" = ? LIMIT 1 [["id", 2]]
Spree::Price Load (0.0ms) SELECT "spree_prices".* FROM "spree_prices" WHERE "spree_prices"."deleted_at" IS NULL AND "spree_prices"."variant_id" = ? [["variant_id", 2]]
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? ORDER BY cost ASC [["shipment_id", 8]]
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::ShippingMethod Load (0.0ms) SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."id" = ? LIMIT 1 [["id", 1]]
Spree::Shipment Load (0.0ms) SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? LIMIT 1 [["id", 8]]
Spree::Order Load (0.0ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? LIMIT 1 [["id", 4]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::ShippingMethod Load (0.1ms) SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."id" = ? LIMIT 1 [["id", 2]]
CACHE (0.0ms) SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? LIMIT 1 [["id", 8]]
CACHE (0.0ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? LIMIT 1 [["id", 4]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::ShippingMethod Load (0.0ms) SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."id" = ? LIMIT 1 [["id", 3]]
CACHE (0.0ms) SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? LIMIT 1 [["id", 8]]
CACHE (0.0ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? LIMIT 1 [["id", 4]]
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/checkout/_delivery.html.erb (14.3ms)
Spree::Adjustment Exists (0.1ms) SELECT 1 AS one FROM "spree_adjustments" INNER JOIN "spree_line_items" ON "spree_adjustments"."adjustable_id" = "spree_line_items"."id" WHERE "spree_adjustments"."adjustable_type" = ? AND "spree_line_items"."order_id" = ? LIMIT 1 [["adjustable_type", "Spree::LineItem"], ["order_id", 4]]
Spree::Adjustment Load (0.0ms) SELECT "spree_adjustments".* FROM "spree_adjustments" INNER JOIN "spree_line_items" ON "spree_adjustments"."adjustable_id" = "spree_line_items"."id" WHERE "spree_adjustments"."adjustable_type" = ? AND "spree_line_items"."order_id" = ? AND "spree_adjustments"."source_type" = 'Spree::PromotionAction' AND "spree_adjustments"."eligible" = 't' ORDER BY created_at ASC [["adjustable_type", "Spree::LineItem"], ["order_id", 4]]
Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE (order_id = 4 OR (adjustable_id = 4 AND adjustable_type = 'Spree::Order')) AND "spree_adjustments"."source_type" = 'Spree::TaxRate' AND "spree_adjustments"."eligible" = 't'
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::Adjustment Load (0.0ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
SQL (80.3ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:28:12.148405' WHERE "spree_shipments"."id" = 8
(0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
SQL (76.1ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:28:12.230068' WHERE "spree_orders"."id" = 4
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::Adjustment Exists (0.1ms) SELECT 1 AS one FROM "spree_adjustments" INNER JOIN "spree_shipments" ON "spree_adjustments"."adjustable_id" = "spree_shipments"."id" WHERE "spree_adjustments"."adjustable_type" = ? AND "spree_shipments"."order_id" = ? LIMIT 1 [["adjustable_type", "Spree::Shipment"], ["order_id", 4]]
Spree::Adjustment Exists (0.1ms) SELECT 1 AS one FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' LIMIT 1 [["adjustable_id", 4], ["adjustable_type", "Spree::Order"]]
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/checkout/_summary.html.erb (169.0ms)
Spree::TokenizedPermission Load (0.1ms) SELECT "spree_tokenized_permissions".* FROM "spree_tokenized_permissions" WHERE "spree_tokenized_permissions"."permissable_id" = ? AND "spree_tokenized_permissions"."permissable_type" = ? LIMIT 1 [["permissable_id", 4], ["permissable_type", "Spree::Order"]]
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/checkout/edit.html.erb within spree/layouts/spree_application (382.7ms)
Spree::Store Load (0.2ms) SELECT "spree_stores".* FROM "spree_stores" WHERE (url like '%localhost%') ORDER BY "spree_stores"."id" ASC LIMIT 1
Spree::Store Load (0.1ms) SELECT "spree_stores".* FROM "spree_stores" WHERE "spree_stores"."default" = 't' ORDER BY "spree_stores"."id" ASC LIMIT 1
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_head.html.erb (4.4ms)
Deface: 1 overrides found for 'spree/shared/_nav_bar'
Deface: 'auth_shared_login_bar' matched 1 times with 'li#search-bar'
Deface: [ERROR] The original source for 'auth_shared_login_bar' has changed, this override should be reviewed to ensure it's still valid.
(0.1ms) SELECT MAX("spree_taxons"."updated_at") AS max_id FROM "spree_taxons" WHERE "spree_taxons"."parent_id" IS NULL
Spree::Taxon Load (0.1ms) SELECT "spree_taxons".* FROM "spree_taxons" WHERE "spree_taxons"."parent_id" IS NULL ORDER BY "lft"
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_search.html.erb (1.8ms)
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_nav_bar.html.erb (10.9ms)
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_main_nav_bar.html.erb (0.3ms)
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_header.html.erb (39.7ms)
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_footer.html.erb (0.2ms)
Spree::Tracker Load (0.1ms) SELECT "spree_trackers".* FROM "spree_trackers" WHERE "spree_trackers"."active" = 't' AND "spree_trackers"."environment" = 'development' ORDER BY "spree_trackers"."id" ASC LIMIT 1
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_google_analytics.html.erb (0.7ms)
Completed 200 OK in 1335ms (Views: 164.7ms | ActiveRecord: 1130.1ms)
```

It's extremely slow, but difficult to know why. With Spree instrumentation the culprit (`Spree::Order.set_shipments_cost`) is obvious.

```
Started GET "/checkout/delivery" for 127.0.0.1 at 2014-06-07 18:26:11 -0700
Processing by Spree::CheckoutController#edit as HTML
Parameters: {"state"=>"delivery"}
Spree::Preference Load (0.1ms) SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = 'spree/frontend_configuration/locale' LIMIT 1
Spree::User Load (0.1ms) SELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 ORDER BY "spree_users"."id" ASC LIMIT 1
Spree::Order Load (0.1ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."user_id" = ? AND "spree_orders"."completed_at" IS NULL AND "spree_orders"."created_by_id" = 1 ORDER BY created_at DESC LIMIT 1 [["user_id", 1]]
Spree::Order Load (0.1ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = 4 AND "spree_orders"."currency" = 'USD' LIMIT 1
Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_type" = 'Spree::Order' AND "spree_adjustments"."adjustable_id" IN (4) ORDER BY spree_adjustments.created_at ASC
Spree::Shipment Exists (0.0ms) SELECT 1 AS one FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? LIMIT 1 [["order_id", 4]]
[Spree::Order.set_shipments_cost] Spree::Shipment Load (0.0ms) SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
[Spree::Order.set_shipments_cost] Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] Spree::Adjustment Load (0.0ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
[Spree::Order.set_shipments_cost] SQL (256.9ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:26:11.818301' WHERE "spree_shipments"."id" = 8
[Spree::Order.set_shipments_cost] (0.2ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] SQL (83.1ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:26:12.077771' WHERE "spree_orders"."id" = 4
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] Finished in 84.6ms
[Spree::Order.set_shipments_cost] Finished in 345.8ms
Spree::Payment Load (0.2ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
[Spree::Order.set_shipments_cost] Spree::ShippingRate Load (0.2ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
[Spree::Order.set_shipments_cost] SQL (77.4ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:26:12.169851' WHERE "spree_shipments"."id" = 8
[Spree::Order.set_shipments_cost] (0.2ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] SQL (81.8ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:26:12.250919' WHERE "spree_orders"."id" = 4
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] Finished in 83.4ms
[Spree::Order.set_shipments_cost] Finished in 168.6ms
Spree::Payment Load (0.2ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
[Spree::Order.set_shipments_cost] Spree::ShippingRate Load (0.2ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
[Spree::Order.set_shipments_cost] SQL (80.1ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:26:12.340670' WHERE "spree_shipments"."id" = 8
[Spree::Order.set_shipments_cost] (0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] SQL (78.6ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:26:12.423246' WHERE "spree_orders"."id" = 4
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] Finished in 79.7ms
[Spree::Order.set_shipments_cost] Finished in 166.4ms
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
[Spree::Order.set_shipments_cost] Spree::ShippingRate Load (0.2ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
[Spree::Order.set_shipments_cost] SQL (83.4ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:26:12.507324' WHERE "spree_shipments"."id" = 8
[Spree::Order.set_shipments_cost] (0.1ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] SQL (77.7ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:26:12.592498' WHERE "spree_orders"."id" = 4
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] Finished in 78.6ms
[Spree::Order.set_shipments_cost] Finished in 166.6ms
Spree::Payment Load (0.1ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
(0.1ms) SELECT COUNT(*) FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? [["order_id", 4]]
Spree::LineItem Load (0.1ms) SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? ORDER BY created_at ASC [["order_id", 4]]
Spree::Variant Load (0.1ms) SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? LIMIT 1 [["id", 2]]
(0.2ms) SELECT SUM("spree_stock_items"."count_on_hand") AS sum_id FROM "spree_stock_items" INNER JOIN "spree_stock_locations" ON "spree_stock_locations"."id" = "spree_stock_items"."stock_location_id" WHERE "spree_stock_items"."deleted_at" IS NULL AND "spree_stock_items"."variant_id" = 2 AND "spree_stock_locations"."active" = 't'
[Spree::Order.set_shipments_cost] Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
[Spree::Order.set_shipments_cost] SQL (79.3ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:26:12.678253' WHERE "spree_shipments"."id" = 8
[Spree::Order.set_shipments_cost] (0.2ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] SQL (84.4ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:26:12.760294' WHERE "spree_orders"."id" = 4
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] Finished in 86.0ms
[Spree::Order.set_shipments_cost] Finished in 169.9ms
Spree::Payment Load (0.2ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::User Load (0.2ms) SELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = ? LIMIT 1 [["id", 1]]
Spree::StockLocation Load (0.2ms) SELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? LIMIT 1 [["id", 1]]
Spree::InventoryUnit Load (0.2ms) SELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ? [["shipment_id", 8]]
Spree::LineItem Load (0.4ms) SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."id" IN (4)
Spree::Variant Load (0.2ms) SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? LIMIT 1 [["id", 2]]
(0.2ms) SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = ? AND "spree_roles"."name" = 'admin' [["user_id", 1]]
Rendered /home/jhawthorn/src/spree/core/app/views/spree/shared/_error_messages.html.erb (0.2ms)
[Spree::Order.set_shipments_cost] Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
[Spree::Order.set_shipments_cost] SQL (77.3ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:26:12.941781' WHERE "spree_shipments"."id" = 8
[Spree::Order.set_shipments_cost] (0.2ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] SQL (81.0ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:26:13.022043' WHERE "spree_orders"."id" = 4
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] Finished in 82.5ms
[Spree::Order.set_shipments_cost] Finished in 165.0ms
Spree::Payment Load (0.2ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::InventoryUnit Load (0.1ms) SELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ? [["shipment_id", 8]]
Spree::LineItem Load (0.1ms) SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."id" = ? LIMIT 1 [["id", 4]]
Spree::Variant Load (0.1ms) SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? LIMIT 1 [["id", 2]]
Spree::Image Exists (0.2ms) SELECT 1 AS one FROM "spree_assets" WHERE "spree_assets"."type" IN ('Spree::Image') AND "spree_assets"."viewable_id" = ? AND "spree_assets"."viewable_type" = ? LIMIT 1 [["viewable_id", 2], ["viewable_type", "Spree::Variant"]]
Spree::Image Load (0.2ms) SELECT "spree_assets".* FROM "spree_assets" WHERE "spree_assets"."type" IN ('Spree::Image') AND "spree_assets"."viewable_id" = ? AND "spree_assets"."viewable_type" = ? ORDER BY "spree_assets"."position" ASC LIMIT 1 [["viewable_id", 2], ["viewable_type", "Spree::Variant"]]
Spree::Product Load (0.1ms) SELECT "spree_products".* FROM "spree_products" WHERE "spree_products"."id" = ? LIMIT 1 [["id", 2]]
Spree::Price Load (0.1ms) SELECT "spree_prices".* FROM "spree_prices" WHERE "spree_prices"."deleted_at" IS NULL AND "spree_prices"."variant_id" = ? [["variant_id", 2]]
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? ORDER BY cost ASC [["shipment_id", 8]]
Spree::ShippingRate Load (0.1ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::ShippingMethod Load (0.1ms) SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."id" = ? LIMIT 1 [["id", 1]]
Spree::Shipment Load (0.1ms) SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? LIMIT 1 [["id", 8]]
Spree::Order Load (0.1ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? LIMIT 1 [["id", 4]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::ShippingMethod Load (0.1ms) SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."id" = ? LIMIT 1 [["id", 2]]
CACHE (0.0ms) SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? LIMIT 1 [["id", 8]]
CACHE (0.0ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? LIMIT 1 [["id", 4]]
CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
Spree::ShippingMethod Load (0.1ms) SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."id" = ? LIMIT 1 [["id", 3]]
CACHE (0.0ms) SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? LIMIT 1 [["id", 8]]
CACHE (0.0ms) SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? LIMIT 1 [["id", 4]]
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/checkout/_delivery.html.erb (31.9ms)
Spree::Adjustment Exists (0.1ms) SELECT 1 AS one FROM "spree_adjustments" INNER JOIN "spree_line_items" ON "spree_adjustments"."adjustable_id" = "spree_line_items"."id" WHERE "spree_adjustments"."adjustable_type" = ? AND "spree_line_items"."order_id" = ? LIMIT 1 [["adjustable_type", "Spree::LineItem"], ["order_id", 4]]
Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" INNER JOIN "spree_line_items" ON "spree_adjustments"."adjustable_id" = "spree_line_items"."id" WHERE "spree_adjustments"."adjustable_type" = ? AND "spree_line_items"."order_id" = ? AND "spree_adjustments"."source_type" = 'Spree::PromotionAction' AND "spree_adjustments"."eligible" = 't' ORDER BY created_at ASC [["adjustable_type", "Spree::LineItem"], ["order_id", 4]]
Spree::Adjustment Load (0.2ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE (order_id = 4 OR (adjustable_id = 4 AND adjustable_type = 'Spree::Order')) AND "spree_adjustments"."source_type" = 'Spree::TaxRate' AND "spree_adjustments"."eligible" = 't'
[Spree::Order.set_shipments_cost] CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] CACHE (0.0ms) SELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY cost ASC LIMIT 1 [["shipment_id", 8]]
[Spree::Order.set_shipments_cost] Spree::Adjustment Load (0.1ms) SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."included" = 'f' [["adjustable_id", 8], ["adjustable_type", "Spree::Shipment"]]
[Spree::Order.set_shipments_cost] SQL (75.2ms) UPDATE "spree_shipments" SET "cost" = 5.0, "adjustment_total" = 0, "updated_at" = '2014-06-08 01:26:13.198137' WHERE "spree_shipments"."id" = 8
[Spree::Order.set_shipments_cost] (0.2ms) SELECT SUM("spree_shipments"."cost") AS sum_id FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ? [["order_id", 4]]
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] SQL (77.3ms) UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 22.99, "item_count" = 1, "adjustment_total" = 1.15, "included_tax_total" = 0.0, "additional_tax_total" = 1.15, "payment_total" = 0.0, "shipment_total" = 5.0, "total" = 29.14, "updated_at" = '2014-06-08 01:26:13.276234' WHERE "spree_orders"."id" = 4
[Spree::Order.set_shipments_cost] [Spree::OrderUpdater.persist_totals] Finished in 78.9ms
[Spree::Order.set_shipments_cost] Finished in 158.9ms
Spree::Payment Load (0.2ms) SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND ("spree_payments"."state" NOT IN ('failed', 'invalid')) [["order_id", 4]]
Spree::Adjustment Exists (0.2ms) SELECT 1 AS one FROM "spree_adjustments" INNER JOIN "spree_shipments" ON "spree_adjustments"."adjustable_id" = "spree_shipments"."id" WHERE "spree_adjustments"."adjustable_type" = ? AND "spree_shipments"."order_id" = ? LIMIT 1 [["adjustable_type", "Spree::Shipment"], ["order_id", 4]]
Spree::Adjustment Exists (0.2ms) SELECT 1 AS one FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' LIMIT 1 [["adjustable_id", 4], ["adjustable_type", "Spree::Order"]]
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/checkout/_summary.html.erb (177.2ms)
Spree::TokenizedPermission Load (0.1ms) SELECT "spree_tokenized_permissions".* FROM "spree_tokenized_permissions" WHERE "spree_tokenized_permissions"."permissable_id" = ? AND "spree_tokenized_permissions"."permissable_type" = ? LIMIT 1 [["permissable_id", 4], ["permissable_type", "Spree::Order"]]
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/checkout/edit.html.erb within spree/layouts/spree_application (457.1ms)
Spree::Store Load (0.3ms) SELECT "spree_stores".* FROM "spree_stores" WHERE (url like '%localhost%') ORDER BY "spree_stores"."id" ASC LIMIT 1
Spree::Store Load (0.2ms) SELECT "spree_stores".* FROM "spree_stores" WHERE "spree_stores"."default" = 't' ORDER BY "spree_stores"."id" ASC LIMIT 1
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_head.html.erb (10.2ms)
Deface: 1 overrides found for 'spree/shared/_nav_bar'
Deface: 'auth_shared_login_bar' matched 1 times with 'li#search-bar'
Deface: [ERROR] The original source for 'auth_shared_login_bar' has changed, this override should be reviewed to ensure it's still valid.
(0.2ms) SELECT MAX("spree_taxons"."updated_at") AS max_id FROM "spree_taxons" WHERE "spree_taxons"."parent_id" IS NULL
Spree::Taxon Load (0.2ms) SELECT "spree_taxons".* FROM "spree_taxons" WHERE "spree_taxons"."parent_id" IS NULL ORDER BY "lft"
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_search.html.erb (2.5ms)
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_nav_bar.html.erb (17.8ms)
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_main_nav_bar.html.erb (0.4ms)
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_header.html.erb (66.8ms)
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_footer.html.erb (0.2ms)
Spree::Tracker Load (0.1ms) SELECT "spree_trackers".* FROM "spree_trackers" WHERE "spree_trackers"."active" = 't' AND "spree_trackers"."environment" = 'development' ORDER BY "spree_trackers"."id" ASC LIMIT 1
Rendered /home/jhawthorn/src/spree/frontend/app/views/spree/shared/_google_analytics.html.erb (0.8ms)
Completed 200 OK in 1705ms (Views: 335.7ms | ActiveRecord: 1303.4ms)
```

I'm interested in thoughts and opinitons on this. It could be implemented outside of spree core, but I think it may be worth including, as I think it could be helpful to all developers.