Monitoring Performance

[thomthom]

I've written a small utility to keep track of the performance of given methods without having to modify the source code or suffer from big performance penalties.

It's part of my next version of TT_Lib² (2.7) https://bitbucket.org/thomthom/tt-library-2

Note: This does not replace utilities such as Profiler__, which is used to find out where the bottlenecks are. This is when you know exactly what methods you are interested in and want to try out different solutions and keep an eye on the performance.

As an example of usage, I wanted to monitor the performance of some select methods used when Vertex Tools activates as I knew there was some bottlenecks there. I created a Profiler config file like this (which I can then load whenever I want)

require 'TT_Lib2/core.rb'
require 'TT_Lib2/profiler.rb'

profiler = TT::Profiler.new( 'Editor Activation' ) {

  self.report_each_event = true
  self.report_event_start = false

  track( TT_Vertex, :edit_vertex )
  track( TT_Vertex, :array_to_lookup_hash )

  track( TT_Vertex::Editor, :activate )
  track( TT_Vertex::Editor, :build_ui )
  track( TT_Vertex::Editor, :rebuild_cache )
  track( TT_Vertex::Editor, :update_scope )

  #track( TT_Vertex::Selection )
  track( TT_Vertex::Selection, :initialize )
  track( TT_Vertex::Selection, :activate )
  track( TT_Vertex::Selection, :refresh )
  track( TT_Vertex::Selection, :get_model_selection )
  track( TT_Vertex::Selection, :update_soft )

  # This trigger will print a report each time Vertex Tools' Editor activates
  # and ensures that the data is reset.
  attach_trigger( TT_Vertex, :edit_vertex ) { |prof|
    prof.print_report
    prof.reset
  }

  start()
}

This config will output live the time to took for each method as well as outputting an report in the end. (Strictly speaking, since I set up a trigger to output a report and reset data for each run I don't need the live method output.)

The results I get is something like this:

> #904840351 TT_Vertex::Selection.get_model_selection : 0.000000s
> #1206940865 TT_Vertex::Selection.refresh : 0.000000s
> #1764322652 TT_Vertex::Editor.update_scope : 0.000000s
> #839121163 TT_Vertex::Editor.rebuild_cache : 0.010000s
> #1793773315 TT_Vertex::Editor.activate : 0.030000s
> #970921526 TT_Vertex.edit_vertex : 0.110000s

==============================================================
 Profile: Editor Activation (22 November 2012 - 13:28)
--------+----------+------------+----------+------------------
   %%   |          | cumulative | average  | Method
  time  |  calls   |  seconds   | seconds  | Name
--------+----------+------------+----------+------------------
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex::Selection.update_soft
   0.00 |        1 |      0.00  |     0.00 | TT_Vertex::Selection.get_model_selection
   0.00 |        1 |      0.00  |     0.00 | TT_Vertex::Selection.refresh
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex::Selection.initialize
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex::Selection.activate
   0.00 |        1 |      0.00  |     0.00 | TT_Vertex::Editor.update_scope
   6.67 |        1 |      0.01  |     0.01 | TT_Vertex::Editor.rebuild_cache
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex::Editor.build_ui
  20.00 |        1 |      0.03  |     0.03 | TT_Vertex::Editor.activate
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex.array_to_lookup_hash
  73.33 |        1 |      0.11  |     0.11 | TT_Vertex.edit_vertex
--------+----------+------------+----------+------------------
 100.00 |        6 |      0.15  |     0.02 | Total
========+==========+============+==========+==================

> #1188782231 TT_Vertex::Selection.get_model_selection : 0.000000s
> #971581720 TT_Vertex::Selection.refresh : 0.000000s
> #932029851 TT_Vertex::Editor.update_scope : 0.000000s
> #1498329497 TT_Vertex::Editor.rebuild_cache : 0.020000s
> #1313627741 TT_Vertex::Editor.activate : 0.040000s
> #894215532 TT_Vertex.edit_vertex : 0.060000s

==============================================================
 Profile: Editor Activation (22 November 2012 - 13:28)
--------+----------+------------+----------+------------------
   %%   |          | cumulative | average  | Method
  time  |  calls   |  seconds   | seconds  | Name
--------+----------+------------+----------+------------------
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex::Selection.update_soft
   0.00 |        1 |      0.00  |     0.00 | TT_Vertex::Selection.get_model_selection
   0.00 |        1 |      0.00  |     0.00 | TT_Vertex::Selection.refresh
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex::Selection.initialize
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex::Selection.activate
   0.00 |        1 |      0.00  |     0.00 | TT_Vertex::Editor.update_scope
  16.67 |        1 |      0.02  |     0.02 | TT_Vertex::Editor.rebuild_cache
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex::Editor.build_ui
  33.33 |        1 |      0.04  |     0.04 | TT_Vertex::Editor.activate
   0.00 |        0 |      0.00  |     0.00 | TT_Vertex.array_to_lookup_hash
  50.00 |        1 |      0.06  |     0.06 | TT_Vertex.edit_vertex
--------+----------+------------+----------+------------------
 100.00 |        6 |      0.12  |     0.02 | Total
========+==========+============+==========+==================

I'll be setting up some profiler configs that can be used to test the Importer and Exporter. I'm thinking of making an issue for each profile where reports are posted as code is modified so we can track the performance of the plugin.

[thomthom]

Here's configs for generic monitoring of the ´Importer´ and ´Exporter´:

require 'TT_Lib2/core.rb'
require 'TT_Lib2/profiler.rb'

STL_Importer = CommunityExtensions::STL::Importer

profiler = TT::Profiler.new( 'STL Importer' ) {

  self.report_each_event = false
  self.report_event_start = false

  track( STL_Importer )

  attach_trigger( STL_Importer, :load_file ) { |prof|
    prof.print_report
    prof.reset
  }

  start()
}

require 'TT_Lib2/core.rb'
require 'TT_Lib2/profiler.rb'

STL_Exporter = CommunityExtensions::STL::Exporter

profiler = TT::Profiler.new( 'STL Exporter' ) {

  self.report_each_event = false
  self.report_event_start = false

  track( STL_Exporter )

  attach_trigger( STL_Exporter, :export_mesh_file ) { |prof|
    prof.print_report
    prof.reset
  }

  start()
}

If you paste these snippets in the Developer Console you get access to the profiler instance.

I have however noticed that the Profiler doesn't hook into private methods. Need to correct that.

[thomthom]

I have however noticed that the Profiler doesn't hook into private methods. Need to correct that.

Fixed! ;)

