Optimizing Matrix Operations

Last time, we reviewed some major frame rate issues I found in ng and established a process to measure and improve on the problem. We reviewed performance of a long-running test and identified the 4x4 matrix and vector modules as major culprits. Today, we’ll do line-by-line analysis of the slow parts and review my progress optimizing them.

Performance Analysis

Recapping the last measurements, here are the most expensive functions for the 5 worst exceptional frames, according to callgrind. This list was generated by the performance tool I wrote to do this exceptional frame analysis.

Frame  # ms/frame  call site

25798  4167.96     /usr/lib/python3.6/site-packages/ng/math/vector.py:__init__
27314  4120.22     /usr/lib/python3.6/site-packages/ng/ng.py:_entities_velocity
24394  3972.68     /usr/lib/python3.6/site-packages/ng/math/matrix.py:__matmul_
21420  3672.30     /usr/lib/python3.6/site-packages/ng/ng.py:_entities_velocity
20191  3374.32     /usr/lib/python3.6/site-packages/ng/math/matrix.py:__init__

The most expensive operations are initializing new matrix and vector class instances and multiplying matrices. These math operations are used per frame, per entity to update entity positions and to prepare MVP matrices for display output.

_entities_velocity indirectly uses vector operations through its own function calls, so it may drop off the list when vector is optimized. We’ll focus on vector and matrix right now.

The goal of this session is to reduce the number of usages of the vector and matrix modules, as well as to improve the performance of each usage.

Let’s use callgrind_annotate to get more information about the call patterns. To reduce the number of calls to a function, we need to know who is calling. We add the --tree=caller option to get this info. To improve the performance of the function, we need to know which lines perform worst. We add the --auto=yes option so callgrind will annotate the source lines of each module with the amount of time spent in each line.

Here are the header and the call tree for frame 25798, which give us more details on calls to vector.py:__init__.

$ callgrind_annotate --auto=yes --tree=caller  emitter-25798.pstats.cg
--------------------------------------------------------------------------------
Profile data file 'emitter-25798.pstats.cg'
--------------------------------------------------------------------------------
Profiled target:  (unknown)
Events recorded:  ns
Events shown:     ns
Event sort order: ns
Thresholds:       99
Include dirs:
User annotated:
Auto-annotation:  on

--------------------------------------------------------------------------------
           ns
--------------------------------------------------------------------------------
4,167,334,999  PROGRAM TOTALS

--------------------------------------------------------------------------------
           ns  file:function
--------------------------------------------------------------------------------

      415,000  < /usr/lib/python3.6/site-packages/ng/ng.py:_entities_velocity (255x) []
       34,000  < /usr/lib/python3.6/site-packages/ng/render/__init__.py:normalized_vertices (32
x) []
       20,000  < /usr/lib/python3.6/site-packages/ng/entity.py:size:128 (8x) []
      521,000  < /usr/lib/python3.6/site-packages/ng/math/bounding_box.py:aa_box (492x) []
       14,000  < /usr/lib/python3.6/site-packages/ng/entity.py:origin:118 (8x) []
4,040,391,999  < /usr/lib/python3.6/site-packages/ng/math/vector.py:__iadd__ (242x) []
       26,000  < /usr/lib/python3.6/site-packages/ng/ng.py:entity_create (8x) []
       34,000  < /usr/lib/python3.6/site-packages/ng/entity.py:velocity:170 (8x) []
       87,000  < /usr/lib/python3.6/site-packages/ng/entity.py:__init__ (40x) []
    1,238,000  < /usr/lib/python3.6/site-packages/ng/render/opengl.py:_draw_entity (984x) []
      278,000  < /usr/lib/python3.6/site-packages/ng/math/vector.py:__mul__ (242x) []
      235,000  < /usr/lib/python3.6/site-packages/ng/entity.py:position:137 (250x) []
       11,000  < /usr/lib/python3.6/site-packages/ng/entity.py:scale:159 (8x) []
4,042,445,000  *  /usr/lib/python3.6/site-packages/ng/math/vector.py:__init__

Most of the calls in the graph look innocuous at a glance. There may be opportunity to optimize some of those call patterns later, but nothing stands out since they are all necessary for the update routine. The calls to vector.py:__init__ from vector.py:__iadd__ and vector.py:__mul__ look suspicious, though. These are bound methods used for class instantiation and operator overloading. The callgrind analysis shows us the lines for __iadd__.

      .      def __iadd__(self, other: Any) -> 'Vector':
