Profiling with Spyder

Anonymous

Profiling with Spyder

Anonymous
Not applicable

Hi,

    Has anyone had any luck profiling with Spyder? I have a script that is running slower than I'd like so I'd like to see where the bottle necks are. I saw that there is a spyder-line-profiler available. I ran a Administrator command prompt and wandered into the Python install directory and typed;

 

 

python.exe -m pip install spyder-line-profiler

 

It spat out an error about the python.h file. I'd already installed the exact same Python install (v3.5.3:1880cb95a742) so I copied the 'include' and 'libs' directories into Fusion's python install directory. Reran the above command and it installed without any errors (nice!).

 

Ran Fusion 360, tried to start Spyder and it crashes....everytime... So 2 questions;

 

-Anyone had any luck getting the spyder-line-profiler to work (I assume I'm going to have to reinstall Fusion to fix this)

-Any other profiler options that others have got to work?

 

Sincerely, Paul.

 

0 Likes
Reply
1,547 Views
6 Replies
Replies (6)

Anonymous
Not applicable

...reinstalled Fusion so I could use Spyder again...

 

I think the saying, can't "see the woods for the trees" applies here... The default Spyder install has a profiler installed *facepalm*. Too busy playing with the debug options to see it in the "Run" menu....

 

That being said.... it isn't showing any of my function calls when I 'Run Profiler' it. It only has two line items for my program "_find_and_load" and "create" and a bunch of references to other files, I assume from the importing. Running the profile seems to happen immediately, but shouldn't it take the same time as executing my program so that it can time going into each function?

 

Paul.

 

0 Likes

Anonymous
Not applicable

I wrote my own tools for this.

 

Use the Stopwatch for basic timing of "one big thing"

Use the SegmentedStopwatch for tracking the total time spent doing something - or many somethings - (that something may be split over multiple slices - like what was the total time used by this function i called 100 times)

Use RelayStopwatch to get very granular timings - e.g. i want to see how long each and every of those 100 calls to that function took.

 

Obviously you need to "instrument" your own code to profile it with these timers but it does the job for me 😉

 

timers.py

 

# -*- coding: utf-8 -*-
# Author-Ross Korsky
# Timers for profiling performance, etc.
#
import time
from collections import OrderedDict

__all__ = ['Stopwatch', 'RelayStopwatch', 'SegmentedStopwatch']

class Stopwatch(object):
  """Provides basic stopwatch functionality to time the duration between events.
  May be paused and resumed (with another call to run).
  """
  def __init__(self, time_fn=time.process_time):
    """
    time.process_time - The sum of the system and user CPU time of the current process.
    time.perf_counter - A clock with the highest available resolution to measure a short duration.
                        It does include time elapsed during thread sleep and is system-wide.
    """
    self._elapsed = 0
    self._started = -1
    self._time_fn = time_fn

  @property
  def elapsed(self):
    return self._elapsed

  def reset(self):
    self.elapsed = 0
    self._started = -1

  def run(self):
    self._started = self._time_fn()

  def pause(self):
    now = self._time_fn()
    if self._started > 0:
      self._elapsed += now - self._started
      self._started = -1


class RelayStopwatch(object):
  """Allows the timing of each part of a chain of events.
  Each section is unique even if the same section name is used multiple times.
  """
  def __init__(self, time_fn=time.perf_counter):
    """
    time.process_time - The sum of the system and user CPU time of the current process
    time.perf_counter - A clock with the highest available resolution to measure a short duration.
                        It does include time elapsed during sleep and is system-wide.
    """
    self.sections = []
    self.__active_section_start = -1
    self._time_fn = time_fn

  def start_section(self, section_name):
    now = self._time_fn()
    if self.__active_section_start > 0:
      self.sections.append((self.__active_section_name, now - self.__active_section_start))
    self.__active_section_name = section_name
    self.__active_section_start = self._time_fn()

  def stop(self):
    now = self._time_fn()
    if self.__active_section_start > 0:
      self.sections.append((self.__active_section_name, now - self.__active_section_start))
      self.__active_section_start = -1

  def __str__(self):
    s = ''
    for name, elapsed in self.sections:
      s += '{}: {}\n'.format(name, elapsed)
    return s


class SegmentedStopwatch(object):
  """Provides a simple container to maintin several named Stopwatch object."""
  def __init__(self, time_fn=time.process_time):
    """
    time.process_time - The sum of the system and user CPU time of the current process
    time.perf_counter - A clock with the highest available resolution to measure a short duration.
                        It does include time elapsed during sleep and is system-wide.
    """
    self._segments = OrderedDict()
    self._active_counts = dict()
    self._active_stopwatch = None
    self._time_fn = time_fn

  def switch_segment(self, segment_name):
    if self._active_stopwatch:
      self._active_stopwatch.pause()
    if segment_name not in self._segments:
      self._segments[segment_name] = Stopwatch(self._time_fn)
      self._active_counts[segment_name] = 0
    self._active_stopwatch = self._segments[segment_name]
    self._active_counts[segment_name] += 1
    self._active_stopwatch.run()

  def pause(self):
    """Pauses the current segment stopwatch."""
    if self._active_stopwatch:
      self._active_stopwatch.pause()

  def resume(self):
    """Resumes the current segment stopwatch."""
    if self._active_stopwatch:
      self._active_stopwatch.run()

  def stop(self):
    """Stops the current segment stopwatch, switch_segment must be called to resume."""
    if self._active_stopwatch:
      self._active_stopwatch.pause()
      self._active_stopwatch = None

  def __str__(self):
    s = ''
    total = 0
    for name, stopwatch in self._segments.items():
      s += '{}: {} // {}\n'.format(name, stopwatch.elapsed, self._active_counts[name])
      total += stopwatch.elapsed
    s += 'TOTAL ELAPSED: {}\n'.format(total)
    return s

 

1 Like

Anonymous
Not applicable

Oh and the overhead of using these timers is negligible - i just leave it in my add-ins but be responsible, especially with RelayStopwatch... it can grow rather fast if you are timing something in a loop 😉

1 Like

Anonymous
Not applicable

Ross,

    Thanks for the reply and the code snippet =). Did you do it this way because you also couldn't get the profiling to work or was it just the easiest thing to do for your project? I've created my own timers before (in other languages), but I was hoping that I could take advantage of the profiler to save inserting timers all over the place. I do like the named stop watches that you can pause so I can just have one per function call and easily do cumulative time in a function.

    

    My code uses a lot of point / vector math which I ported to use the Fusion 360 API primitives and I suspect that this is the slow point. I'm only creating a 'few hundred' objects and this was taking ~8 minutes to process. I wrote a similar script in Ruby for SketchUp years ago and at those settings it ran like a scared cat. My guess is I'll just have to pull out all the API native types (which will make the code more ugly to read) and just instantiate the objects at the end before display.

 

