Basic support for profiling

[marcandre]

To have profiling turned on, I was thinking of something like this, but maybe it should be only in bin/something and/or the rake task?

[andrykonchin]

I used just a copy of exe/rubocop file - exe/rubocop-profile with set up stackprof.

https://gist.github.com/andrykonchin/6c1e7699e16ed1b1ea89cda265c50fe9

Not sure whether any profiling stuff should leak to the core source code.

[marcandre]

This should be a good start:

1. bin/rubocop-profile is like exe/rubocop but with profiling on.

2. rake prof:run[path] executes bin/rubocop-profile path

3. rake prof:slow_cops prints the slowest cops' entrypoints

4. rake prof:walk[Class#method] investigates the given method and walks through the call stack.

Example output

[14:58][~/rubocop(perf)]$ rake prof:slow_cops
stackprof tmp/stackprof.dump --text --method 'RuboCop::Cop::Commissioner#trigger_responding_cops'
     363  (   19.4%)  RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#on_send
      44  (    2.4%)  RuboCop::Cop::Style::NumericPredicate#on_send
      39  (    2.1%)  RuboCop::Cop::Style::TrailingMethodEndStatement#on_def
      32  (    1.7%)  RuboCop::Cop::Metrics::ModuleLength#on_module
      31  (    1.7%)  RuboCop::Cop::Layout::DefEndAlignment#on_send
      28  (    1.5%)  RuboCop::Cop::Lint::MixedRegexpCaptureTypes#on_regexp
      26  (    1.4%)  RuboCop::Cop::Layout::IndentationConsistency#on_begin
      25  (    1.3%)  RuboCop::Cop::Layout::DotPosition#on_send
      25  (    1.3%)  RuboCop::Cop::Lint::NestedMethodDefinition#on_def
      25  (    1.3%)  RuboCop::Cop::MultilineExpressionIndentation#on_send
      25  (    1.3%)  RuboCop::Cop::Layout::FirstArgumentIndentation#on_send
      23  (    1.2%)  RuboCop::Cop::Layout::ArgumentAlignment#on_send
      21  (    1.1%)  RuboCop::Cop::Lint::DuplicateMethods#on_def
      21  (    1.1%)  RuboCop::Cop::Performance::FixedSize#on_send
      20  (    1.1%)  RuboCop::Cop::Naming::VariableName#on_lvasgn
      20  (    1.1%)  RuboCop::Cop::Style::RedundantSelf#on_def
      19  (    1.0%)  RuboCop::Cop::Lint::DeprecatedClassMethods#on_send
      18  (    1.0%)  RuboCop::Cop::Lint::RaiseException#on_send
      17  (    0.9%)  RuboCop::Cop::Layout::ClosingParenthesisIndentation#on_send
      17  (    0.9%)  RuboCop::Cop::MethodComplexity#on_def
      15  (    0.8%)  RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#on_const
      15  (    0.8%)  RuboCop::Cop::Layout::DefEndAlignment#on_def
      14  (    0.7%)  RuboCop::Cop::MethodComplexity#on_def
      14  (    0.7%)  RuboCop::Cop::Layout::SpaceAroundOperators#on_send
      13  (    0.7%)  RuboCop::Cop::Style::ConditionalAssignment#on_send
      13  (    0.7%)  RuboCop::Cop::Lint::Debugger#on_send
      13  (    0.7%)  RuboCop::Cop::Layout::SpaceInsideHashLiteralBraces#on_hash
      12  (    0.6%)  RuboCop::Cop::MethodComplexity#on_def
      12  (    0.6%)  RuboCop::Cop::Layout::SpaceBeforeFirstArg#on_send
      11  (    0.6%)  RuboCop::Cop::Layout::SpaceInsideReferenceBrackets#on_send
      11  (    0.6%)  RuboCop::Cop::Naming::MethodName#on_def
      11  (    0.6%)  RuboCop::Cop::Layout::EmptyLinesAroundAccessModifier#on_send
      11  (    0.6%)  RuboCop::Cop::Layout::IndentationWidth#on_class
      11  (    0.6%)  RuboCop::Cop::Style::MethodCallWithoutArgsParentheses#on_send
      11  (    0.6%)  RuboCop::Cop::Lint::IneffectiveAccessModifier#on_module
      10  (    0.5%)  RuboCop::Cop::Performance::Detect#on_send
      10  (    0.5%)  RuboCop::Cop::Naming::VariableName#on_lvasgn
      10  (    0.5%)  RuboCop::Cop::Style::UnpackFirst#on_send
      10  (    0.5%)  RuboCop::Cop::Performance::Size#on_send
      10  (    0.5%)  RuboCop::Cop::Metrics::MethodLength#on_def


$ rake prof:walk[RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#on_send]
stackprof tmp/stackprof.dump --walk --method 'RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#on_send'
RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#on_send (/Users/work/rubocop/lib/rubocop/cop/layout/space_around_method_call_operator.rb:42)
  samples:     1 self (0.0%)  /    363 total (5.3%)
  callers:
     363  (  100.0%)  RuboCop::Cop::Commissioner#trigger_responding_cops
  callees (362 total):
     358  (   98.9%)  RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#check_and_add_offense
       4  (    1.1%)  RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#dot_or_safe_navigation_operator?
  code:
                                  |    42  |         def on_send(node)
    4    (0.1%)                   |    43  |           return unless dot_or_safe_navigation_operator?(node)
                                  |    44  | 
  358    (5.2%)                   |    45  |           check_and_add_offense(node)
    1    (0.0%) /     1   (0.0%)  |    46  |         end
                                  |    47  | 


Select next method:
 1)  RuboCop::Cop::Commissioner#trigger_responding_cops
 2)  RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#check_and_add_offense
 3)  RuboCop::Cop::Layout::SpaceAroundMethodCallOperator#dot_or_safe_navigation_operator?
 4)  exit

[andrykonchin]

Looks good 👍 .

The only additional thing that could be helpful is to be able to work with different dump files at the same time to compare the picture before and after optimization.

Also I find useful to measure execution time of every profiling with time shell command. It may be useful to do this as well in the prof:run[path] rake task.

[marcandre]

Thanks for the review. I've added execution time for rubocop-profile.

For multiple dump files, I'm not sure about the best way to proceed (ENV? param?), so I think I'll commit this and anyone can propose an enhancement with that later.