147,000          other = Vector(other)
      .
      .          self.x += other.x
180,999          self.y += other.y
278,000  => /usr/lib/python3.6/site-packages/ng/math/vector.py:__init__ (242x)
      .          self.z += other.z
      .
      .          return self

This method overloads the += operator, performing vector addition with a scalar value and mutating the original vector instance. This operation doesn’t need to allocate a new vector, but the first line creates a new vector instance from the user’s input. I intended this as a convenience, allowing the user to call the method with another type such as a tuple. Removing this convenience will significantly reduce the number of Vector allocations. Here’s the change:

def __iadd__(self, other: Vector) -> 'Vector':
    self.x += other.x
    self.y += other.y
    self.z += other.z

    return self

The __sub__ and __add__ methods had a similar pattern, so I also changed those. With these changes, we can expect frame 25798 to be improved and can move to frames 24394 and 20191. These both spend a lot of time in the matrix module. I did a quick comparison of 20191 and 24394 and saw that they are similar, so we can review only 24394.

Here are the callgrind header and tree for frame 24394.

$ callgrind_annotate --auto=yes --tree=caller  emitter-24394.pstats.cg
--------------------------------------------------------------------------------
Profile data file 'emitter-24394.pstats.cg'
--------------------------------------------------------------------------------
Profiled target:  (unknown)
Events recorded:  ns
Events shown:     ns
Event sort order: ns
Thresholds:       99
Include dirs:
User annotated:
Auto-annotation:  on

--------------------------------------------------------------------------------
           ns
--------------------------------------------------------------------------------
3,972,006,999  PROGRAM TOTALS

--------------------------------------------------------------------------------
           ns  file:function
--------------------------------------------------------------------------------

3,889,429,000  < /usr/lib/python3.6/site-packages/ng/entity.py:matrix_init (4074x) []
    2,352,000  < /usr/lib/python3.6/site-packages/ng/render/opengl.py:_render_entity (410x) []
    2,343,000  < /usr/lib/python3.6/site-packages/ng/render/opengl.py:_draw_entity (784x) []
3,881,484,999  *  /usr/lib/python3.6/site-packages/ng/math/matrix.py:__matmul__

   57,394,000  < /usr/lib/python3.6/site-packages/ng/render/opengl.py:_render_entity (198x) []
   59,996,999  < /usr/lib/python3.6/site-packages/ng/render/opengl.py:update (7x) []
   21,398,999  *  /usr/lib/python3.6/site-packages/ng/render/opengl.py:_render_entity

   30,022,000  < /usr/lib/python3.6/site-packages/ng/render/opengl.py:_render_entity (205x) []
   10,284,999  *  /usr/lib/python3.6/site-packages/ng/render/opengl.py:_draw_entity

    5,807,000  < /usr/lib/python3.6/site-packages/ng/math/matrix.py:__matmul__ (5268x) []
    5,807,000  *  ~:<built-in method numpy.core.multiarray.matmul>

    5,312,000  < /usr/lib/python3.6/site-packages/ng/math/matrix.py:__init__ (6767x) []
    5,312,000  *  ~:<built-in method numpy.core.multiarray.array>

    7,177,999  < /usr/lib/python3.6/site-packages/ng/entity.py:matrix_init (252x) []
3,882,551,000  < /usr/lib/python3.6/site-packages/ng/entity.py:position:137 (198x) []
   11,371,000  < /usr/lib/python3.6/site-packages/ng/entity.py:rotation:148 (211x) []
      819,000  < /usr/lib/python3.6/site-packages/ng/entity.py:children_add (6x) []
      135,000  < /usr/lib/python3.6/site-packages/ng/entity.py:scale:159 (6x) []
      151,999  < /usr/lib/python3.6/site-packages/ng/entity.py:origin:118 (6x) []
    4,083,000  *  /usr/lib/python3.6/site-packages/ng/entity.py:matrix_init

The worst performer, matrix.py:__matmul__, is the matrix multiplication operator on the Matrix class. The engine makes heavy use of this operation while calculating entity model matrices and while preparing MVP matrices for display rendering.

Again, there might be opportunity to improve caller efficiency, but let’s see how we can optimize this method in the matrix module.

