Save 37% off PRO during our Black Friday Sale! »

What's my app *really* doing in production?

What's my app *really* doing in production?

Presentation by Daniel Azuma at RailsConf 2017. Covers instrumentation and monitoring of live Ruby/Rails applications.

E06aa8f63d2a1753a2b352bc1cabbde2?s=128

Daniel Azuma

April 27, 2017
Tweet

Transcript

  1. What’s my app really doing in production? Daniel Azuma

  2. RailsConf 2011, ©Pinar Özger

  3. Daniel Azuma http://daniel-azuma.com/

  4. None
  5. Code samples are: Copyright 2017 Google Inc. Licensed under the

    Apache License, Version 2.0 (the "License"); you may not use this code except in compliance with the License. You may obtain a copy of the License at: https://www.apache.org/licenses/LICENSE-2.0 Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License. Lawyercat says:
  6. RailsConf 2017, © Daniel Azuma

  7. Measurement

  8. None
  9. None
  10. None
  11. ?

  12. Measure everything!

  13. How?

  14. https://codelabs.developers.google.com/codelabs/cloud-monitoring-codelab/

  15. Measuring in production • Instrumentation APIs • Instrumenting safely in

    production • What should you measure?
  16. Paul Almasy / WHO

  17. ActiveSupport::Notifications

  18. How do you know if your cache is working?

  19. How do you know if your cache is working? •

    Measure cache hit rate
  20. ActiveSupport::Notifications. instrument "cache_read.active_support" \ do actually_read_the_cache end Rails’s cache code

  21. Rails’s cache code Your app code ActiveSupport::Notifications. subscribe "cache_read.active_support" \

    do |name, st, fin, id, data| Rails.logger.info \ "cache #{data[:hit] ? 'HIT' : 'MISS'}" end ActiveSupport::Notifications. instrument "cache_read.active_support" \ do actually_read_the_cache end
  22. Rails’s cache code Your app code ActiveSupport::Notifications. subscribe "cache_read.active_support" \

    do |name, st, fin, id, data| Rails.logger.info \ "cache #{data[:hit] ? 'HIT' : 'MISS'}" end ActiveSupport::Notifications. instrument "cache_read.active_support" \ do actually_read_the_cache end # Log cache HIT cache MISS cache HIT cache HIT ...
  23. 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

    redirect_to.action_controller halted_callback.action_controller render_template.action_view render_partial.action_view render_collection.action_view sql.active_record instantiation.active_record receive.action_mailer deliver.action_mailer cache_read.active_support cache_generate.active_support cache_fetch_hit.active_support cache_write.active_support cache_delete.active_support cache_exist?.active_support enqueue_at.active_job enqueue.active_job perform_start.active_job perform.active_job load_config_initializer.railties deprecation.rails Rails already instruments:
  24. • Measure cache hit rate How do you know if

    your cache is working?
  25. http://antiquescientifica.com/photo_x-ray_and_disk_generator_with_doctor_c._1900.jpg

  26. • Measure cache hit rate • Isolate actions of interest

    How do you know if your cache is working?
  27. Interesting Action Subscribe Unsubscribe Other Action

  28. Interesting Action Unsubscribe Other Action Other Action Other Action Other

    Action Other Action Other Action Subscribe
  29. module MyApp::CacheInstrumentation ActiveSupport::Notifications.subscribe \ "cache_read.active_support" \ do |name, st, fin,

    id, data| Rails.logger.info "cache #{data[:hit] ? 'HIT' : 'MISS'}" end end
  30. module MyApp::CacheInstrumentation ActiveSupport::Notifications.subscribe \ "start_processing.action_controller" \ do |name, st, fin,

    id, data| should_i_measure = data[:controller] == "MyController" && data[:action] == "interesting_action" end ActiveSupport::Notifications.subscribe \ "cache_read.active_support" \ do |name, st, fin, id, data| Rails.logger.info "cache #{data[:hit] ? 'HIT' : 'MISS'}" end end
  31. module MyApp::CacheInstrumentation thread_mattr_accessor :should_i_measure ActiveSupport::Notifications.subscribe \ "start_processing.action_controller" \ do |name,

    st, fin, id, data| self.should_i_measure = data[:controller] == "MyController" && data[:action] == "interesting_action" end ActiveSupport::Notifications.subscribe \ "cache_read.active_support" \ do |name, st, fin, id, data| Rails.logger.info "cache #{data[:hit] ? 'HIT' : 'MISS'}" \ if self.should_i_measure end end Thread 1 should_i_measure Thread 2 should_i_measure Thread 3 should_i_measure “Per-thread” Globals
  32. • Measure cache hit rate • Isolate actions of interest

    How do you know if your cache is working?
  33. Harry Thompson / Evening Standard / Getty Images

  34. • Measure cache hit rate • Isolate actions of interest

    • Correlate with latency measurements How do you know if your cache is working?
  35. module MyApp::CacheInstrumentation thread_mattr_accessor :should_i_measure ActiveSupport::Notifications.subscribe "start_processing.action_controller" do |name, st, fin,

    id, data| self.should_i_measure = data[:controller] == "MyController" && data[:action] == "interesting_action" end ActiveSupport::Notifications.subscribe \ "cache_read.active_support" do |name, st, fin, id, data| Rails.logger.info "cache #{data[:hit] ? 'HIT' : 'MISS'}" \ if self.should_i_measure end end
  36. module MyApp::CacheInstrumentation thread_mattr_accessor :should_i_measure ActiveSupport::Notifications.subscribe "start_processing.action_controller" do |name, st, fin,

    id, data| self.should_i_measure = data[:controller] == "MyController" && data[:action] == "interesting_action" end ActiveSupport::Notifications.subscribe \ "cache_read.active_support" do |name, st, fin, id, data| Rails.logger.info "cache #{data[:hit] ? 'HIT' : 'MISS'}" \ if self.should_i_measure end ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args| event = ActiveSupport::Notifications::Event.new *args Rails.logger.info "request took #{event.duration} ms" \ if self.should_i_measure end end
  37. module MyApp::CacheInstrumentation thread_mattr_accessor :should_i_measure thread_mattr_accessor :hit_or_miss ActiveSupport::Notifications.subscribe "start_processing.action_controller" do |name,

    st, fin, id, data| self.should_i_measure = data[:controller] == "MyController" && data[:action] == "interesting_action" end ActiveSupport::Notifications.subscribe \ "cache_read.active_support" do |name, st, fin, id, data| self.hit_or_miss = data[:hit] ? "HIT" : "MISS" \ if self.should_i_measure end ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args| event = ActiveSupport::Notifications::Event.new *args Rails.logger.info "cache #{self.hit_or_miss} (#{event.duration} ms)" \ if self.should_i_measure end end
  38. # Log cache MISS (179 ms) cache MISS (182 ms)

    cache MISS (172 ms) cache HIT (132 ms) cache MISS (168 ms) cache MISS (180 ms) cache MISS (173 ms) cache MISS (178 ms) cache MISS (171 ms) cache MISS (186 ms) cache HIT (129 ms) cache MISS (176 ms) cache MISS (171 ms) ...
  39. # Log cache MISS (179 ms) cache MISS (182 ms)

    cache MISS (172 ms) cache HIT (132 ms) cache MISS (168 ms) cache MISS (180 ms) cache MISS (173 ms) cache MISS (178 ms) cache MISS (171 ms) cache MISS (186 ms) cache HIT (129 ms) cache MISS (176 ms) cache MISS (171 ms) ...
  40. # Log cache MISS (179 ms) cache MISS (182 ms)

    cache MISS (172 ms) cache HIT (132 ms) cache MISS (168 ms) cache MISS (180 ms) cache MISS (173 ms) cache MISS (178 ms) cache MISS (171 ms) cache MISS (186 ms) cache HIT (129 ms) cache MISS (176 ms) cache MISS (171 ms) ... “Actionable” Data
  41. Other instrumentation APIs

  42. module MyApp::MyController around_filter :measure_time def measure_time start = Time.now yield

    ensure secs = Time.now - start logger.info "It took #{secs} seconds" end end ActionController filters Use it when: You just have to measure something simple about the request as a whole
  43. Rack Middleware class MyApp::MyMiddleware def initialize app; @app = app;

    end def call env start = Time.now @app.call env ensure secs = Time.now - start puts "It took #{secs} seconds" end end Use it when: You’re using something besides Rails, or want to measure middleware
  44. trace = TracePoint.new :call do |tp| if tp.method_id == :my_method

    Rails.logger.info "my_method called" end end trace.enable do do_stuff end TracePoint Use it when: You want to measure something at the language level (like method calls)
  45. Fox Photos / Getty Images

  46. Safety

  47. Tips for reducing latency

  48. • Isolate cases of interest Tips for reducing latency

  49. • Isolate cases of interest • Re-evaluate existing instrumentation Tips

    for reducing latency
  50. • Isolate cases of interest • Re-evaluate existing instrumentation •

    Sample your data Tips for reducing latency
  51. • Isolate cases of interest • Re-evaluate existing instrumentation •

    Sample your data • Use TracePoint sparingly Tips for reducing latency
  52. • Isolate cases of interest • Re-evaluate existing instrumentation •

    Sample your data • Use TracePoint sparingly • Report asynchronously Tips for reducing latency
  53. Avoid side effects Avoid behavior changes, not just state changes

  54. What should you measure?

  55. Central Press / Getty Images

  56. What are your app’s indicators?

  57. Measure Results (responses, error rates)

  58. Internal processes (intermediate results, rendering)

  59. External interfaces (databases, APIs, caches)

  60. Measure Errors (including retries)

  61. Start measuring!

  62. https://www.flickr.com/photos/brookhavenlab/3181807959/

  63. Thank you! http://daniel-azuma.com/ @danielazuma