Paul.

0 Likes

Anonymous
Not applicable
Honestly, I didn't even try a true profiler. I like the freedom to instrument at the sub-function level (e.g. loops, parts of functions, etc) and generally it's faster to build something lightweight than to learn a new profiling tool - in the short term at least 😉 I've found that the python side of things is not likely to be the slow part - calls to any sketch draw function is - and it gets worse as you add more lines. See the thread called "Strange Sketch Copy / Move Behaviour" - I'd link to it but the forums are messed up right now - with an empty sketch i can draw 400-500 lines per second, but once i get 400 lines in there i'm down to 4-5 lines persecond. Also I dont think you need to use your own point/vector classes. The built in ones are fine (and well performing) - but putting a wrapper around them has helped me a lot. Especially wrapping the Matrix3D class so that it actually provides the operations a drawing program needs - you know things like rotate and translate that doesn't require a point and a vector to perform what i always want to do when sketching - rotate about the z axis.. and other "silly" things like the ability to scale and reflect and to accumulate transforms. I'll share my helper files when the forum is working well enough for me to include code again.
1 Like

Anonymous
Not applicable
I've found a workaround for a large portion of the poor performance - when setting sketch.isComputeDeferred = True also set sketch.areProfilesShown = False. Then when setting sketch.isComputeDeferred = False also set sketch.areProfilesShown = True.
0 Likes