Here are the line-by-line costs of the methods.

            .  class Matrix():
    3,702,999      def __init__(self, values):
    5,312,000  => ~:<built-in method numpy.core.multiarray.array> (6767x)
    2,327,000  => ~:<method 'tolist' of 'numpy.ndarray' objects> (6767x)
            .          self._np_array = np.array(values)
            .
            .          self.values = self._np_array.tolist()
            .
            .      def _columns(self):
            .          return len(self.values[0])
            .
3,881,484,999      def __matmul__(self, other):
    5,807,000  => ~:<built-in method numpy.core.multiarray.matmul> (5268x)
    6,831,999  => /usr/lib/python3.6/site-packages/ng/math/matrix.py:__init__ (5268x)
            .          return Matrix(np.matmul(self._np_array, other._np_array))

The only purpose of the Matrix class is to be a wrapper around the numpy array. The original ng Matrix class implemented matrix operations in Python. That was slow, so I previously changed it to use a numpy array for its underlying operations, leaving Matrix as a wrapper class.

The price of the wrapper class is apparent; every time we create a new matrix or multiply two matrices, we incur the cost of a new Python class instance that serves only to create a new numpy array instance underneath it.

Wrapping third party APIs is a good practice in certain languages and situations, allowing one to protect one’s own APIs from changes to third party APIs. In this case, though, performance is the larger consideration.

If the wrapper class were very important to the design, one potential optimization would be to rewrite the matrix class as a C library. In this case, numpy is ubiquitous in the Python computation space and carries a stable API, so I’m comfortable using it directly instead of wrapping it. I ditched the Matrix class entirely and ng now directly uses numpy arrays for all matrix operations.

The Data

Here’s the data from a new run measured after the changes. I reformatted it a bit to compare it more easily with the data from the last run.

Metric

Run 0

Run 1

Session length (s)

2467.48

628.72

ms/frame (mean)

87.80

64.17

ms/frame (median)

79.32

63.10

ms/frame (std dev)

75.96

15.68

Exceptional frames (variation multiple > 0.5

96

46

  • sec/exceptional frame

25.70

13.67

  • ms/frame (mean)

798.30

208.43

  • ms/frame (median)

278.32

149.94

  • ms/frame (std dev)

1029.25

144.21

Active entities (mean)

206.07

243.30

Active entities (median)

205.00

247.00

Active entities (std dev)

17.90

21.54

The first thing to highlight is this run length is much shorter than the last. Because there will be several iterations of optimization, I decided to do shorter 10 minute runs for the intermediate iterations. The caveat is we can’t directly compare the summary data from this run to the last; the decreased session length affects the averaged data.

That’s okay. Again, this will be a series of improvements. We don’t need to do a direct session-to-session comparison to answer the questions I want to answer right now.

  • Are there still exceptional frames?

  • If so, how often?

  • If so, are the exceptions getting worse over time?

The first two questions are answered by the summary data. Yes, there are still exceptional frames. They happen several times per minute on average.

Metric

Last Run

This Run

Exceptional frames (variation multiple > 0.5

96

46

  • sec/exceptional frame

25.70

13.67

Let’s look at the graphs.

../_images/2018-06-03_frame_rate_runtime_f74cde-nparray-opt.png
../_images/2018-06-03_frame_rate_variation_exc_f74cde-nparray-opt.png
../_images/2018-06-03_frame_rate_variation_f74cde-nparray-opt.png

The spikes in the graph indicate the same pattern as before. The frame-to-frame variation worsens over the length of the session.

Here’s the new short list of expensive calls.

Frame # ms/frame  call site
8980  581.74      /usr/lib/python3.6/site-packages/ng/math/bounding_box.py:aa_box
8232  526.43      /usr/lib/python3.6/site-packages/ng/math/vector.py:__init__
7645  494.95      /usr/lib/python3.6/site-packages/ng/math/bounding_box.py:aa_box
6999  478.29      /usr/lib/python3.6/site-packages/ng/math/vector.py:__init__
6484  465.14      /usr/lib/python3.6/site-packages/OpenGL/wrapper.py:calculate_cArgs

Finally, some good news. The matrix module has dropped off the list of worst offenders and numpy’s array multiplication routines are not on the list. This suggests replacing the matrix class with numpy arrays improved things. The vector module is still there, indicating we might be able to improve it further. boundingbox_py.aa_box is new to the list. That function uses the vector module, so it’s reasonable to expect that vector is the bottleneck for aabox. An internal call in the PyOpenGL library is also new to the list this time.