Strange output "SELECT 1"

Question

When I use rack-mini-profiler with my application (running ruby 1.9.3 p194, rails 3.2.8 and pg 0.14.0), I get very strange analysis outputs. Typically It will look something like this:

/da/brugte-biler/Fiat/Multipla autouncle.dev on Mon, 27 Aug 2012 13:30:50 GMT
                                             duration (ms) from start (ms) query time (ms)
GET http://autouncle.dev:80/da/brugte-biler/F...   19.2 +0.0   3 sql   0.5
  Executing action: search                         83.4 +16.0  48 sql  9.4
   Rendering: cars_search/table_listing            819.2  +99.0  356 sql   71.2
    Rendering: cars/_reliability_report            12.5 +601.0
    Rendering: cars_search/_sidebar                1093.7 +616.0   281 sql   356.7
    Rendering: cars/_listing_table                 1612.6 +1731.0  123 sql   549.5
    Rendering: kaminari/_paginator                 27.2 +3632.0
   Rendering: layouts/search_results               31.3 +3671.0
    Rendering: layouts/_shared_head_content        223.4  +3673.0
    Rendering: partials/_top_links                 2.6  +3907.0
    Rendering: partials/_search_form               165.1  +3912.0
    Rendering: partials/_footer_links              5.2  +4086.0
    Rendering: layouts/_shared_footer_content      8.7  +4099.0
share show trivial show time with children   24.0 % in sql

The strange thing here is, that is says, that there is being called 356 sql statements. But of cause there isn't. If I click them, to see what was called, the I see a lot of statements like this:

8.70 ms 
Executing action: search — 7.70 ms
Executing action: search
T+23.7 ms
Reader
0.3 ms
app/models/car_search.rb:97:in `relation'
app/controllers/cars_search_controller.rb:102:in `pagination_relation'
app/controllers/cars_search_controller.rb:37:in `search'
app/controllers/controller_concerns/country_requesting.rb:66:in `select_database_shard'
lib/www_middleware.rb:11:in `call'
SELECT 1   
Executing action: search
T+25.8 ms
Reader
0.2 ms
app/models/car_search.rb:97:in `relation'
app/controllers/cars_search_controller.rb:102:in `pagination_relation'
app/controllers/cars_search_controller.rb:37:in `search'
app/controllers/controller_concerns/country_requesting.rb:66:in `select_database_shard'
lib/www_middleware.rb:11:in `call'
SELECT 1   
Executing action: search
T+26.8 ms
Reader
0.2 ms
app/models/car_search.rb:97:in `relation'
app/controllers/cars_search_controller.rb:102:in `pagination_relation'
app/controllers/cars_search_controller.rb:37:in `search'
app/controllers/controller_concerns/country_requesting.rb:66:in `select_database_shard'
lib/www_middleware.rb:11:in `call'
SELECT 1

And it just goes on and on for 356 times.

I'm very puzzled what to make of this. Any clue to what this might be all about?

UPDATE:

The code in car_search.rb is a pretty heavy method, that builds up the relevant query. Basically what it does is something similar to this:

def relation
  cars = Car.onsale # a scope that says .where(:sales_state => 'onsale')

  cars = cars.with_brand(brand) if brand.present? # a scope that says .where(:brand => 'some_brand')

  cars = cars.with_model_name(model_name) if model_name.present? # a scope that says .where(:model_name => 'some_model_name')

  return cars
end

what is the code in www_middleware.rb? looks like you are missing some eager loading to me — Sam Saffron, Aug 29 '12 at 12:22
It's a middleware, that we added to test/benchmark our TTFB, so that we could request a page, that newer hits the app-code directly. It should not apply anything def initialize(app) @app = app end def call(env) request = Rack::Request.new(env) if request.path_info.match(/ttfb_test/) return [200, {"Content-Type" => "text/html"}, self] else @app.call(env) end end def each(&block) block.call("Hello Denmark") end — Niels Kristian, Aug 29 '12 at 15:01
You can see a detailed explanation to why we made the middleware here: http://stackoverflow.com/questions/12181133/strange-ttfb-time-to-first-byte-issue if interested... — Niels Kristian, Aug 29 '12 at 15:14
can you add context around: app/models/car_search.rb:97:in `relation' app/controllers/cars_search_controller.rb:102 (10 lines around each) — Sam Saffron, Aug 29 '12 at 21:08
I'm also getting this. Did you ever find a reason or solution? — toxaq, Jul 01 '13 at 08:30

Strange output "SELECT 1"

0 Answers0