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.