From 62141b63162b43245c5ab76cf7bfcb2e7daa807e Mon Sep 17 00:00:00 2001
From: Sam Saffron <sam.saffron@gmail.com>
Date: Wed, 5 Jun 2019 16:08:11 +1000
Subject: [PATCH] FEATURE: enable_performance_http_headers for performance
 diagnostics

This adds support for DISCOURSE_ENABLE_PERFORMANCE_HTTP_HEADERS
when set to `true` this will turn on performance related headers

```text
X-Redis-Calls: 10     # number of redis calls
X-Redis-Time: 1.02    # redis time in seconds
X-Sql-Commands: 102   # number of SQL commands
X-Sql-Time: 1.02      # duration in SQL in seconds
X-Queue-Time: 1.01    # time the request sat in queue (depends on NGINX)
```

To get queue time NGINX must provide: HTTP_X_REQUEST_START

We do not recommend you enable this without thinking, it exposes information
about what your page is doing, usually you would only enable this if you
intend to strip off the headers further down the stream in a proxy
---
 config/discourse_defaults.conf                     | 10 ++++++++++
 .../200-message_bus_request_tracker.rb             |  4 ++++
 lib/middleware/request_tracker.rb                  | 14 ++++++++++++++
 spec/components/middleware/request_tracker_spec.rb | 14 +++++++++++++-
 4 files changed, 41 insertions(+), 1 deletion(-)

diff --git a/config/discourse_defaults.conf b/config/discourse_defaults.conf
index bf4e8e3fa76..e66ed464b20 100644
--- a/config/discourse_defaults.conf
+++ b/config/discourse_defaults.conf
@@ -239,3 +239,13 @@ refresh_maxmind_db_during_precompile_days = 2
 # backup path containing maxmind db files
 maxmind_backup_path =
 
+# when enabled the following headers will be added to every response:
+# (note, if measurements do not exist for the header they will be omitted)
+#
+# X-Redis-Calls: 10
+# X-Redis-Time: 1.02
+# X-Sql-Calls: 102
+# X-Sql-Time: 1.02
+# X-Queue-Time: 1.01
+enable_performance_http_headers = false
+
diff --git a/config/initializers/200-message_bus_request_tracker.rb b/config/initializers/200-message_bus_request_tracker.rb
index 1026912c491..c0ebcfcb1b6 100644
--- a/config/initializers/200-message_bus_request_tracker.rb
+++ b/config/initializers/200-message_bus_request_tracker.rb
@@ -16,4 +16,8 @@ Rails.configuration.middleware = Rails.configuration.middleware + session_operat
 if Rails.env != 'development' || ENV['TRACK_REQUESTS']
   require 'middleware/request_tracker'
   Rails.configuration.middleware.unshift Middleware::RequestTracker
+
+  if GlobalSetting.enable_performance_http_headers
+    MethodProfiler.ensure_discourse_instrumentation!
+  end
 end
diff --git a/lib/middleware/request_tracker.rb b/lib/middleware/request_tracker.rb
index e8af3b5b15a..470ab5f1671 100644
--- a/lib/middleware/request_tracker.rb
+++ b/lib/middleware/request_tracker.rb
@@ -165,6 +165,20 @@ class Middleware::RequestTracker
     # possibly transferred?
     if info && (headers = result[1])
       headers["X-Runtime"] = "%0.6f" % info[:total_duration]
+
+      if GlobalSetting.enable_performance_http_headers
+        if redis = info[:redis]
+          headers["X-Redis-Calls"] = redis[:calls].to_s
+          headers["X-Redis-Time"] = "%0.6f" % redis[:duration]
+        end
+        if sql = info[:sql]
+          headers["X-Sql-Calls"] = sql[:calls].to_s
+          headers["X-Sql-Time"] = "%0.6f" % sql[:duration]
+        end
+        if queue = env['REQUEST_QUEUE_SECONDS']
+          headers["X-Queue-Time"] = "%0.6f" % queue
+        end
+      end
     end
 
     if env[Auth::DefaultCurrentUserProvider::BAD_TOKEN] && (headers = result[1])
diff --git a/spec/components/middleware/request_tracker_spec.rb b/spec/components/middleware/request_tracker_spec.rb
index ca8e1b67dd6..ae73bbaa034 100644
--- a/spec/components/middleware/request_tracker_spec.rb
+++ b/spec/components/middleware/request_tracker_spec.rb
@@ -274,6 +274,8 @@ describe Middleware::RequestTracker do
 
     it "can correctly log detailed data" do
 
+      global_setting :enable_performance_http_headers, true
+
       # ensure pg is warmed up with the select 1 query
       User.where(id: -100).pluck(:id)
 
@@ -283,7 +285,7 @@ describe Middleware::RequestTracker do
       freeze_time 1.minute.from_now
 
       tracker = Middleware::RequestTracker.new(app([200, {}, []], sql_calls: 2, redis_calls: 2))
-      tracker.call(env("HTTP_X_REQUEST_START" => "t=#{start}"))
+      _, headers, _ = tracker.call(env("HTTP_X_REQUEST_START" => "t=#{start}"))
 
       expect(@data[:queue_seconds]).to eq(60)
 
@@ -295,6 +297,16 @@ describe Middleware::RequestTracker do
 
       expect(timing[:redis][:duration]).to be > 0
       expect(timing[:redis][:calls]).to eq 2
+
+      expect(headers["X-Queue-Time"]).to eq("60.000000")
+
+      expect(headers["X-Redis-Calls"]).to eq("2")
+      expect(headers["X-Redis-Time"].to_f).to be > 0
+
+      expect(headers["X-Sql-Calls"]).to eq("2")
+      expect(headers["X-Sql-Time"].to_f).to be > 0
+
+      expect(headers["X-Runtime"].to_f).to be > 0
     end
   end