[RFC] 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.

This could also be used to improve reporting to services like [skylight.io](http://skylight.io) or newrelic.

Consider as an example `GET /checkout/delivery` on a spree sandbox

```
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 quite slow (1335ms), but difficult to know why or where spree is spending it's time. With this change, the culprit (`Spree::Order.set_shipments_cost`) is more clear.

```
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 opinions on this, whether it's useful, and what could make it better. 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.