Experimental - DO NOT MERGE! Auto-instrumentation of Controller Time #198

itsderek23 · 2018-06-01T15:19:48Z

Install instructions:

add rubocop to the Gemfile
add require 'scout_apm/auto_instrument' to config/boot.rb

itsderek23 · 2018-06-01T15:22:26Z

No rush, but I tried adding this to an app, but I'm not seeing any auto-instrumentation.

Relevant diffs below:

diff --git a/Gemfile b/Gemfile
index f467c15..15bf591 100644
--- a/Gemfile
+++ b/Gemfile
@@ -31,9 +31,13 @@
-gem 'scout_apm', git: 'https://github.com/scoutapp/scout_apm_ruby.git', branch: 'scoutprof_statsd_context'
+
+gem 'rubocop' # for auto instrument
+gem 'scout_apm', git: 'https://github.com/scoutapp/scout_apm_ruby.git', branch: 'auto_instruments'
+# gem 'scout_apm', git: 'https://github.com/scoutapp/scout_apm_ruby.git', branch: 'scoutprof_statsd_context'

diff --git a/Gemfile.lock b/Gemfile.lock
index 353ce16..a4f3768 100644
--- a/Gemfile.lock
+++ b/Gemfile.lock
@@ -1,9 +1,9 @@
 GIT
   remote: https://github.com/scoutapp/scout_apm_ruby.git
-  revision: 634484b7673baf1083b8b3076118c100ab2e022e
-  branch: scoutprof_statsd_context
+  revision: 3f469a854bf57d23fd778e9860628eceabd64196
+  branch: auto_instruments
   specs:
-    scout_apm (3.0.0.pre23)
+    scout_apm (2.4.11)
 
 GEM
   remote: https://rubygems.org/
@@ -51,6 +51,7 @@ GEM
     airbrussh (1.1.0)
       sshkit (>= 1.6.1, != 1.7.0)
     arel (6.0.3)
+    ast (2.4.0)
     autoprefixer-rails (6.5.0.1)
       execjs
     aws-sdk (2.0.28)
@@ -268,6 +269,9 @@ GEM
     oj (3.1.3)
     orm_adapter (0.5.0)
     os (0.9.6)
+    parallel (1.12.1)
+    parser (2.5.1.0)
+      ast (~> 2.4.0)
     pg (0.18.3)
     pg-eyeballs (1.1.0)
       activerecord (>= 4.0, < 6.0)
@@ -280,6 +284,7 @@ GEM
       capybara (~> 2.1)
       cliver (~> 0.3.1)
       websocket-driver (>= 0.2.0)
+    powerpack (0.1.1)
     premailer (1.8.7)
       css_parser (>= 1.4.5)
       htmlentities (>= 4.0.0)
@@ -334,6 +339,7 @@ GEM
       activesupport (= 4.2.7.1)
       rake (>= 0.8.7)
       thor (>= 0.18.1, < 2.0)
+    rainbow (3.0.0)
     raindrops (0.17.0)
     rake (11.3.0)
     rbnacl (3.4.0)
@@ -373,6 +379,14 @@ GEM
     rollbar (2.15.5)
       multi_json
     rouge (1.10.1)
+    rubocop (0.56.0)
+      parallel (~> 1.10)
+      parser (>= 2.5)
+      powerpack (~> 0.1)
+      rainbow (>= 2.2.2, < 4.0)
+      ruby-progressbar (~> 1.7)
+      unicode-display_width (~> 1.0, >= 1.0.1)
+    ruby-progressbar (1.9.0)
     rugged (0.23.2)
     safe_yaml (1.0.4)
     sass (3.4.22)
@@ -476,6 +490,7 @@ GEM
       unf_ext
     unf_ext (0.0.7.1)
     unicode (0.4.4.2)
+    unicode-display_width (1.3.3)
     unicorn (5.2.0)
       kgio (~> 2.6)
       raindrops (~> 0.7)
@@ -558,6 +573,7 @@ DEPENDENCIES
   retriable (~> 2.1)
   rollbar
   rouge
+  rubocop
   rugged
   sass-rails
   scout_apm!

diff --git a/config/boot.rb b/config/boot.rb
index 6b750f0..961b641 100644
--- a/config/boot.rb
+++ b/config/boot.rb
@@ -1,3 +1,3 @@
 ENV['BUNDLE_GEMFILE'] ||= File.expand_path('../../Gemfile', __FILE__)
