diff --git a/lib/method_profiler.rb b/lib/method_profiler.rb new file mode 100644 index 0000000000..6d99b9f88e --- /dev/null +++ b/lib/method_profiler.rb @@ -0,0 +1,43 @@ +# see https://samsaffron.com/archive/2017/10/18/fastest-way-to-profile-a-method-in-ruby +class MethodProfiler + def self.patch(klass, methods, name) + patches = methods.map do |method_name| + <<~RUBY + unless defined?(#{method_name}__mp_unpatched) + alias_method :#{method_name}__mp_unpatched, :#{method_name} + def #{method_name}(*args, &blk) + unless prof = Thread.current[:_method_profiler] + return #{method_name}__mp_unpatched(*args, &blk) + end + begin + start = Process.clock_gettime(Process::CLOCK_MONOTONIC) + #{method_name}__mp_unpatched(*args, &blk) + ensure + data = (prof[:#{name}] ||= {duration: 0.0, calls: 0}) + data[:duration] += Process.clock_gettime(Process::CLOCK_MONOTONIC) - start + data[:calls] += 1 + end + end + end + RUBY + end.join("\n") + + klass.class_eval patches + end + + def self.start + Thread.current[:_method_profiler] = { + __start: Process.clock_gettime(Process::CLOCK_MONOTONIC) + } + end + + def self.stop + finish = Process.clock_gettime(Process::CLOCK_MONOTONIC) + if data = Thread.current[:_method_profiler] + Thread.current[:_method_profiler] = nil + start = data.delete(:__start) + data[:total_duration] = finish - start + end + data + end +end diff --git a/lib/middleware/request_tracker.rb b/lib/middleware/request_tracker.rb index a2dae84e97..7a57ba94de 100644 --- a/lib/middleware/request_tracker.rb +++ b/lib/middleware/request_tracker.rb @@ -1,7 +1,43 @@ +# frozen_string_literal: true + require_dependency 'middleware/anonymous_cache' class Middleware::RequestTracker + @@detailed_request_loggers = nil + + # register callbacks for detailed request loggers called on every request + # example: + # + # Middleware::RequestTracker.detailed_request_logger(->|env, data| do + # # do stuff with env and data + # end + 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) + + MethodProfiler.patch(Redis::Client, [ + :call, :call_pipeline + ], :redis) + @patched_instrumentation = true + end + + (@@detailed_request_loggers ||= []) << callback + end + + def self.unregister_detailed_request_logger(callback) + @@detailed_request_loggers.delete callback + + if @@detailed_request_loggers.length == 0 + @detailed_request_loggers = nil + end + + end + def initialize(app, settings = {}) @app = app end @@ -44,19 +80,17 @@ class Middleware::RequestTracker end - TRACK_VIEW = "HTTP_DISCOURSE_TRACK_VIEW".freeze - CONTENT_TYPE = "Content-Type".freeze - def self.get_data(env, result) + def self.get_data(env, result, timing) status, headers = result status = status.to_i helper = Middleware::AnonymousCache::Helper.new(env) request = Rack::Request.new(env) - env_track_view = env[TRACK_VIEW] + env_track_view = env["HTTP_DISCOURSE_TRACK_VIEW"] track_view = status == 200 - track_view &&= env_track_view != "0".freeze && env_track_view != "false".freeze - track_view &&= env_track_view || (request.get? && !request.xhr? && headers[CONTENT_TYPE] =~ /text\/html/) + track_view &&= env_track_view != "0" && env_track_view != "false" + track_view &&= env_track_view || (request.get? && !request.xhr? && headers["Content-Type"] =~ /text\/html/) track_view = !!track_view { @@ -65,22 +99,32 @@ class Middleware::RequestTracker has_auth_cookie: helper.has_auth_cookie?, is_background: request.path =~ /^\/message-bus\// || request.path == /\/topics\/timings/, is_mobile: helper.is_mobile?, - track_view: track_view + track_view: track_view, + timing: timing } + end def call(env) + MethodProfiler.start if @@detailed_request_loggers result = @app.call(env) + info = MethodProfiler.stop if @@detailed_request_loggers + result ensure # we got to skip this on error ... its just logging - data = self.class.get_data(env, result) rescue nil + data = self.class.get_data(env, result, info) rescue nil host = RailsMultisite::ConnectionManagement.host(env) if data if result && (headers = result[1]) headers["X-Discourse-TrackView"] = "1" if data[:track_view] end + + if @@detailed_request_loggers + @@detailed_request_loggers.each { |logger| logger.call(env, data) } + end + log_later(data, host) end diff --git a/spec/components/middleware/request_tracker_spec.rb b/spec/components/middleware/request_tracker_spec.rb index c8c217eb44..b61a995d22 100644 --- a/spec/components/middleware/request_tracker_spec.rb +++ b/spec/components/middleware/request_tracker_spec.rb @@ -21,7 +21,7 @@ describe Middleware::RequestTracker do def log_tracked_view(val) data = Middleware::RequestTracker.get_data(env( "HTTP_DISCOURSE_TRACK_VIEW" => val - ), ["200", { "Content-Type" => 'text/html' }]) + ), ["200", { "Content-Type" => 'text/html' }], 0.2) Middleware::RequestTracker.log_request(data) end @@ -40,19 +40,19 @@ describe Middleware::RequestTracker do data = Middleware::RequestTracker.get_data(env( "HTTP_USER_AGENT" => "AdsBot-Google (+http://www.google.com/adsbot.html)" - ), ["200", { "Content-Type" => 'text/html' }]) + ), ["200", { "Content-Type" => 'text/html' }], 0.1) Middleware::RequestTracker.log_request(data) data = Middleware::RequestTracker.get_data(env( "HTTP_DISCOURSE_TRACK_VIEW" => "1" - ), ["200", {}]) + ), ["200", {}], 0.1) Middleware::RequestTracker.log_request(data) data = Middleware::RequestTracker.get_data(env( "HTTP_USER_AGENT" => "Mozilla/5.0 (iPhone; CPU iPhone OS 8_1 like Mac OS X) AppleWebKit/600.1.4 (KHTML, like Gecko) Version/8.0 Mobile/12B410 Safari/600.1.4" - ), ["200", { "Content-Type" => 'text/html' }]) + ), ["200", { "Content-Type" => 'text/html' }], 0.1) Middleware::RequestTracker.log_request(data) @@ -65,5 +65,49 @@ describe Middleware::RequestTracker do expect(ApplicationRequest.page_view_crawler.first.count).to eq(1) expect(ApplicationRequest.page_view_anon_mobile.first.count).to eq(1) end + + end + + context "callbacks" do + def app(result, sql_calls: 0, redis_calls: 0) + lambda do |env| + sql_calls.times do + User.where(id: -100).first + end + redis_calls.times do + $redis.get("x") + end + result + end + end + + let :logger do + ->(env, data) do + @env = env + @data = data + end + end + + before do + Middleware::RequestTracker.register_detailed_request_logger(logger) + end + + after do + Middleware::RequestTracker.register_detailed_request_logger(logger) + end + + it "can correctly log detailed data" do + tracker = Middleware::RequestTracker.new(app([200, {}, []], sql_calls: 2, redis_calls: 2)) + tracker.call(env) + + timing = @data[:timing] + expect(timing[:total_duration]).to be > 0 + + expect(timing[:sql][:duration]).to be > 0 + expect(timing[:sql][:calls]).to eq 2 + + expect(timing[:redis][:duration]).to be > 0 + expect(timing[:redis][:calls]).to eq 2 + end end end