Building a Performance Analytics Tool with ActiveSupport

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.

Efa305e8e1b4eca01dd9f5c8bea4294b?s=128

Christian Bruckmayer

April 17, 2020
Tweet

Transcript

  1. None
  2. None
  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

  9. None
  10. Grafana

  11. Active
 Monitoring

  12. Response
 Time

  13. Database
 Operations

  14. Plugin Data Storage Visualize ActiveMonitoring

  15. https://bruckmayer.net/rails-conf-2020

  16. None
  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
  21. None
  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

  46. None
  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

  97. None
  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