-
+require 'scout_apm/auto_instrument'
 require 'bundler/setup' # Set up gems listed in the Gemfile.

itsderek23 · 2018-06-01T15:37:56Z

Also:

ruby -v
ruby 2.1.2p95 (2014-05-08 revision 45877) [x86_64-darwin13.0]

I noticed that ScoutApm::InstructionSequence#load_iseq isn't called. I wonder if this is due to my older Ruby version.

itsderek23 · 2018-06-01T16:05:15Z

Works with Ruby 2.3.1, so a Ruby version issue.

Pretty cool - this breaks down a lot of the time!

itsderek23 · 2018-06-01T21:40:54Z

This helps address scoutapp/roadmap#68

dlanderson · 2018-06-07T15:11:34Z

Correct - needs Ruby 2.3.1+ currently.

ioquatix · 2019-01-27T01:53:19Z

Okay, I've made a first stab at improving this.

I've added some tests.

I suggest that the next step is to ensure we are generating the correct instrumentation and add a handful more tests.

ioquatix · 2019-01-27T01:53:53Z

The code right now is very much Rails specific, but I've left it open for the future, we can probably modify it to suit different frameworks e.g. Sinatra.

ioquatix · 2019-01-27T02:31:48Z

Do you have any prescribed method for doing integration tests? i.e. create a default rails site, insert the scout_apm gem, run it, and check that it's instrumented/collecting data?

I feel like this would be a nice addition.

lib/scout_apm/layer_children_set.rb

lib/scout_apm/auto_instrument.rb

cschneid · 2019-01-27T17:37:34Z

Gemfile

@@ -10,3 +10,7 @@ if RUBY_VERSION <= "1.8.7"
  gem "pry", "~> 0.9.12"
  gem "rake", "~> 10.5"
 end
+
+group :development do
+  gem "parser"


Can this be a dev-time gemspec dependency instead?

Yes, no problem.

dlanderson

@ioquatix awesome! A few things I want to go over and that need fixing. I'll ping you so we can chat about them

dlanderson · 2019-01-29T17:47:15Z

lib/scout_apm/auto_instrument/instruction_sequence.rb

+        if path =~ CONTROLLER_PATH_PATTERN
+          new_code = Rails.rewrite(path)
+
+          return compile(new_code, path, filepath)


filepath is undefined. Also, I think the arguments to compile are wrong - https://ruby-doc.org/core-2.5.0/RubyVM/InstructionSequence.html#method-c-compile

Yeah, my bad, we should probably add some tests for this.

dlanderson · 2019-01-29T17:47:41Z

lib/scout_apm/auto_instrument/instruction_sequence.rb

+module ScoutApm
+  module AutoInstrument
+    module InstructionSequence
+      CONTROLLER_PATH_PATTERN = /\/apm\/app\/controllers\/.*_controller.rb$/


We need to make sure we remove the \/apm portion here

lib/scout_apm/auto_instrument/instruction_sequence.rb

dlanderson · 2019-01-29T17:51:00Z

lib/scout_apm/auto_instrument/rails.rb

@@ -0,0 +1,73 @@
+
+# In order for this to work, you must add `gem 'parser'` to your Gemfile.
+require 'parser/current'


Thinking we'll be more defensive here and use conditionals around our definitions and code in order to prevent things blowing up if someone doesn't include parser or we're running in an older ruby version, non MRI, etc.

Okay I wrapped it and rescue LoadError. Let's see how this works on travis.

lib/scout_apm/auto_instrument/rails.rb

dlanderson · 2019-01-29T17:53:36Z

lib/scout_apm/auto_instrument/rails.rb

+          column = node.location.column || 'column?'
+          method_name = node.children[1] || '*unknown*'
+
+          wrap(node.location.expression, "::ScoutApm::Instruments::AutoInstruments.dynamic_layer('#{method_name}:l#{line}:c#{column}'){", "}")


::ScoutApm::Instruments::AutoInstruments.dynamic_layer si so... ugly 😜 Thinking about how we can make that better. We mentioned about the invisible space or hot dog. Need to decide on options here

We could use ::ScoutApm::AutoInstrument{...}.

I implemented this change in recent commit.

dlanderson · 2019-01-29T17:54:09Z

lib/scout_apm/instruments/auto_instruments.rb

