Building a Performance Analytics Tool with ActiveSupport

Setting up a performance analytics tool like NewRelic or Skylight is one of the first things many developers do in a new project. However, have you ever wondered how these tools work under the hood?

In this talk, we will build a basic performance analytics tool from scratch. We will deep dive into ActiveSupport instrumentations to collect, group and normalise metrics from your app. To persist these metrics, we will use a time series database and visualise the data on a dashboard. By the end of the talk, you will know how your favourite performance analytics tool works.

Transcript

3. Develop
4. Admit
5. Ultimate
 Proof
6. Let’s Build a Performance Monitoring Tool with ActiveSupport
7. Hello! I am 
 Christian Bruckmayer
 
 @bruckmayer
 bruckmayer.net
8. Bristol
10. Grafana
11. Active
 Monitoring
12. Response
 Time
13. Database
 Operations
14. Plugin Data Storage Visualize ActiveMonitoring
15. https://bruckmayer.net/rails-conf-2020
17. https://youtu.be/XL51vf-XBTs
18. Collecting Storing Processing Visualizing
19. Active
 Support
20. 1.day.from_now => Sun, 29 Mar 2020 13:45:13 UTC +00:00 ["Ruby", "Rails"].to_sentence => "Ruby and Rails” ["Ruby", "Rails"].many? => true
22. Notifications.instrument("add", term: "1 + 1") do 1 + 1 end Notifications.subscribe("add") do |payload| logger.log("#{payload[:start]}: #{payload[:term]}") end
23. redirect_to.action_controller halted_callback.action_controller unpermitted_parameters.action_controller process_middleware.action_dispatch render_template.action_view render_partial.action_view render_collection.action_view sql.active_record instantiation.active_record … write_fragment.action_controller read_fragment.action_controller expire_fragment.action_controller exist_fragment?.action_controller write_page.action_controller expire_page.action_controller start_processing.action_controller process_action.action_controller send_file.action_controller send_data.action_controller 51 Hooks
24. redirect_to.action_controller halted_callback.action_controller unpermitted_parameters.action_controller process_middleware.action_dispatch render_template.action_view render_partial.action_view render_collection.action_view sql.active_record instantiation.active_record … write_fragment.action_controller read_fragment.action_controller expire_fragment.action_controller exist_fragment?.action_controller write_page.action_controller expire_page.action_controller start_processing.action_controller process_action.action_controller send_file.action_controller send_data.action_controller 51 Hooks
25. redirect_to.action_controller halted_callback.action_controller unpermitted_parameters.action_controller process_middleware.action_dispatch render_template.action_view render_partial.action_view render_collection.action_view sql.active_record instantiation.active_record … write_fragment.action_controller read_fragment.action_controller expire_fragment.action_controller exist_fragment?.action_controller write_page.action_controller expire_page.action_controller start_processing.action_controller process_action.action_controller send_file.action_controller send_data.action_controller 51 Hooks
26. redirect_to.action_controller halted_callback.action_controller unpermitted_parameters.action_controller process_middleware.action_dispatch render_template.action_view render_partial.action_view render_collection.action_view sql.active_record instantiation.active_record … write_fragment.action_controller read_fragment.action_controller expire_fragment.action_controller exist_fragment?.action_controller write_page.action_controller expire_page.action_controller start_processing.action_controller process_action.action_controller send_file.action_controller send_data.action_controller 51 Hooks
27. Notifications.instrument("add", term: "1 + 1") do 1 + 1 end Notifications.subscribe("add") do |payload| logger.log("#{payload[:start]}: #{payload[:term]}") end
28. module ActiveMonitoring class Notifications class << self attr_accessor :notifier def subscribe(name, &block) notifier[name] ||= [] notifier[name] << block end end self.notifier = {} end end Plugin
29. module ActiveMonitoring class Notifications class << self attr_accessor :notifier def subscribe(name, &block) notifier[name] ||= [] notifier[name] << block end end self.notifier = {} end end Plugin
30. module ActiveMonitoring class Notifications class << self def instrument(name, payload = {}) start = Time.now result = yield if block_given? finish = Time.now notifier[name].to_a.each do |callback| callback.call payload.merge(start: start, finish: finish) end result end end end end Plugin
31. module ActiveMonitoring class Notifications class << self def instrument(name, payload = {}) start = Time.now result = yield if block_given? finish = Time.now notifier[name].to_a.each do |callback| callback.call payload.merge(start: start, finish: finish) end result end end end end Plugin
32. redirect_to.action_controller halted_callback.action_controller unpermitted_parameters.action_controller process_middleware.action_dispatch render_template.action_view render_partial.action_view render_collection.action_view sql.active_record instantiation.active_record … write_fragment.action_controller read_fragment.action_controller expire_fragment.action_controller exist_fragment?.action_controller write_page.action_controller expire_page.action_controller start_processing.action_controller process_action.action_controller send_file.action_controller send_data.action_controller 51 Hooks
33. module Redis class Probe def call(*) Notifications.instrument("call.redis", payload) do super end end end end
34. Instrumentation
35. Collecting Storing Processing Visualizing
36. module ActiveMonitoring class Engine < ::Rails::Engine config.after_initialize do Notifications.subscribe("process_action") do |payload| # Store data end end end end Plugin
37. { controller: "PostsController", action: "index", params: {"action" => "index", "controller" => "posts"}, headers: #<ActionDispatch::Http::Headers:0x0055a67a519b88>, format: :html, method: "GET", path: "/posts", request: #<ActionDispatch::Request:0x00007ff1cb9bd7b8>, status: 200, view_runtime: 46.848, db_runtime: 0.157 }
38. id timestamp duration hook_name location 1 2020-03-28 14:35:59 101 process_action Home#index 2 2020-03-28 14:35:59 28 process_action Home#index 3 2020-03-28 14:35:59 300 process_action SignUp#create 4 2020-03-28 14:35:59 56 process_action Home#index
39. Relational
 Database
40. Create Read Update Delete
41. class BooksController < ApplicationController def new; end def create; end def show; end def edit; end def update; end def destroy; end end
42. Create Read Update Delete
43. B+ Tree
44. B+ Tree
45. https://db-engines.com/en/ranking_categories
47. https://db-engines.com/en/ranking/time+series+dbms
48. timestamp duration hook_name location 2020-03-28 14:35:59 101 process_action Home#index 2020-03-28 14:35:59 28 process_action Home#index 2020-03-28 14:35:59 300 process_action SignUp#create 2020-03-28 14:35:59 56 process_action Home#index
49. timestamp duration hook_name location 2020-03-28 14:35:59 101 process_action Home#index 2020-03-28 14:35:59 28 process_action Home#index 2020-03-28 14:35:59 300 process_action SignUp#create 2020-03-28 14:35:59 56 process_action Home#index Measurement
50. timestamp duration hook_name location 2020-03-28 14:35:59 101 process_action Home#index 2020-03-28 14:35:59 28 process_action Home#index 2020-03-28 14:35:59 300 process_action SignUp#create 2020-03-28 14:35:59 56 process_action Home#index Primary Key
51. timestamp duration hook_name location 2020-03-28 14:35:59 101 process_action Home#index 2020-03-28 14:35:59 28 process_action Home#index 2020-03-28 14:35:59 300 process_action SignUp#create 2020-03-28 14:35:59 56 process_action Home#index Field
52. timestamp duration hook_name location 2020-03-28 14:35:59 101 process_action Home#index 2020-03-28 14:35:59 28 process_action Home#index 2020-03-28 14:35:59 300 process_action SignUp#create 2020-03-28 14:35:59 56 process_action Home#index Tag
53. Memory Disk Log Structured 
 Merge Tree Dec Jan Feb March
54. Memory Disk Log Structured 
 Merge Tree Dec Jan Feb March
55. Memory Disk Log Structured 
 Merge Tree Compress Jan Feb March
56. module ActiveMonitoring class Railtie < ::Rails::Engine config.after_initialize do Notifications.subscribe("process_action") do |payload| location = "#{payload[:controller]}##{payload[:action]}" InfluxDB::Client.write_point( "rails", timestamp: payload[:finish], tags: { hook_name: "process_action", location: location }, values: { duration: payload[:finish] - payload[:start] } ) end end end end Plugin
57. module ActiveMonitoring class Railtie < ::Rails::Engine config.after_initialize do Notifications.subscribe(“sql.active_record”) do |payload| # Clean, normalize & group data # Store data end end end end Plugin
58. Relational
 vs. Time Series
59. Collecting Storing Processing Visualizing
60. module ActiveMonitoring class Engine < ::Rails::Engine config.after_initialize do Notifications.subscribe(“sql.active_record”) do |payload| # Clean, normalize & group data # Store data end end end end Plugin
61. Normalizing
62. { sql: 'SELECT "posts".* FROM "posts" WHERE id=1', name: "Post Load", connection_id: 70307250813140, connection: #SQLite3Adapter:0x00007f9f7a838850>, binds: [:WithCastValue:0x00007fe19d15dc00>], type_casted_binds: [11], statement_name: nil }
63. { sql: 'SELECT "posts".* FROM "posts" WHERE id=1', name: "Post Load", connection_id: 70307250813140, connection: #SQLite3Adapter:0x00007f9f7a838850>, binds: [:WithCastValue:0x00007fe19d15dc00>], type_casted_binds: [11], statement_name: nil }
64. SELECT "posts".* FROM "posts" WHERE id=1 SELECT "posts".* FROM "posts" WHERE id=2 SELECT "posts".* FROM "posts" WHERE id=x
65. query = SELECT "posts".* FROM "posts" WHERE id=1 query.gsub!(/(\s(=|>|<|!=)\s)('[^']+'|[\$\+\-\w\.]+)/, ‘\1x')
66. class Normalizer def initialize(query:) @query = query end def to_s query.squish! query.gsub!(/(\s(=|>|<|!=)\s)('[^']+'|[\$\+\-\w\.]+)/, '\1xxx') query.gsub!(/(\sIN\s)\([^\(\)]+\)/i, '\1(xxx)') query.gsub!(/(\sVALUES\s)\(.+\)/i, '\1(xxx)') query.gsub!(/(\s(LIKE||SIMILAR TO)\s)('[^']+')/i, '\1xxx') query.gsub!(/(\s(LIMIT|OFFSET)\s)(\d+)/i, '\1xxx') query end end
67. Cleaning
68. { sql: "SELECT SQLITE_VERSION(*)", name: "SCHEMA", connection_id: 70307250813140, connection: #SQLite3Adapter:0x00007f9f7a838850>, binds: [:WithCastValue:0x00007fe19d15dc00>], type_casted_binds: [11], statement_name: nil }
69. SELECT SQLITE_VERSION(*) SELECT version FROM SCHEMA_MIGRATIONS Active Record
70. CREATE TABLE books (id int, name varchar(255)) ALTER TABLE books DROP COLUMN name Migration
71. class Query TRACKED_SQL_COMMANDS = %w[SELECT INSERT UPDATE DELETE].freeze UNTRACKED_NAMES = %w[SCHEMA].freeze def track? query.start_with?(*TRACKED_SQL_COMMANDS) && !name.upcase.start_with?(*UNTRACKED_NAMES) end end
72. Grouping
73. { sql: 'SELECT "posts".* FROM "posts" WHERE id=1', name: "Post Load", connection_id: 70307250813140, connection: #SQLite3Adapter:0x00007f9f7a838850>, binds: [:WithCastValue:0x00007fe19d15dc00>], type_casted_binds: [11], statement_name: nil, request_id: ??? }
74. redirect_to.action_controller halted_callback.action_controller unpermitted_parameters.action_controller process_middleware.action_dispatch render_template.action_view render_partial.action_view render_collection.action_view sql.active_record instantiation.active_record … write_fragment.action_controller read_fragment.action_controller expire_fragment.action_controller exist_fragment?.action_controller write_page.action_controller expire_page.action_controller start_processing.action_controller process_action.action_controller send_file.action_controller send_data.action_controller 51 Hooks
75. module ActiveMonitoring class Engine < ::Rails::Engine config.after_initialize do Notifications.subscribe("start_processing") do |data| location = “#{payload[:controller]}##{payload[:action]}" Current.request_id = payload[:request_id] Current.location = location end end end end
76. module ActiveMonitoring class Current class << self def store Thread.current[:active_monitoring] ||= {} Thread.current[:active_monitoring] end end end end
77. module ActiveMonitoring class Current class << self def request_id store[:request_id] end def request_id=(value) store[:request_id] = value end end end end
78. module ActiveMonitoring class Railtie < ::Rails::Railtie config.after_initialize do Notifications.subscribe("sql") do |data| query = Query.new(query: data[:sql], name: data[:name]) if query.track? # ... end end end end end
79. module ActiveMonitoring class Railtie < ::Rails::Railtie config.after_initialize do Notifications.subscribe("sql") do |data| # ... tags = { hook_name: "sql", request_id: Current.request_id, location: Current.location, query: query.normalized_query } end end end end
80. module ActiveMonitoring class Railtie < ::Rails::Railtie config.after_initialize do Notifications.subscribe("sql") do |data| # ... tags = { hook_name: "sql", request_id: Current.request_id, location: Current.location, query: query.normalized_query } end end end end
81. module ActiveMonitoring class Railtie < ::Rails::Railtie config.after_initialize do Notifications.subscribe("sql") do |data| # ... InfluxDB::Client.write_point( "rails", timestamp: Time.current, tags: tags, values: { duration: data[:finish] - data[:start] } ) end end end end
82. More
 Value
83. Performance
84. Collecting Storing Processing Visualizing
85. timestamp duration hook_name location 2020-03-28 14:35:59 101 process_action Home#index 2020-03-28 14:35:59 28 process_action Home#index 2020-03-28 14:35:59 300 process_action SignUp#create 2020-03-28 14:35:59 56 process_action Home#index
86. timestamp duration hook_name location 2020-03-28 14:35:59 101 process_action Home#index 2020-03-28 14:35:59 28 process_action Home#index 2020-03-28 14:35:59 300 process_action SignUp#create 2020-03-28 14:35:59 56 process_action SignUp#create 2020-03-28 14:35:59 120 process_action SignUp#create 2020-03-28 14:35:59 73 process_action Home#index 2020-03-28 14:35:59 48 process_action SignUp#create 2020-03-28 14:35:59 20 process_action SignUp#create 2020-03-28 14:35:59 800 process_action SignUp#create 2020-03-28 14:35:59 36 process_action Home#index
87. Grafana
88. Spot
 Issues
89. response_time = [ 101, 28, 300, 42, 56 ] average = response_time.sum / response_time.length # 105 Average
90. response_time = [ 28, 42, 56, 101, 300 ].sort median = response_time[response_time.length / 2] # 56 Median
91. SELECT percentile(“controller_value”, 50) FROM "rails"
92. Median / Average
93. Median Average
94. Median Average P90
95. https://www.schneems.com/
96. Set
 Priority
98. 80/20
 Rule
99. Indicator
100. Grafana
101. Grafana
102. Insights
103. Collecting Storing Processing Visualizing
104. Open
 Source
105. Plugin Data Storage Visualize ActiveMonitoring
106. Customize
107. Collaborate
108. Understand
109. https://github.com/influxdata/influxdb-rails
110. Questions?
111. Thank You!
 
 @bruckmayer
 christian@bruckmayer.net