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

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

Transcript

1. What’s my app really doing in production? Daniel Azuma
2. RailsConf 2011, ©Pinar Özger
3. Daniel Azuma http://daniel-azuma.com/
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
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