+          layer = ScoutApm::Layer.new('AutoInstrument', name)
+          req.start_layer(layer)
+          started_layer = true
+          puts "================ STARTED AUTO INSTRUMENT LAYER #{name} ============="


Reminder to remove this debug code before releasing to customers

dlanderson · 2019-01-29T17:56:26Z

test/unit/auto_instrument_test.rb

+  def test_rails_controller_rewrite
+    assert_equal instrumented_source("controller"), ::ScoutApm::AutoInstrument::Rails.rewrite(source_path("controller"))
+  end
+end if RUBY_VERSION >= "2.3.1"


I think we can test the rewriter on all versions. It's the load_iseq feature that's version dependent

dlanderson

I forgot a crucial bug in super for load_iseq

dlanderson · 2019-01-29T18:00:02Z

lib/scout_apm/auto_instrument/instruction_sequence.rb

+
+          return compile(new_code, path, filepath)
+        else
+          return super


Forgot this crucial one: we must assume super (load_iseq) does not exist (but it might exist).

Yeah, I reworked it to be compile_file. It's simple solution for now.

We could probably write super rescue compile_file(path) but that might be a bad idea, because it could eat up other exceptions.

…ed too.

- There is no `super` implementation, so invoke `compile_file`. - The 2nd argument of `compile` should be a file name.

- Only match user-defined controllers in the Rails app directory. - Revert to original source code if instrumentation fails.

lib/scout_apm/auto_instrument/instruction_sequence.rb

lib/scout_apm/auto_instrument.rb

cschneid · 2019-02-07T21:27:04Z

lib/scout_apm/auto_instrument/rails.rb

+        end
+
+        def instrument(method_name, line, column)
+          ["::ScoutApm::AutoInstrument(\"\#{self.class}\\\##{method_name}:L#{line}:C#{column}\"){", "}"]


The desc field of a layer may make sense to put an exact line & column number in.

So the name can be Foo/length and desc is line 3, column 8 or whatever format you want.

The latest version of this puts the class and controller method with line number into the name field and the first line of code/expression into the description field. How do you feel about that? Can you try it and see if it makes sense?

lib/scout_apm/auto_instrument/layer.rb

When instrumenting specific lines of code in the controller, we aren't failing the entire request if that line fails, because the controller may catch the error and do something with it (e.g. error page).

jsierles · 2019-02-18T00:32:23Z

Thanks for the work on this!

Just one finding. On Heroku, the Rails console is not run using bundler, so requiring in boot.rb would fail. To remedy this, I added the gem to a pre_boot bundler group:

require "bundler"
Bundler.setup(:pre_boot)

require 'scout_apm/auto_instrument'

itsderek23 · 2019-02-20T01:47:05Z

Should we set the version to something like 2.4.21.pre.auto? Without that, I'm unsure how to check which apps are running this branch.

dlanderson · 2019-02-20T20:45:20Z

Replaced by #247

ioquatix force-pushed the auto_instruments branch from ff8917f to b254fdc Compare January 27, 2019 02:03

cschneid reviewed Jan 27, 2019

View reviewed changes

ioquatix force-pushed the auto_instruments branch from 7122fb7 to d834dfb Compare January 27, 2019 20:16

dlanderson suggested changes Jan 29, 2019

View reviewed changes

ioquatix force-pushed the auto_instruments branch from db4b355 to 16d7443 Compare January 29, 2019 23:09

dlanderson and others added 16 commits February 5, 2019 13:51

POC ScoutProf replacement using RubyVM::InstructionSequence#load_iseq

9940620

Remove redundant node checks

4fe9c6f

Restructure code using parser gem and added tests.

3c71179

Update travis config.

9d9b538

Remove usage of require_relative.

89a2707

Skip auto_instrument on older ruby versions.

43b9ce3

Skip tests on older Rubies.

7579fc3

Invoke #rewrite during load to force any lazy dependencies to be load…

003cbba

…ed too.

Add missing rvm: 2.3 to travis matrix.

32c6cb7

Move parser to dependency in gemspec.

15f203f

Fix controller path pattern.

75ab759

Fix extending load_iseq into RubyVM::InstructionSequence.

6891c77

Fix load_iseq implementation.

4b55201

- There is no `super` implementation, so invoke `compile_file`. - The 2nd argument of `compile` should be a file name.

Don't fail if parser gem is not available, print warning instead.

95b06a3

Update tests and improve documentation.

99c8b09