[jimfoltz]

Does it make sense to add these tests to the repo? What about just adding the tests directly to the importer/exporter API? For example: CommunityExtensions::STL::Exporter.start_profiler

[thomthom]

I was just about to ask about this.

Not sure if the profiler configs needs to be part of the actual code. (Remember it currently relies on TT::Profiler from TT_Lib².

What I've done at the moment is add a profiler folder in the project root - making it sibling to src. I was thinking profile configs and other profiler data can be kept there - outside the main source.

I think it's similar to how unit tests are organized ... ?

[jimfoltz]

Remember it currently relies on TT::Profiler from TT_Lib².

True, but profiler could be required only in the method that needs it. So any theoretical start_profiler method would require 'TT_Lib2/profiler, and is meant to be used via the command-line or external script.

[briangbrown]

I would suggest keeping profiling and test code separate from the main source. On Nov 22, 2012 8:13 AM, "Jim Foltz" notifications@github.com wrote:

Remember it currently relies on TT::Profiler from TT_Lib².

True, but profiler could be required only in the method that needs it. So any theoretical start_profiler method would require 'TT_Lib2/profiler, and is meant to be used via the command-line or external script.

— Reply to this email directly or view it on GitHubhttps://github.com/SketchUp/sketchup-stl/issues/48#issuecomment-10637281.

[jimfoltz]

@briangbrown Does that mean kept out of the repo, or just out of the src folder?

[briangbrown]

I think in the repo. Basically just needs to be in a place where it doesn't get included in the rbz when that is created. So it would be easier to isolate test and profiling files. Not sure on the best structure, but I would think maybe a test and profile folder parallel to src. (Sending from my phone so not looking at the exact structure right now).

Brian On Nov 23, 2012 2:40 PM, "Jim Foltz" notifications@github.com wrote:

@briangbrown https://github.com/briangbrown Does that mean kept out of the repo, or just out of the src folder?

— Reply to this email directly or view it on GitHubhttps://github.com/SketchUp/sketchup-stl/issues/48#issuecomment-10670280.

[thomthom]

That's what I was thinking as well.

[thomthom]

@jimfoltz I found a bug where private methods where not profiled. Fixed it and added a debug flag that will output more info when it tries to hook into the methods.

profiler = TT::Profiler.new( 'Editor Activation' ) {

  self.debug = true

  self.report_each_event = true
  self.report_event_start = false

  track( TT_Vertex, :edit_vertex )
  track( TT_Vertex, :array_to_lookup_hash )

  track( TT_Vertex::Editor, :activate )

  start()
}