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

@@ -120,6 +120,9 @@ vendor/bundle/*
 # ignore jetbrains ide file
 *.iml
 
+# vim swap
+*.swn
+
 # ignore nodejs files
 /node_modules
 /package-lock.json

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)

app/controllers/topics_controller.rb

@@ -585,15 +585,23 @@ class TopicsController < ApplicationController
   end
 
   def timings
+    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_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] },
+        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
     @topic_view = TopicView.new(params[:topic_id])

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)

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

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]

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"]

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\n<html><body>You are being <a href=\"http://awesome.com\">redirected</a>.</body></html>"
+    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\n<html><body>You are being <a href=\"http://awesome.com\">redirected</a>.</body></html>"
     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