Add instrumentation around blocks.

719ba0d

ioquatix and others added 9 commits February 5, 2019 13:51

Whitespace.

3eed875

Better handling of parser gem dependency.

ec41fbb

Fix RuboCop offence in test fixture.

91b3022

Removes AutoInstruments debugging output

cae368f

Adds ||= case to AutoInstrument parser test controller

6ceb9e8

Fix handling of ||= and &&= with hash receiver.

42dbc9e

Prefer "L"/"C" for line/column prefix.

ef2e414

Improved loading of Rails controllers.

b5ceb62

- Only match user-defined controllers in the Rails app directory. - Revert to original source code if instrumentation fails.

Update test fixtures.

b10d6ec

ioquatix force-pushed the auto_instruments branch from 7adfbb8 to b10d6ec Compare February 5, 2019 00:51

Defend against undefined ::Rails.root in load_iseq

13b41f3

dlanderson reviewed Feb 6, 2019

View reviewed changes

lib/scout_apm/auto_instrument/instruction_sequence.rb Show resolved Hide resolved

cschneid suggested changes Feb 7, 2019

View reviewed changes

ioquatix added 2 commits February 8, 2019 11:25

Don't load ScoutApm::AutoInstrument on older Rubies.

1ca2bae

Include class name in auto-instrumentation.

14d1c5b

ioquatix force-pushed the auto_instruments branch from 4a2bc0a to 14d1c5b Compare February 7, 2019 22:28

ioquatix added 3 commits February 8, 2019 12:10

Remove error handling.

2614940

When instrumenting specific lines of code in the controller, we aren't failing the entire request if that line fails, because the controller may catch the error and do something with it (e.g. error page).

Add support for adding description.

095c49f

Use the description field to log the first line of source code.

19778c4

dlanderson closed this Feb 20, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Experimental - DO NOT MERGE! Auto-instrumentation of Controller Time #198

Experimental - DO NOT MERGE! Auto-instrumentation of Controller Time #198

itsderek23 commented Jun 1, 2018 •

edited

itsderek23 commented Jun 1, 2018

itsderek23 commented Jun 1, 2018

itsderek23 commented Jun 1, 2018

itsderek23 commented Jun 1, 2018

dlanderson commented Jun 7, 2018

ioquatix commented Jan 27, 2019

ioquatix commented Jan 27, 2019

ioquatix commented Jan 27, 2019

cschneid Jan 27, 2019

ioquatix Jan 27, 2019

dlanderson left a comment

dlanderson Jan 29, 2019

ioquatix Jan 29, 2019

dlanderson Jan 29, 2019

ioquatix Jan 29, 2019

dlanderson Jan 29, 2019

ioquatix Jan 29, 2019

dlanderson Jan 29, 2019

ioquatix Jan 29, 2019 •

edited

ioquatix Jan 29, 2019

dlanderson Jan 29, 2019

dlanderson Jan 29, 2019

dlanderson left a comment

dlanderson Jan 29, 2019

ioquatix Jan 29, 2019

ioquatix Jan 29, 2019 •

edited

cschneid Feb 7, 2019

ioquatix Feb 8, 2019

jsierles commented Feb 18, 2019

itsderek23 commented Feb 20, 2019

dlanderson commented Feb 20, 2019

		@@ -0,0 +1,73 @@

		# In order for this to work, you must add `gem 'parser'` to your Gemfile.
		require 'parser/current'

Experimental - DO NOT MERGE! Auto-instrumentation of Controller Time #198

Experimental - DO NOT MERGE! Auto-instrumentation of Controller Time #198

Conversation

itsderek23 commented Jun 1, 2018 • edited

itsderek23 commented Jun 1, 2018

itsderek23 commented Jun 1, 2018

itsderek23 commented Jun 1, 2018

itsderek23 commented Jun 1, 2018

dlanderson commented Jun 7, 2018

ioquatix commented Jan 27, 2019

ioquatix commented Jan 27, 2019

ioquatix commented Jan 27, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dlanderson left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ioquatix Jan 29, 2019 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dlanderson left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ioquatix Jan 29, 2019 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jsierles commented Feb 18, 2019

itsderek23 commented Feb 20, 2019

dlanderson commented Feb 20, 2019

itsderek23 commented Jun 1, 2018 •

edited

ioquatix Jan 29, 2019 •

edited

ioquatix Jan 29, 2019 •

edited