MrWater
Reputation: 1797
Why does a request to a link is slower the second time it runs in production in rails?
I have a page, using rails and some javascript, in production mode, which shows report data, which has some filters embedded in some links within that report.
The first time I hit one of those filter links, which use ajax calls, I have a response that takes 157 ms. The second time I hit the same link, I have a response that takes more than 30 s. The third time I hit the link after a while, and it takes again 147ms. If I click it right afterwards, it will go up again...
I have considered tracing the http request (using firefox about:networking); putting logger.debug messages along the controller actions.
The networking log I cannot interpret it very easily... The logger messages seems to indicate that everything is fine (within the smallest time registered)...
As this issue only happens on production (and quality, running as production) environment and not in localhost, I am inclined to think it has either something to do with the fact I am using nginx or something about the assets, which are precompiled in prod. environment...
How can I know where the issue is, as it definitely doesn't seem to be in the controller ? (I have thought of using debugging tools, and before going deeper with those, wondered if there could be some easier way...)
Server Info
| => Booting Puma
app_1 | => Rails 5.0.6 application starting in production on http://0.0.0.0:3000
app_1 | => Run `rails server -h` for more startup options
app_1 | /usr/src/app/app/controllers/environmental_impacts_controller.backup.rb:522: warning: key :name is duplicated and overwritten on line 523
app_1 | Creating scope :approved. Overwriting existing method ProcessInstance.approved.
app_1 | Puma starting in single mode...
app_1 | * Version 3.11.2 (ruby 2.3.3-p222), codename: Love Song
app_1 | * Min threads: 5, max threads: 5
app_1 | * Environment: production
app_1 | * Listening on tcp://0.0.0.0:3000
Rails app logs
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] HELLO search_report 2018-03-05 14:37:53 +0000
[ ... ]
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] SEARCH REPORT About to render js page 2018-03-05 14:37:53 +0000
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] Rendering environmental_impacts/search_report.js.erb
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] Rendered environmental_impacts/_totals_per_cost_type.html.erb (0.5ms)
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] Rendered environmental_impacts/_totals_per_cost_type.html.erb (0.5ms)
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] Rendered environmental_impacts/_totals_per_cost_type.html.erb (0.7ms)
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] Rendered environmental_impacts/_totals_per_cost_type.html.erb (0.5ms)
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] Rendered environmental_impacts/_tabelas.html.erb (4.3ms)
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] Rendered environmental_impacts/search_report.js.erb (5.3ms)
app_1 | [6ee95907-9a79-427d-a4f6-1af132fc2c43] Completed 200 OK in 128ms (Views: 5.9ms | ActiveRecord: 33.4ms)
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Started POST "/environmental_impacts/search_report?filtered_by=Corte+teste+1+2%3Cbr%3E&process_instance_id=126" for 82.154.171.205 at 2018-03-05 14:38:51 +0000
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Processing by EnvironmentalImpactsController#search_report as JS
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Parameters: {"filtered_by"=>"Corte teste 1 2<br>", "process_instance_id"=>"126"}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2 [["id", 1], ["LIMIT", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.1ms) SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'association_admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)) OR ((roles.name = 'company_admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)) OR ((roles.name = 'support') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL))) [["user_id", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Company Load (0.5ms) SELECT "companies".* FROM "companies" WHERE "companies"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] CACHE (0.0ms) SELECT "companies".* FROM "companies" WHERE "companies"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Installation Load (0.6ms) SELECT "installations".* FROM "installations" WHERE "installations"."company_id" = $1 ORDER BY "installations"."id" ASC LIMIT $2 [["company_id", 1], ["LIMIT", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Installation Load (0.2ms) SELECT "installations".* FROM "installations" WHERE "installations"."id" = $1 LIMIT $2 [["id", 15], ["LIMIT", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] CACHE (0.0ms) SELECT "companies".* FROM "companies" WHERE "companies"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (0.7ms) SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'association_admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)) OR ((roles.name = 'company_admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)) OR ((roles.name = 'support') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)) OR ((roles.name = 'environmental_analyst') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL))) [["user_id", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.4ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, (DATE_TRUNC('month', (startdate::timestamptz - INTERVAL '0 second') AT TIME ZONE 'Etc/UTC') + INTERVAL '0 second') AT TIME ZONE 'Etc/UTC' AS date_trunc_month_startdate_timestamptz_interval_0_second_at_tim FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" INNER JOIN "process_instances" ON "process_instances"."id" = "process_instance_maps"."process_instance_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (startdate IS NOT NULL) GROUP BY (DATE_TRUNC('month', (startdate::timestamptz - INTERVAL '0 second') AT TIME ZONE 'Etc/UTC') + INTERVAL '0 second') AT TIME ZONE 'Etc/UTC'
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: 2008-02-01, End Date: 2018-03-05, filters: , cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: nil
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: nil
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting Unit cost per month. Output: #<EnvironmentalImpact::ActiveRecord_Relation:0x000000085395a0>
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.4ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, (DATE_TRUNC('month', (startdate::timestamptz - INTERVAL '0 second') AT TIME ZONE 'Etc/UTC') + INTERVAL '0 second') AT TIME ZONE 'Etc/UTC' AS date_trunc_month_startdate_timestamptz_interval_0_second_at_tim, pollution_origins.name AS pollution_origins_name FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" INNER JOIN "pollution_origins" ON "pollution_origins"."id" = "process_instance_maps"."pollution_origin_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (startdate >= '2008-02-01' and startdate <= '2018-03-05') AND (startdate IS NOT NULL) GROUP BY (DATE_TRUNC('month', (startdate::timestamptz - INTERVAL '0 second') AT TIME ZONE 'Etc/UTC') + INTERVAL '0 second') AT TIME ZONE 'Etc/UTC', pollution_origins.name
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] ProcessInstanceMap Load (2.5ms) SELECT
app_1 | process_instance_maps.id,
app_1 | process_instance_maps.process_instance_id,
app_1 | process_instance_maps.activity_id,
app_1 | process_instance_maps.pollution_origin_id,
app_1 | process_instance_maps.sub_pollution_origin_id,
app_1 | process_instances.tag as process_instance_name,
app_1 | process_instances.process_type_id as process_type,
app_1 | activities.name as activity_name,
app_1 | pollution_origins.name as pollution_origin_name,
app_1 | sub_pollution_origins.name as sub_pollution_origin_name,
app_1 | environmental_impacts.total_cost,
app_1 | environmental_impacts.startdate as startdate FROM "process_instance_maps" INNER JOIN "process_instances" ON "process_instances"."id" = "process_instance_maps"."process_instance_id" INNER JOIN "activities" ON "activities"."id" = "process_instance_maps"."activity_id" INNER JOIN "pollution_origins" ON "pollution_origins"."id" = "process_instance_maps"."pollution_origin_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" INNER JOIN "environmental_impacts" ON "environmental_impacts"."process_instance_map_id" = "process_instance_maps"."id" WHERE "process_instance_maps"."installation_id" = $1 AND ("environmental_impacts"."startdate" IS NOT NULL) ORDER BY environmental_impacts.startdate [["installation_id", 15]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] ProcessType Load (0.8ms) SELECT "process_types".* FROM "process_types" ORDER BY "process_types"."id" ASC
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Scoped order and limit are ignored, it's forced to be batch order and batch size.
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] ProcessInstanceMap Load (4.3ms) SELECT
app_1 | process_instance_maps.id,
app_1 | process_instance_maps.process_instance_id,
app_1 | process_instance_maps.activity_id,
app_1 | process_instance_maps.pollution_origin_id,
app_1 | process_instance_maps.sub_pollution_origin_id,
app_1 | process_instances.tag as process_instance_name,
app_1 | process_instances.process_type_id as process_type,
app_1 | activities.name as activity_name,
app_1 | pollution_origins.name as pollution_origin_name,
app_1 | sub_pollution_origins.name as sub_pollution_origin_name,
app_1 | environmental_impacts.total_cost,
app_1 | environmental_impacts.startdate as startdate FROM "process_instance_maps" INNER JOIN "process_instances" ON "process_instances"."id" = "process_instance_maps"."process_instance_id" INNER JOIN "activities" ON "activities"."id" = "process_instance_maps"."activity_id" INNER JOIN "pollution_origins" ON "pollution_origins"."id" = "process_instance_maps"."pollution_origin_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" INNER JOIN "environmental_impacts" ON "environmental_impacts"."process_instance_map_id" = "process_instance_maps"."id" WHERE "process_instance_maps"."installation_id" = $1 AND ("environmental_impacts"."startdate" IS NOT NULL) ORDER BY "process_instance_maps"."id" ASC LIMIT $2 [["installation_id", 15], ["LIMIT", 1000]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] HELLO search_report 2018-03-05 14:38:51 +0000
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] SEARCH REPORT Before reset Filters Start Date: nil
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] HELLOOOOO set_filters pid: 126
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Debug - set_filters : <ActionController::Parameters {"filtered_by"=>"Corte teste 1 2<br>", "process_instance_id"=>"126", "controller"=>"environmental_impacts", "action"=>"search_report"} permitted: false>
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Installation Load (0.5ms) SELECT "installations".* FROM "installations" ORDER BY "installations"."name" ASC
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (0.7ms) SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'association_admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)) OR ((roles.name = 'support') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL))) [["user_id", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] USER is from Company - session[:filters]: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] SEARCH REPORT Filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] SEARCH REPORT Filters Start Date: Sun, 05 Mar 2017
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] SEARCH REPORT I'm in DASHBOARD 2018-03-05 14:38:51 +0000
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Start Date 2017-03-05, Companyid:
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] GET TOTAL COST start_date : 2017-03-05
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: 2017-03-05, End Date: 2018-03-05, filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.2ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, (DATE_TRUNC('month', (startdate::timestamptz - INTERVAL '0 second') AT TIME ZONE 'Etc/UTC') + INTERVAL '0 second') AT TIME ZONE 'Etc/UTC' AS date_trunc_month_startdate_timestamptz_interval_0_second_at_tim FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (startdate >= '2017-03-05' and startdate <= '2018-03-05') AND (process_instance_id = '126') AND (startdate IS NOT NULL) GROUP BY (DATE_TRUNC('month', (startdate::timestamptz - INTERVAL '0 second') AT TIME ZONE 'Etc/UTC') + INTERVAL '0 second') AT TIME ZONE 'Etc/UTC'
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: 2017-03-05, End Date: 2018-03-05, filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.5ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, (DATE_TRUNC('month', (startdate::timestamptz - INTERVAL '0 second') AT TIME ZONE 'Etc/UTC') + INTERVAL '0 second') AT TIME ZONE 'Etc/UTC' AS date_trunc_month_startdate_timestamptz_interval_0_second_at_tim, sub_pollution_origins.name AS sub_pollution_origins_name FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" INNER JOIN "process_instances" ON "process_instances"."id" = "process_instance_maps"."process_instance_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (startdate >= '2017-03-05' and startdate <= '2018-03-05') AND (process_instance_id = '126') AND (startdate IS NOT NULL) GROUP BY (DATE_TRUNC('month', (startdate::timestamptz - INTERVAL '0 second') AT TIME ZONE 'Etc/UTC') + INTERVAL '0 second') AT TIME ZONE 'Etc/UTC', sub_pollution_origins.name
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: 2017-03-05, End Date: 2018-03-05, filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.8ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, sub_pollution_origins.name AS sub_pollution_origins_name FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" INNER JOIN "process_instances" ON "process_instances"."id" = "process_instance_maps"."process_instance_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (startdate >= '2017-03-05' and startdate <= '2018-03-05') AND (process_instance_id = '126') GROUP BY sub_pollution_origins.name
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] ###################### Loading Costs - Environmental Impacts 2018-03-05 14:38:51 +0000
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] HELLOOOOO set_filters pid: 126
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Debug - set_filters : <ActionController::Parameters {"filtered_by"=>"Corte teste 1 2<br>", "process_instance_id"=>"126", "controller"=>"environmental_impacts", "action"=>"search_report"} permitted: false>
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] CACHE (0.0ms) SELECT "installations".* FROM "installations" ORDER BY "installations"."name" ASC
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] CACHE (0.0ms) SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'association_admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)) OR ((roles.name = 'support') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL))) [["user_id", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] USER is from Company - session[:filters]: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] CACHE (0.0ms) SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'association_admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)) OR ((roles.name = 'support') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL))) [["user_id", 1]]
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: , End Date: , filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.2ms) SELECT SUM("environmental_impacts"."total_cost") FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (process_instance_id = '126')
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: , End Date: , filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.0ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, sub_pollution_origins.id AS sub_pollution_origins_id, sub_pollution_origins.name AS sub_pollution_origins_name FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (process_instance_id = '126') GROUP BY sub_pollution_origins.id, sub_pollution_origins.name
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: , End Date: , filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.2ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, pollution_origins.id AS pollution_origins_id, pollution_origins.name AS pollution_origins_name FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "pollution_origins" ON "pollution_origins"."id" = "process_instance_maps"."pollution_origin_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (process_instance_id = '126') GROUP BY pollution_origins.id, pollution_origins.name
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: , End Date: , filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.0ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, sub_activities.id AS sub_activities_id, sub_activities.name AS sub_activities_name FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "sub_activities" ON "sub_activities"."id" = "process_instance_maps"."sub_activity_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (process_instance_id = '126') GROUP BY sub_activities.id, sub_activities.name
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: , End Date: , filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.1ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, activities.id AS activities_id, activities.name AS activities_name FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "activities" ON "activities"."id" = "process_instance_maps"."activity_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (process_instance_id = '126') GROUP BY activities.id, activities.name
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Getting cost instance filters. Start_date: , End Date: , filters: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}, cid: 1
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 0: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] COST INSTANCE Filters 1: {:pid=>"126", :aid=>nil, :said=>nil, :poid=>nil, :spoid=>nil}
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] (1.0ms) SELECT SUM("environmental_impacts"."total_cost") AS sum_total_cost, process_instances.id AS process_instances_id, process_instances.tag AS process_instances_tag FROM "environmental_impacts" INNER JOIN "process_instance_maps" ON "process_instance_maps"."id" = "environmental_impacts"."process_instance_map_id" INNER JOIN "process_instances" ON "process_instances"."id" = "process_instance_maps"."process_instance_id" INNER JOIN "sub_pollution_origins" ON "sub_pollution_origins"."id" = "process_instance_maps"."sub_pollution_origin_id" WHERE (process_instance_maps.company_id = 1) AND (process_instance_maps.installation_id = 15) AND (process_instance_id = '126') GROUP BY process_instances.id, process_instances.tag
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] SEARCH REPORT About to render js page 2018-03-05 14:38:51 +0000
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Rendering environmental_impacts/search_report.js.erb
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Rendered environmental_impacts/_totals_per_cost_type.html.erb (0.8ms)
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Rendered environmental_impacts/_totals_per_cost_type.html.erb (0.4ms)
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Rendered environmental_impacts/_totals_per_cost_type.html.erb (0.4ms)
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Rendered environmental_impacts/_totals_per_cost_type.html.erb (0.4ms)
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Rendered environmental_impacts/_tabelas.html.erb (3.2ms)
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Rendered environmental_impacts/search_report.js.erb (3.8ms)
app_1 | [45b78362-7cd9-40c9-88b7-1d6b15350183] Completed 200 OK in 91ms (Views: 4.5ms | ActiveRecord: 26.4ms)
Some pictures from the browser status:
An expected state:
The state right after clicking for a second time (staying like this for 50 s for example):
web logs
web_1 | 172.19.0.3 - - [05/Mar/2018:15:17:47 +0000] "POST https://aaa.b/xxx HTTP/1.1" 200 3357 "/xxx/yyy" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"
web_1 | 172.19.0.3 - - [05/Mar/2018:15:18:46 +0000] "POST /xxx/yyy?filtered_by=aaa&pid=126 HTTP/1.1" 200 2355 "/xxx/yyy" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"
web_1 | 172.19.0.3 - - [05/Mar/2018:15:19:45 +0000] "POST /xxx/yyy?***" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"
I don't know if it is relevant, but I am using docker and docker-compose on this...
using nginx for collecting the web requests
my nginx.conf
user www-data;
events {
worker_connections 768;
}
http {
upstream app {
server app:3000;
}
include /etc/nginx/mime.types;
default_type application/octet-stream;
gzip on;
gzip_disable "msie6";
server {
listen 80;
try_files $uri/index.html $uri @app;
location / {
proxy_pass http://app;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header Host $http_host;
proxy_redirect off;
}
client_max_body_size 10M;
keepalive_timeout 10;
}
}
Upvotes: 0
Views: 66
Answers (1)
Pierre Ozoux
Reputation: 830
It was a bug in HAProxy.
Updating HAProxy to latest fixed the issue.
Upvotes: 1
Related Questions
- Rails - Completed time for a request significantly higher than View and DB times
- Slow processing when render helper link_to
- Rails taking longer than expected to load page
- Rails Link Generation/Caching Issue
- ROR very slow in development while production works fine
- Rails 4, every time I click some links, why resources load many times?
- Rails application access is very slow
- What's the extra time for when loading web page in rails?
- Where is the rest of the response time coming from?
- rails 3 routing performance issue