From 12872d03beff6d0417ad07367c33a28268b53cb0 Mon Sep 17 00:00:00 2001 From: Sam Date: Fri, 19 Jan 2018 08:26:18 +1100 Subject: [PATCH] PERF: run post timings in background This means that if a very large amount of registered users hit a single topic we will handle it gracefully, even if db gets slow. --- .gitignore | 5 +++- Gemfile.lock | 4 ++-- app/controllers/topics_controller.rb | 24 ++++++++++++------- config/application.rb | 3 +++ lib/hijack.rb | 35 ++++++++++++++++------------ lib/method_profiler.rb | 4 ++++ lib/middleware/request_tracker.rb | 10 +++++--- spec/components/hijack_spec.rb | 15 ++++++++---- 8 files changed, 67 insertions(+), 33 deletions(-) diff --git a/.gitignore b/.gitignore index 8a1f8652b9a..fbaaa543869 100644 --- a/.gitignore +++ b/.gitignore @@ -117,9 +117,12 @@ bundler_stubs/* vendor/bundle/* *.db -#ignore jetbrains ide file +# ignore jetbrains ide file *.iml +# vim swap +*.swn + # ignore nodejs files /node_modules /package-lock.json diff --git a/Gemfile.lock b/Gemfile.lock index c6320f2da37..a035893211f 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -144,7 +144,7 @@ GEM railties (>= 4.2.0) thor (>= 0.14, < 2.0) jwt (1.5.6) - kgio (2.11.0) + kgio (2.11.1) libv8 (6.3.292.48.1) listen (3.1.5) rb-fsevent (~> 0.9, >= 0.9.4) @@ -389,7 +389,7 @@ GEM unf_ext unf_ext (0.0.7.4) unicode-display_width (1.3.0) - unicorn (5.3.1) + unicorn (5.4.0) kgio (~> 2.6) raindrops (~> 0.7) uniform_notifier (1.10.0) diff --git a/app/controllers/topics_controller.rb b/app/controllers/topics_controller.rb index fa241cb5435..9f5113f340e 100644 --- a/app/controllers/topics_controller.rb +++ b/app/controllers/topics_controller.rb @@ -585,14 +585,22 @@ class TopicsController < ApplicationController end def timings - PostTiming.process_timings( - current_user, - topic_params[:topic_id].to_i, - topic_params[:topic_time].to_i, - (topic_params[:timings].to_h || {}).map { |post_number, t| [post_number.to_i, t.to_i] }, - mobile: view_context.mobile_view? - ) - render body: nil + allowed_params = topic_params + + topic_id = allowed_params[:topic_id].to_i + topic_time = allowed_params[:topic_time].to_i + timings = allowed_params[:timings].to_h || {} + + hijack do + PostTiming.process_timings( + current_user, + topic_id, + topic_time, + timings.map { |post_number, t| [post_number.to_i, t.to_i] }, + mobile: view_context.mobile_view? + ) + render body: nil + end end def feed diff --git a/config/application.rb b/config/application.rb index 20cbc7451ab..eb2b23be4d8 100644 --- a/config/application.rb +++ b/config/application.rb @@ -155,6 +155,9 @@ module Discourse # for some reason still seeing it in Rails 4 config.middleware.delete Rack::Lock + # wrong place in middleware stack AND request tracker handles it + config.middleware.delete Rack::Runtime + # ETags are pointless, we are dynamically compressing # so nginx strips etags, may revisit when mainline nginx # supports etags (post 1.7) diff --git a/lib/hijack.rb b/lib/hijack.rb index 026077dbb61..74efe769789 100644 --- a/lib/hijack.rb +++ b/lib/hijack.rb @@ -1,5 +1,7 @@ # frozen_string_literal: true +require_dependency 'method_profiler' + # This module allows us to hijack a request and send it to the client in the deferred job queue # For cases where we are making remote calls like onebox or proxying files and so on this helps # free up a unicorn worker while the remote IO is happening @@ -13,20 +15,19 @@ module Hijack request.env['discourse.request_tracker.skip'] = true request_tracker = request.env['discourse.request_tracker'] - # unicorn will re-cycle env, this ensures we keep the original copy - env_copy = request.env.dup - request_copy = ActionDispatch::Request.new(env_copy) + # in the past unicorn would recycle env, this is not longer the case + env = request.env + request_copy = ActionDispatch::Request.new(env) - transfer_timings = MethodProfiler.transfer if defined? MethodProfiler + transfer_timings = MethodProfiler.transfer io = hijack.call Scheduler::Defer.later("hijack #{params["controller"]} #{params["action"]}") do - MethodProfiler.start(transfer_timings) if defined? MethodProfiler - + MethodProfiler.start(transfer_timings) begin - Thread.current[Logster::Logger::LOGSTER_ENV] = env_copy + Thread.current[Logster::Logger::LOGSTER_ENV] = env # do this first to confirm we have a working connection # before doing any work io.write "HTTP/1.1 " @@ -43,7 +44,7 @@ module Hijack instance.instance_eval(&blk) rescue => e # TODO we need to reuse our exception handling in ApplicationController - Discourse.warn_exception(e, message: "Failed to process hijacked response correctly", env: env_copy) + Discourse.warn_exception(e, message: "Failed to process hijacked response correctly", env: env) end unless instance.response_body || response.committed? @@ -56,36 +57,40 @@ module Hijack headers = response.headers # add cors if needed - if cors_origins = env_copy[Discourse::Cors::ORIGINS_ENV] - Discourse::Cors.apply_headers(cors_origins, env_copy, headers) + if cors_origins = env[Discourse::Cors::ORIGINS_ENV] + Discourse::Cors.apply_headers(cors_origins, env, headers) end headers['Content-Length'] = body.bytesize headers['Content-Type'] = response.content_type || "text/plain" headers['Connection'] = "close" - status_string = Rack::Utils::HTTP_STATUS_CODES[instance.status.to_i] || "Unknown" - io.write "#{instance.status} #{status_string}\r\n" + status_string = Rack::Utils::HTTP_STATUS_CODES[response.status.to_i] || "Unknown" + io.write "#{response.status} #{status_string}\r\n" headers.each do |name, val| io.write "#{name}: #{val}\r\n" end + timings = MethodProfiler.stop + if timings && duration = timings[:total_duration] + io.write "X-Runtime: #{"%0.6f" % duration}\r\n" + end + io.write "\r\n" io.write body rescue Errno::EPIPE, IOError # happens if client terminated before we responded, ignore io = nil ensure - + MethodProfiler.clear Thread.current[Logster::Logger::LOGSTER_ENV] = nil io.close if io rescue nil if request_tracker status = instance.status rescue 500 - timings = MethodProfiler.stop if defined? MethodProfiler - request_tracker.log_request_info(env_copy, [status, headers || {}, []], timings) + request_tracker.log_request_info(env, [status, headers || {}, []], timings) end end end diff --git a/lib/method_profiler.rb b/lib/method_profiler.rb index c96a7f5957c..9ad59b007ff 100644 --- a/lib/method_profiler.rb +++ b/lib/method_profiler.rb @@ -37,6 +37,10 @@ class MethodProfiler } end + def self.clear + Thread.current[:_method_profiler] = nil + end + def self.stop finish = Process.clock_gettime(Process::CLOCK_MONOTONIC) if data = Thread.current[:_method_profiler] diff --git a/lib/middleware/request_tracker.rb b/lib/middleware/request_tracker.rb index 2b2e318d993..052b665bc4d 100644 --- a/lib/middleware/request_tracker.rb +++ b/lib/middleware/request_tracker.rb @@ -1,6 +1,7 @@ # frozen_string_literal: true require_dependency 'middleware/anonymous_cache' +require_dependency 'method_profiler' class Middleware::RequestTracker @@ -15,7 +16,6 @@ class Middleware::RequestTracker def self.register_detailed_request_logger(callback) unless @patched_instrumentation - require_dependency "method_profiler" MethodProfiler.patch(PG::Connection, [ :exec, :async_exec, :exec_prepared, :send_query_prepared, :query ], :sql) @@ -134,9 +134,13 @@ class Middleware::RequestTracker end env["discourse.request_tracker"] = self - MethodProfiler.start if @@detailed_request_loggers + MethodProfiler.start result = @app.call(env) - info = MethodProfiler.stop if @@detailed_request_loggers + info = MethodProfiler.stop + # possibly transferred? + if info + env["X-Runtime"] = "%0.6f" % info[:total_duration] + end result ensure log_request_info(env, result, info) unless env["discourse.request_tracker.skip"] diff --git a/spec/components/hijack_spec.rb b/spec/components/hijack_spec.rb index 3a9522ab9b6..a9f92ef309b 100644 --- a/spec/components/hijack_spec.rb +++ b/spec/components/hijack_spec.rb @@ -141,36 +141,43 @@ describe Hijack do end it "renders a redirect correctly" do + Process.stubs(:clock_gettime).returns(1.0) tester.hijack_test do + Process.stubs(:clock_gettime).returns(2.0) redirect_to 'http://awesome.com' end - result = "HTTP/1.1 302 Found\r\nLocation: http://awesome.com\r\nContent-Type: text/html\r\nContent-Length: 84\r\nConnection: close\r\n\r\nYou are being redirected." + result = "HTTP/1.1 302 Found\r\nLocation: http://awesome.com\r\nContent-Type: text/html\r\nContent-Length: 84\r\nConnection: close\r\nX-Runtime: 1.000000\r\n\r\nYou are being redirected." expect(tester.io.string).to eq(result) end it "renders stuff correctly if is empty" do + Process.stubs(:clock_gettime).returns(1.0) tester.hijack_test do + Process.stubs(:clock_gettime).returns(2.0) render body: nil end - result = "HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nContent-Length: 0\r\nConnection: close\r\n\r\n" + result = "HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nContent-Length: 0\r\nConnection: close\r\nX-Runtime: 1.000000\r\n\r\n" expect(tester.io.string).to eq(result) end it "renders stuff correctly if it works" do + Process.stubs(:clock_gettime).returns(1.0) tester.hijack_test do + Process.stubs(:clock_gettime).returns(2.0) render plain: "hello world" end - result = "HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nContent-Length: 11\r\nConnection: close\r\n\r\nhello world" + result = "HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nContent-Length: 11\r\nConnection: close\r\nX-Runtime: 1.000000\r\n\r\nhello world" expect(tester.io.string).to eq(result) end it "returns 500 by default" do + Process.stubs(:clock_gettime).returns(1.0) tester.hijack_test - expected = "HTTP/1.1 500 Internal Server Error\r\nContent-Type: text/html\r\nContent-Length: 0\r\nConnection: close\r\n\r\n" + expected = "HTTP/1.1 500 Internal Server Error\r\nContent-Type: text/html\r\nContent-Length: 0\r\nConnection: close\r\nX-Runtime: 0.000000\r\n\r\n" expect(tester.io.string).to eq(expected) end